Skip to content

Commit

Permalink
deploy: Add timing information to journal
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
cgwalters committed Oct 27, 2024
1 parent 3375e9d commit 7829003
Show file tree
Hide file tree
Showing 5 changed files with 71 additions and 8 deletions.
31 changes: 25 additions & 6 deletions src/libostree/ostree-sysroot-deploy.c
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand All @@ -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))
Expand Down Expand Up @@ -663,31 +665,38 @@ 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
// 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;
Expand Down Expand Up @@ -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;
Expand All @@ -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;
}
Expand Down
18 changes: 18 additions & 0 deletions src/libotutil/ot-gio-utils.c
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
2 changes: 2 additions & 0 deletions src/libotutil/ot-gio-utils.h
Original file line number Diff line number Diff line change
Expand Up @@ -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
3 changes: 1 addition & 2 deletions src/ostree/ot-builtin-checkout.c
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
25 changes: 25 additions & 0 deletions tests/test-ot-unix-utils.c
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
#include "config.h"

#include "libglnx.h"
#include "ot-gio-utils.h"
#include "ot-unix-utils.h"
#include <glib.h>

Expand Down Expand Up @@ -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 ();
}

0 comments on commit 7829003

Please sign in to comment.