deploy: Add timing information to journal

Followup to previous performance disaster with !fsverity and composefs.
Let's add a bit of timing information for the nontrivial subtasks
that gets logged to the journal.

Because we're not Rust we need to add our own little helper
to format "human durations" with extra string allocations.

Signed-off-by: Colin Walters <[email protected]>

src/libostree/ostree-sysroot-deploy.c

@@ -606,8 +606,8 @@ merge_configuration_from (OstreeSysroot *sysroot, OstreeDeployment *merge_deploy
  */
 static gboolean
 checkout_deployment_tree (OstreeSysroot *sysroot, OstreeRepo *repo, OstreeDeployment *deployment,
-                          const char *revision, int *out_deployment_dfd, GCancellable *cancellable,
-                          GError **error)
+                          const char *revision, int *out_deployment_dfd, guint64 *checkout_elapsed,
+                          guint64 *composefs_elapsed, GCancellable *cancellable, GError **error)
 {
   GLNX_AUTO_PREFIX_ERROR ("Checking out deployment tree", error);
   /* Find the directory with deployments for this stateroot */
@@ -630,14 +630,18 @@ checkout_deployment_tree (OstreeSysroot *sysroot, OstreeRepo *repo, OstreeDeploy
   /* Generate hardlink farm, then opendir it */
   OstreeRepoCheckoutAtOptions checkout_opts = { .process_passthrough_whiteouts = TRUE };
 
+  guint64 checkout_start_time = g_get_monotonic_time ();
   if (!ostree_repo_checkout_at (repo, &checkout_opts, osdeploy_dfd, checkout_target_name, csum,
                                 cancellable, error))
     return FALSE;
+  guint64 checkout_end_time = g_get_monotonic_time ();
 
   glnx_autofd int ret_deployment_dfd = -1;
   if (!glnx_opendirat (osdeploy_dfd, checkout_target_name, TRUE, &ret_deployment_dfd, error))
     return FALSE;
 
+  guint64 composefs_start_time = 0;
+  guint64 composefs_end_time = 0;
 #ifdef HAVE_COMPOSEFS
   /* TODO: Consider changing things in the future to parse the deployment config from memory, and
    * if composefs is enabled, then we can check out in "user mode" (i.e. only have suid binaries
@@ -665,29 +669,34 @@ checkout_deployment_tree (OstreeSysroot *sysroot, OstreeRepo *repo, OstreeDeploy
     composefs_enabled = repo->composefs_wanted;
   if (composefs_enabled == OT_TRISTATE_YES)
     {
+      composefs_start_time = g_get_monotonic_time ();
       // TODO: Clean up our mess around composefs/fsverity...we have duplication
       // between the repo config and the sysroot config, *and* we need to better
       // handle skew between repo config and repo state (e.g. "post-copy" should
       // support transitioning verity on and off in general).
       // For now we configure things such that the fsverity digest is only added
       // if present on disk in the unsigned case, and in the signed case unconditionally
       // require it.
-      g_autoptr(GVariantBuilder) cfs_checkout_opts_builder = g_variant_builder_new (G_VARIANT_TYPE ("a{sv}"));
+      g_autoptr (GVariantBuilder) cfs_checkout_opts_builder
+          = g_variant_builder_new (G_VARIANT_TYPE ("a{sv}"));
       guint32 composefs_requested = 1;
       if (composefs_config->is_signed)
         composefs_requested = 2;
       g_variant_builder_add (cfs_checkout_opts_builder, "{sv}", "verity",
-                               g_variant_new_uint32 (composefs_requested));
+                             g_variant_new_uint32 (composefs_requested));
       g_debug ("composefs requested: %u", composefs_requested);
       g_autoptr (GVariant) cfs_checkout_opts = g_variant_builder_end (cfs_checkout_opts_builder);
       if (!ostree_repo_checkout_composefs (repo, cfs_checkout_opts, ret_deployment_dfd,
                                            OSTREE_COMPOSEFS_NAME, csum, cancellable, error))
         return FALSE;
+      composefs_end_time = g_get_monotonic_time ();
     }
   else
     g_debug ("not using composefs");
 #endif
 
+  *checkout_elapsed = (checkout_end_time - checkout_start_time);
+  *composefs_elapsed = (composefs_end_time - composefs_start_time);
   if (out_deployment_dfd)
     *out_deployment_dfd = glnx_steal_fd (&ret_deployment_dfd);
   return TRUE;
@@ -3191,8 +3200,10 @@ sysroot_initialize_deployment (OstreeSysroot *self, const char *osname, const ch
 
   /* Check out the userspace tree onto the filesystem */
   glnx_autofd int deployment_dfd = -1;
-  if (!checkout_deployment_tree (self, repo, new_deployment, revision, &deployment_dfd, cancellable,
-                                 error))
+  guint64 checkout_elapsed = 0;
+  guint64 composefs_elapsed = 0;
+  if (!checkout_deployment_tree (self, repo, new_deployment, revision, &deployment_dfd,
+                                 &checkout_elapsed, &composefs_elapsed, cancellable, error))
     return FALSE;
 
   g_autoptr (OstreeKernelLayout) kernel_layout = NULL;
@@ -3204,12 +3215,20 @@ sysroot_initialize_deployment (OstreeSysroot *self, const char *osname, const ch
                                                 opts ? opts->override_kernel_argv : NULL);
   _ostree_deployment_set_overlay_initrds (new_deployment, opts ? opts->overlay_initrds : NULL);
 
+  guint64 etc_start_time = g_get_monotonic_time ();
   if (!prepare_deployment_etc (self, repo, new_deployment, deployment_dfd, cancellable, error))
     return FALSE;
+  guint64 etc_elapsed = g_get_monotonic_time () - etc_start_time;
 
   if (!prepare_deployment_var (self, new_deployment, deployment_dfd, cancellable, error))
     return FALSE;
 
+  g_autofree char *checkout_elapsed_str = ot_format_human_duration (checkout_elapsed);
+  g_autofree char *composefs_elapsed_str = ot_format_human_duration (composefs_elapsed);
+  g_autofree char *etc_elapsed_str = ot_format_human_duration (etc_elapsed);
+  ot_journal_print (LOG_INFO, "Created deployment; subtasks: checkout=%s composefs=%s etc=%s",
+                    checkout_elapsed_str, composefs_elapsed_str, etc_elapsed_str);
+
   ot_transfer_out_value (out_new_deployment, &new_deployment);
   return TRUE;
 }

src/libotutil/ot-gio-utils.c

@@ -170,3 +170,21 @@ ot_file_get_path_cached (GFile *file)
 
   return path;
 }
