From 7829003e8082ca710f6c1660b069bcaeb5a65d03 Mon Sep 17 00:00:00 2001 From: Colin Walters Date: Sun, 27 Oct 2024 16:24:49 -0400 Subject: [PATCH] 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. --- src/libostree/ostree-sysroot-deploy.c | 31 +++++++++++++++++++++------ src/libotutil/ot-gio-utils.c | 18 ++++++++++++++++ src/libotutil/ot-gio-utils.h | 2 ++ src/ostree/ot-builtin-checkout.c | 3 +-- tests/test-ot-unix-utils.c | 25 +++++++++++++++++++++ 5 files changed, 71 insertions(+), 8 deletions(-) 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 (); }