diff --git a/src/libostree/ostree-sysroot-deploy.c b/src/libostree/ostree-sysroot-deploy.c index abc97292bb..e14a5c339c 100644 --- a/src/libostree/ostree-sysroot-deploy.c +++ b/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,9 +630,11 @@ 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)) @@ -663,8 +665,11 @@ checkout_deployment_tree (OstreeSysroot *sysroot, OstreeRepo *repo, OstreeDeploy g_debug ("composefs enabled by config: %d repo: %d", composefs_enabled, repo->composefs_wanted); if (repo->composefs_wanted == OT_TRISTATE_YES) composefs_enabled = repo->composefs_wanted; + guint64 composefs_start_time = 0; + guint64 composefs_end_time = 0; 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 @@ -672,22 +677,26 @@ checkout_deployment_tree (OstreeSysroot *sysroot, OstreeRepo *repo, OstreeDeploy // 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; } diff --git a/src/libotutil/ot-gio-utils.c b/src/libotutil/ot-gio-utils.c index d3d9765cc4..3e2432a995 100644 --- a/src/libotutil/ot-gio-utils.c +++ b/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); + } +} diff --git a/src/libotutil/ot-gio-utils.h b/src/libotutil/ot-gio-utils.h index 9928713771..5197e1f9e3 100644 --- a/src/libotutil/ot-gio-utils.h +++ b/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 diff --git a/src/ostree/ot-builtin-checkout.c b/src/ostree/ot-builtin-checkout.c index bfbe5d3c3b..0c776196fe 100644 --- a/src/ostree/ot-builtin-checkout.c +++ b/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); diff --git a/tests/test-ot-unix-utils.c b/tests/test-ot-unix-utils.c index 853e877ff5..659b5c2d84 100644 --- a/tests/test-ot-unix-utils.c +++ b/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 @@ -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 (); }