+
+/* Format the provided nanoseconds for human consumption;
+ * currently only suitable for tasks on the order of seconds.
+ */
+char *
+ot_format_human_duration (guint64 nanos)
+{
+  guint64 ms = nanos / 1000;
+  if (ms == 0)
+    return g_strdup_printf ("%" G_GUINT64_FORMAT "ns", nanos);
+  else if (ms < 1000)
+    return g_strdup_printf ("%" G_GUINT64_FORMAT "ms", ms);
+  else
+    {
+      double secs = ((double)ms) / 1000;
+      return g_strdup_printf ("%0.1fs", secs);
+    }
+}

src/libotutil/ot-gio-utils.h

@@ -63,4 +63,6 @@ gs_file_get_path_cached (GFile *file)
   return ot_file_get_path_cached (file);
 }
 
+char *ot_format_human_duration (guint64 nanos);
+
 G_END_DECLS

src/ostree/ot-builtin-checkout.c

@@ -155,8 +155,7 @@ process_one_checkout (OstreeRepo *repo, const char *resolved_commit, const char
       g_autoptr (GVariantBuilder) checkout_opts_builder
           = g_variant_builder_new (G_VARIANT_TYPE ("a{sv}"));
       if (opt_composefs_noverity)
-        g_variant_builder_add (checkout_opts_builder, "{sv}", "verity",
-                               g_variant_new_uint32 (0));
+        g_variant_builder_add (checkout_opts_builder, "{sv}", "verity", g_variant_new_uint32 (0));
       g_autoptr (GVariant) checkout_opts = g_variant_builder_end (checkout_opts_builder);
       return ostree_repo_checkout_composefs (repo, checkout_opts, AT_FDCWD, destination,
                                              resolved_commit, cancellable, error);

tests/test-ot-unix-utils.c

@@ -20,6 +20,7 @@
 #include "config.h"
 
 #include "libglnx.h"
+#include "ot-gio-utils.h"
 #include "ot-unix-utils.h"
 #include <glib.h>
 
@@ -74,11 +75,35 @@ test_ot_util_filename_validate (void)
   g_clear_error (&error);
 }
 
+static void
+test_ot_human_duration (void)
+{
+  struct tcase
+  {
+    guint64 v;
+    const char *expected;
+  };
+  const struct tcase test_cases[] = {
+    { 0, "0ns" },    { 590, "590ns" },    { 1590, "1ms" },
+    { 9001, "9ms" }, { 1597249, "1.6s" }, { 10597249, "10.6s" },
+  };
+
+  for (guint i = 0; i < G_N_ELEMENTS (test_cases); i++)
+    {
+      const struct tcase *tcase = &test_cases[i];
+      g_autofree char *buf = ot_format_human_duration (tcase->v);
+      g_assert_cmpstr (buf, ==, tcase->expected);
+    }
+
+  return;
+}
+
 int
 main (int argc, char **argv)
 {
   g_test_init (&argc, &argv, NULL);
   g_test_add_func ("/ot_util_path_split_validate", test_ot_util_path_split_validate);
   g_test_add_func ("/ot_util_filename_validate", test_ot_util_filename_validate);
+  g_test_add_func ("/ot_human_duration", test_ot_human_duration);
   return g_test_run ();
 }