Add startup profiling functionality

Using `sudo FWUPD_PROFILE=10 ./src/fwupd --verbose` will print a
dump of startup times onto the console so that we can debug which
plugin is slowing down system startup. For example:

    ../src/fu-engine.c:5409:plugins-coldplug [108.55ms]:
        ../plugins/amt/fu-plugin-amt.c:437:amt [27.14ms]:
            :create-context [12.66ms]
            :get-version [8.44ms]
            :add-device [3.95ms]

docs/env.md

@@ -17,6 +17,7 @@ with a non-standard filesystem layout.
 * `FWUPD_XMLB_VERBOSE` can be set to show Xmlb silo regeneration and quirk matches
 * `FWUPD_DBUS_SOCKET` is used to set the socket filename if running without a dbus-daemon
 * `FWUPD_DOWNLOAD_VERBOSE` can be used to show wget or curl output
+* `FWUPD_PROFILE` can be used to set the profile traceback threshold value in ms
 * standard glibc variables like `LANG` are also honored for CLI tools that are translated
 * libcurl respects the session proxy, e.g. `http_proxy`, `all_proxy`, `sftp_proxy` and `no_proxy`
 

libfwupdplugin/fu-progress.c

@@ -11,6 +11,7 @@
 #include <math.h>
 
 #include "fu-progress.h"
+#include "fu-string.h"
 
 /**
  * FuProgress:
@@ -62,23 +63,16 @@ typedef struct {
 	FuProgressFlags flags;
 	guint percentage;
 	FwupdStatus status;
-	GPtrArray *steps;
+	GPtrArray *children; /* of FuProgress */
 	gboolean profile;
+	gdouble duration; /* seconds */
+	guint step_weighting;
 	GTimer *timer;
+	GTimer *timer_child;
 	guint step_now;
-	guint step_max;
-	gulong percentage_child_id;
-	gulong status_child_id;
-	FuProgress *child;
 	FuProgress *parent; /* no-ref */
 } FuProgressPrivate;
 
-typedef struct {
-	FwupdStatus status;
-	guint value;
-	gdouble profile;
-} FuProgressStep;
-
 enum { SIGNAL_PERCENTAGE_CHANGED, SIGNAL_STATUS_CHANGED, SIGNAL_LAST };
 
 static guint signals[SIGNAL_LAST] = {0};
@@ -216,6 +210,8 @@ fu_progress_flag_to_string(FuProgressFlags flag)
 		return "guessed";
 	if (flag == FU_PROGRESS_FLAG_NO_PROFILE)
 		return "no-profile";
+	if (flag == FU_PROGRESS_FLAG_NO_TRACEBACK)
+		return "no-traceback";
 	return NULL;
 }
 
@@ -236,6 +232,8 @@ fu_progress_flag_from_string(const gchar *flag)
 		return FU_PROGRESS_FLAG_GUESSED;
 	if (g_strcmp0(flag, "no-profile") == 0)
 		return FU_PROGRESS_FLAG_NO_PROFILE;
+	if (g_strcmp0(flag, "no-traceback") == 0)
+		return FU_PROGRESS_FLAG_NO_TRACEBACK;
 	return FU_PROGRESS_FLAG_UNKNOWN;
 }
 
@@ -334,6 +332,54 @@ fu_progress_get_percentage(FuProgress *self)
 	return priv->percentage;
 }
 
+static void
+fu_progress_set_parent(FuProgress *self, FuProgress *parent)
+{
+	FuProgressPrivate *priv = GET_PRIVATE(self);
+	g_return_if_fail(FU_IS_PROGRESS(self));
+	g_return_if_fail(FU_IS_PROGRESS(parent));
+	priv->parent = parent; /* no ref! */
+	priv->profile = fu_progress_get_profile(parent);
+}
+
+static guint
+fu_progress_get_step_weighting(FuProgress *self)
+{
+	FuProgressPrivate *priv = GET_PRIVATE(self);
+	return priv->step_weighting;
+}
+
+static void
+fu_progress_set_step_weighting(FuProgress *self, guint step_weighting)
+{
+	FuProgressPrivate *priv = GET_PRIVATE(self);
+	priv->step_weighting = step_weighting;
+}
+
+/**
+ * fu_progress_get_duration:
+ * @self: a #FuProgress
+ *
+ * Get the duration of the step.
+ *
+ * Return value: The duration value in seconds
+ *
+ * Since: 1.8.2
+ **/
+gdouble
+fu_progress_get_duration(FuProgress *self)
+{
+	FuProgressPrivate *priv = GET_PRIVATE(self);
+	return priv->duration;
+}
+
+static void
+fu_progress_set_duration(FuProgress *self, gdouble duration)
+{
+	FuProgressPrivate *priv = GET_PRIVATE(self);
+	priv->duration = duration;
+}
+
 static void
 fu_progress_build_parent_chain(FuProgress *self, GString *str, guint level)
 {
@@ -345,7 +391,7 @@ fu_progress_build_parent_chain(FuProgress *self, GString *str, guint level)
 			       level,
 			       priv->id,
 			       priv->step_now,
-			       priv->step_max);
+			       priv->children->len);
 }
 
 /**
@@ -383,6 +429,10 @@ fu_progress_set_percentage(FuProgress *self, guint percentage)
 		return;
 	}
 
+	/* done */
+	if (percentage == 100)
+		fu_progress_set_duration(self, g_timer_elapsed(priv->timer, NULL));
+
 	/* save */
 	priv->percentage = percentage;
 	g_signal_emit(self, signals[SIGNAL_PERCENTAGE_CHANGED], 0, percentage);
@@ -430,15 +480,14 @@ fu_progress_set_profile(FuProgress *self, gboolean profile)
 /**
  * fu_progress_get_profile:
  * @self: A #FuProgress
- * @profile:
  *
  * Returns if the profile is enabled for this progress.
  *
- * Return value: if profiling should be enabled
+ * Return value: if profiling has been enabled
  *
- * Since: 1.7.0
+ * Since: 1.8.2
  **/
-static gboolean
+gboolean
 fu_progress_get_profile(FuProgress *self)
 {
 	FuProgressPrivate *priv = GET_PRIVATE(self);
@@ -461,27 +510,17 @@ fu_progress_reset(FuProgress *self)
 	g_return_if_fail(FU_IS_PROGRESS(self));
 
 	/* reset values */
-	priv->step_max = 0;
 	priv->step_now = 0;
 	priv->percentage = G_MAXUINT;
 
 	/* only use the timer if profiling; it's expensive */
-	if (priv->profile)
+	if (priv->profile) {
 		g_timer_start(priv->timer);
-
+		g_timer_start(priv->timer_child);
-	/* disconnect client */
-	if (priv->percentage_child_id != 0) {
-		g_signal_handler_disconnect(priv->child, priv->percentage_child_id);
-		priv->percentage_child_id = 0;
 	}
-	if (priv->status_child_id != 0) {
-		g_signal_handler_disconnect(priv->child, priv->status_child_id);
-		priv->status_child_id = 0;
-	}
-	g_clear_object(&priv->child);
 
 	/* no more step data */
-	g_ptr_array_set_size(priv->steps, 0);
+	g_ptr_array_set_size(priv->children, 0);
 }
 
 /**
@@ -503,15 +542,16 @@ fu_progress_set_steps(FuProgress *self, guint step_max)
 	g_return_if_fail(FU_IS_PROGRESS(self));
 	g_return_if_fail(priv->id != NULL);
 
-	/* only use the timer if profiling; it's expensive */
+	/* create fake steps */
-	if (priv->profile)
+	for (guint i = 0; i < step_max; i++)
-		g_timer_start(priv->timer);
+		fu_progress_add_step(self, priv->status, 0, NULL);
-
-	/* set step_max */
-	priv->step_max = step_max;
 
 	/* show that the sub-progress has been created */
 	fu_progress_set_percentage(self, 0);
+	fu_progress_add_flag(self, FU_PROGRESS_FLAG_NO_PROFILE);
+
+	/* reset child timer */
+	g_timer_start(priv->timer_child);
 }
 
 /**
@@ -530,69 +570,7 @@ fu_progress_get_steps(FuProgress *self)
 {
 	FuProgressPrivate *priv = GET_PRIVATE(self);
 	g_return_val_if_fail(FU_IS_PROGRESS(self), G_MAXUINT);
-	return priv->step_max;
+	return priv->children->len;
-}
-
-/**
- * fu_progress_add_step:
- * @self: A #FuProgress
- * @status: status value to use for this phase
- * @value: A step weighting variable argument array
- * @name: (nullable): Human readable name to identify the step
- *
- * This sets the step weighting, which you will want to do if one action
- * will take a bigger chunk of time than another.
- *
- * The progress ID must be set fu_progress_set_id() before this method is used.
- *
- * Since: 1.8.2
- **/
-void
-fu_progress_add_step(FuProgress *self, FwupdStatus status, guint value, const gchar *name)
-{
-	FuProgressPrivate *priv = GET_PRIVATE(self);
-	FuProgressStep *step;
-
-	g_return_if_fail(FU_IS_PROGRESS(self));
-	g_return_if_fail(priv->id != NULL);
-
-	/* current status */
-	if (priv->steps->len == 0)
-		fu_progress_set_status(self, status);
-
-	/* save data */
-	step = g_new0(FuProgressStep, 1);
-	step->status = status;
-	step->value = value;
-	step->profile = .0;
-	g_ptr_array_add(priv->steps, step);
-
-	/* in case anything is not using ->steps */
-	fu_progress_set_steps(self, priv->steps->len);
-}
-
-/**
- * fu_progress_finished:
- * @self: A #FuProgress
- *
- * Called when the step_now sub-task wants to finish early and still complete.
- *
- * Since: 1.7.0
- **/
-void
-fu_progress_finished(FuProgress *self)
-{
-	FuProgressPrivate *priv = GET_PRIVATE(self);
-
-	g_return_if_fail(FU_IS_PROGRESS(self));
-
-	/* is already at 100%? */
-	if (priv->step_now == priv->step_max)
-		return;
-
-	/* all done */
-	priv->step_now = priv->step_max;
-	fu_progress_set_percentage(self, 100);
 }
 
 static gdouble
@@ -615,14 +593,14 @@ fu_progress_get_step_percentage(FuProgress *self, guint idx)
 	guint current = 0;
 	guint total = 0;
 
-	for (guint i = 0; i < priv->steps->len; i++) {
+	for (guint i = 0; i < priv->children->len; i++) {
-		FuProgressStep *step = g_ptr_array_index(priv->steps, i);
+		FuProgress *child = g_ptr_array_index(priv->children, i);
 		if (i <= idx)
-			current += step->value;
+			current += fu_progress_get_step_weighting(child);
-		total += step->value;
+		total += fu_progress_get_step_weighting(child);
 	}
 	if (total == 0)
-		return 0;
+		return -1;
 	return ((gdouble)current * 100.f) / (gdouble)total;
 }
 
@@ -639,50 +617,51 @@ fu_progress_child_percentage_changed_cb(FuProgress *child, guint percentage, FuP
 	gdouble offset;
 	gdouble range;
 	gdouble extra;
-	guint parent_percentage;
+	guint parent_percentage = G_MAXUINT;
 
-	/* propagate up the stack if FuProgress has only one step */
+	/* propagate up the stack if FuProgress has only one priv */
-	if (priv->step_max == 1) {
+	if (priv->children->len == 1) {
 		fu_progress_set_percentage(self, percentage);
 		return;
 	}
 
-	/* did we call done on a self that did not have a size set? */
+	/* did we call done on a step that did not have a size set? */
-	if (priv->step_max == 0)
+	if (priv->children->len == 0)
 		return;
 
 	/* already at >= 100% */
-	if (priv->step_now >= priv->step_max) {
+	if (priv->step_now >= priv->children->len) {
-		g_warning("already at %u/%u step_max", priv->step_now, priv->step_max);
+		g_warning("already at %u/%u step_max", priv->step_now, priv->children->len);
 		return;
 	}
 
 	/* if the child finished, set the status back to the last parent status */
-	if (percentage == 100 && priv->steps->len > 0) {
+	if (percentage == 100 && priv->children->len > 0) {
-		FuProgressStep *step = g_ptr_array_index(priv->steps, priv->step_now);
+		FuProgress *child_tmp = g_ptr_array_index(priv->children, priv->step_now);
-		fu_progress_set_status(self, step->status);
+		if (fu_progress_get_status(child_tmp) != FWUPD_STATUS_UNKNOWN)
+			fu_progress_set_status(self, fu_progress_get_status(child_tmp));
 	}
 
-	/* we have to deal with non-linear step_max */
+	/* we don't store zero */
-	if (priv->steps->len > 0) {
+	if (priv->step_now == 0) {
-		/* we don't store zero */
+		gdouble pc = fu_progress_get_step_percentage(self, 0);
-		if (priv->step_now == 0) {
+		if (pc > 0)
-			gdouble pc = fu_progress_get_step_percentage(self, 0);
 			parent_percentage = percentage * pc / 100;
-		} else {
+	} else {
-			gdouble pc1 = fu_progress_get_step_percentage(self, priv->step_now - 1);
+		gdouble pc1 = fu_progress_get_step_percentage(self, priv->step_now - 1);
-			gdouble pc2 = fu_progress_get_step_percentage(self, priv->step_now);
+		gdouble pc2 = fu_progress_get_step_percentage(self, priv->step_now);
-			/* bi-linearly interpolate */
+		/* bi-linearly interpolate */
+		if (pc1 > 0 && pc2 > 0)
 			parent_percentage = (((100 - percentage) * pc1) + (percentage * pc2)) / 100;
-		}
+	}
-		goto out;
+	if (parent_percentage != G_MAXUINT) {
+		fu_progress_set_percentage(self, parent_percentage);
+		return;
 	}
 
-	/* get the offset */
+	/* get the range between the parent priv and the next parent priv */
-	offset = fu_progress_discrete_to_percent(priv->step_now, priv->step_max);
+	offset = fu_progress_discrete_to_percent(priv->step_now, priv->children->len);
-
+	range = fu_progress_discrete_to_percent(priv->step_now + 1, priv->children->len) - offset;
-	/* get the range between the parent step and the next parent step */
-	range = fu_progress_discrete_to_percent(priv->step_now + 1, priv->step_max) - offset;
 	if (range < 0.01)
 		return;
 
@@ -691,17 +670,88 @@ fu_progress_child_percentage_changed_cb(FuProgress *child, guint percentage, FuP
 
 	/* emit from the parent */
 	parent_percentage = (guint)(offset + extra);
-out:
 	fu_progress_set_percentage(self, parent_percentage);
 }
 
-static void
+/**
-fu_progress_set_parent(FuProgress *self, FuProgress *parent)
+ * fu_progress_add_step:
+ * @self: A #FuProgress
+ * @status: status value to use for this phase
+ * @value: A step weighting variable argument array
+ * @name: (nullable): Human readable name to identify the step
+ *
+ * This sets the step weighting, which you will want to do if one action
+ * will take a bigger chunk of time than another.
+ *
+ * The progress ID must be set fu_progress_set_id() before this method is used.
+ *
+ * Since: 1.8.2
+ **/
+void
+fu_progress_add_step(FuProgress *self, FwupdStatus status, guint value, const gchar *name)
+{
+	g_autoptr(FuProgress) child = fu_progress_new(NULL);
+	FuProgressPrivate *priv = GET_PRIVATE(self);
+
+	g_return_if_fail(FU_IS_PROGRESS(self));
+	g_return_if_fail(priv->id != NULL);
+
+	/* save data */
+	fu_progress_set_status(child, status);
+	fu_progress_set_step_weighting(child, value);
+
+	/* connect signals */
+	g_signal_connect(FU_PROGRESS(child),
+			 "percentage-changed",
+			 G_CALLBACK(fu_progress_child_percentage_changed_cb),
+			 self);
+	g_signal_connect(FU_PROGRESS(child),
+			 "status-changed",
+			 G_CALLBACK(fu_progress_child_status_changed_cb),
+			 self);
+	fu_progress_set_parent(child, self);
+	if (name != NULL)
+		fu_progress_set_name(child, name);
+
+	/* use first child status */
+	if (priv->children->len == 0)
+		fu_progress_set_status(self, status);
+
+	/* add child */
+	g_ptr_array_add(priv->children, g_steal_pointer(&child));
+
+	/* reset child timer */
+	g_timer_start(priv->timer_child);
+}
+
+/**
+ * fu_progress_finished:
+ * @self: A #FuProgress
+ *
+ * Called when the step_now sub-task wants to finish early and still complete.
+ *
+ * Since: 1.7.0
+ **/
+void
+fu_progress_finished(FuProgress *self)
 {
 	FuProgressPrivate *priv = GET_PRIVATE(self);
+
 	g_return_if_fail(FU_IS_PROGRESS(self));
-	priv->parent = parent; /* no ref! */
+
-	priv->profile = fu_progress_get_profile(parent);
+	/* is already at 100%? */
+	if (priv->step_now == priv->children->len)
+		return;
+
+	/* all done */
+	priv->step_now = priv->children->len;
+	fu_progress_set_percentage(self, 100);
+
+	/* we finished early, so invalidate children */
+	for (guint i = 0; i < priv->children->len; i++) {
+		FuProgress *child = g_ptr_array_index(priv->children, i);
+		fu_progress_add_flag(child, FU_PROGRESS_FLAG_NO_TRACEBACK);
+	}
 }
 
 /**
@@ -721,25 +771,11 @@ fu_progress_get_child(FuProgress *self)
 
 	g_return_val_if_fail(FU_IS_PROGRESS(self), NULL);
 	g_return_val_if_fail(priv->id != NULL, NULL);
+	g_return_val_if_fail(priv->children->len > 0, NULL);
+	g_return_val_if_fail(priv->children->len > priv->step_now, NULL);
 
-	/* already created child */
+	/* all preallocated, nothing to do */
-	if (priv->child != NULL)
+	return FU_PROGRESS(g_ptr_array_index(priv->children, priv->step_now));
-		return priv->child;
-
-	/* connect up signals */
-	priv->child = fu_progress_new(NULL);
-	priv->percentage_child_id =
-	    g_signal_connect(FU_PROGRESS(priv->child),
-			     "percentage-changed",
-			     G_CALLBACK(fu_progress_child_percentage_changed_cb),
-			     self);
-	priv->status_child_id = g_signal_connect(FU_PROGRESS(priv->child),
-						 "status-changed",
-						 G_CALLBACK(fu_progress_child_status_changed_cb),
-						 self);
-	fu_progress_set_parent(priv->child, self);
-	fu_progress_set_status(priv->child, priv->status);
-	return priv->child;
 }
 
 static void
@@ -757,18 +793,18 @@ fu_progress_show_profile(FuProgress *self)
 
 	/* get the total time so we can work out the divisor */
 	str = g_string_new("raw timing data was { ");
-	for (guint i = 0; i < priv->step_max; i++) {
+	for (guint i = 0; i < priv->children->len; i++) {
-		FuProgressStep *step = g_ptr_array_index(priv->steps, i);
+		FuProgress *child = g_ptr_array_index(priv->children, i);
-		g_string_append_printf(str, "%.3f, ", step->profile);
+		g_string_append_printf(str, "%.3f, ", fu_progress_get_duration(child));
 	}
-	if (priv->step_max > 0)
+	if (priv->children->len > 0)
 		g_string_set_size(str, str->len - 2);
 	g_string_append(str, " } -- ");
 
 	/* get the total time so we can work out the divisor */
-	for (guint i = 0; i < priv->step_max; i++) {
+	for (guint i = 0; i < priv->children->len; i++) {
-		FuProgressStep *step = g_ptr_array_index(priv->steps, i);
+		FuProgress *child = g_ptr_array_index(priv->children, i);
-		total_time += step->profile;
+		total_time += fu_progress_get_duration(child);
 	}
 	if (total_time < 0.001)
 		return;
@@ -776,20 +812,22 @@ fu_progress_show_profile(FuProgress *self)
 
 	/* what we set */
 	g_string_append(str, "steps were set as [ ");
-	for (guint i = 0; i < priv->step_max; i++) {
+	for (guint i = 0; i < priv->children->len; i++) {
-		FuProgressStep *step = g_ptr_array_index(priv->steps, i);
+		FuProgress *child = g_ptr_array_index(priv->children, i);
-		g_string_append_printf(str, "%u ", step->value);
+		g_string_append_printf(str, "%u ", fu_progress_get_step_weighting(child));
 	}
 
 	/* what we _should_ have set */
 	g_string_append_printf(str, "] but should have been [ ");
-	for (guint i = 0; i < priv->step_max; i++) {
+	for (guint i = 0; i < priv->children->len; i++) {
-		FuProgressStep *step = g_ptr_array_index(priv->steps, i);
+		FuProgress *child = g_ptr_array_index(priv->children, i);
-		g_string_append_printf(str, "%.0f ", step->profile / division);
+		g_string_append_printf(str, "%.0f ", fu_progress_get_duration(child) / division);
 
 		/* this is sufficiently different to what we guessed */
-		if (fabs((gdouble)step->value - step->profile / division) > 5)
+		if (fabs((fu_progress_get_duration(child) / division) -
+			 (gdouble)fu_progress_get_step_weighting(child)) > 5) {
 			close_enough = FALSE;
+		}
 	}
 	g_string_append(str, "]");
 	if (priv->flags & FU_PROGRESS_FLAG_GUESSED) {
@@ -816,31 +854,34 @@ fu_progress_show_profile(FuProgress *self)
 void
 fu_progress_step_done(FuProgress *self)
 {
+	FuProgress *child = NULL;
 	FuProgressPrivate *priv = GET_PRIVATE(self);
 	gdouble percentage;
 
 	g_return_if_fail(FU_IS_PROGRESS(self));
 	g_return_if_fail(priv->id != NULL);
 
-	/* did we call done on a self that did not have a size set? */
+	/* did we call done when no size set? */
-	if (priv->step_max == 0) {
+	if (priv->children->len == 0) {
 		g_autoptr(GString) str = g_string_new(NULL);
 		fu_progress_build_parent_chain(self, str, 0);
 		g_warning("progress done when no size set! [%s]: %s", priv->id, str->str);
 		return;
 	}
 
+	/* get the active child */
+	if (priv->children->len > 0)
+		child = g_ptr_array_index(priv->children, priv->step_now);
+
 	/* save the duration in the array */
 	if (priv->profile) {
-		if (priv->steps->len > 0) {
+		if (child != NULL)
-			FuProgressStep *step = g_ptr_array_index(priv->steps, priv->step_now);
+			fu_progress_set_duration(child, g_timer_elapsed(priv->timer_child, NULL));
-			step->profile = g_timer_elapsed(priv->timer, NULL);
+		g_timer_start(priv->timer_child);
-		}
-		g_timer_start(priv->timer);
 	}
 
 	/* is already at 100%? */
-	if (priv->step_now >= priv->step_max) {
+	if (priv->step_now >= priv->children->len) {
 		g_autoptr(GString) str = g_string_new(NULL);
 		fu_progress_build_parent_chain(self, str, 0);
 		g_warning("already at 100%% [%s]: %s", priv->id, str->str);
@@ -848,14 +889,14 @@ fu_progress_step_done(FuProgress *self)
 	}
 
 	/* is child not at 100%? */
-	if (!fu_progress_has_flag(self, FU_PROGRESS_FLAG_CHILD_FINISHED) && priv->child != NULL) {
+	if (!fu_progress_has_flag(self, FU_PROGRESS_FLAG_CHILD_FINISHED) && child != NULL) {
-		FuProgressPrivate *child_priv = GET_PRIVATE(priv->child);
+		FuProgressPrivate *child_priv = GET_PRIVATE(child);
-		if (child_priv->step_now != child_priv->step_max) {
+		if (child_priv->step_now != child_priv->children->len) {
 			g_autoptr(GString) str = g_string_new(NULL);
-			fu_progress_build_parent_chain(priv->child, str, 0);
+			fu_progress_build_parent_chain(child, str, 0);
 			g_warning("child is at %u/%u step_max and parent done [%s]\n%s",
 				  child_priv->step_now,
-				  child_priv->step_max,
+				  child_priv->children->len,
 				  priv->id,
 				  str->str);
 			/* do not abort, as we want to clean this up */
@@ -866,30 +907,25 @@ fu_progress_step_done(FuProgress *self)
 	priv->step_now++;
 
 	/* update status */
-	if (priv->steps->len > 0) {
+	if (priv->step_now < priv->children->len) {
-		if (priv->step_now == priv->step_max) {
+		FuProgress *child_tmp = g_ptr_array_index(priv->children, priv->step_now);
-			fu_progress_set_status(self, FWUPD_STATUS_UNKNOWN);
+		if (fu_progress_get_status(child_tmp) != FWUPD_STATUS_UNKNOWN)
-		} else {
+			fu_progress_set_status(self, fu_progress_get_status(child_tmp));
-			FuProgressStep *step = g_ptr_array_index(priv->steps, priv->step_now);
+	} else if (priv->parent != NULL) {
-			fu_progress_set_status(self, step->status);
+		fu_progress_set_status(self, fu_progress_get_percentage(priv->parent));
-		}
+	} else {
+		fu_progress_set_status(self, FWUPD_STATUS_UNKNOWN);
 	}
 
 	/* find new percentage */
-	if (priv->steps->len == 0) {
+	percentage = fu_progress_get_step_percentage(self, priv->step_now - 1);
-		percentage = fu_progress_discrete_to_percent(priv->step_now, priv->step_max);
+	if (percentage < 0)
-	} else {
+		percentage = fu_progress_discrete_to_percent(priv->step_now, priv->children->len);
-		percentage = fu_progress_get_step_percentage(self, priv->step_now - 1);
-	}
 	fu_progress_set_percentage(self, (guint)percentage);
 
 	/* show any profiling stats */
-	if (priv->profile && priv->step_now == priv->step_max && priv->steps->len > 0)
+	if (priv->profile && priv->step_now == priv->children->len)
 		fu_progress_show_profile(self);
-
-	/* reset child if it exists */
-	if (priv->child != NULL)
-		fu_progress_reset(priv->child);
 }
 
 /**
@@ -916,13 +952,77 @@ fu_progress_sleep(FuProgress *self, guint delay_ms)
 	}
 }
 
+static void
+fu_progress_traceback_cb(FuProgress *self,
+			 guint idt,
+			 guint child_idx,
+			 guint threshold_ms,
+			 GString *str)
+{
+	FuProgressPrivate *priv = GET_PRIVATE(self);
+	if (priv->flags & FU_PROGRESS_FLAG_NO_TRACEBACK)
+		return;
+	if (priv->children->len == 0 && fu_progress_get_duration(self) < 0.0001)
+		return;
+	if (threshold_ms == 0 || fu_progress_get_duration(self) * 1000 > threshold_ms) {
+		for (guint i = 0; i < idt; i++)
+			g_string_append(str, " ");
+		if (priv->id != NULL)
+			g_string_append(str, priv->id);
+		if (priv->name != NULL)
+			g_string_append_printf(str, ":%s", priv->name);
+		if (priv->id == NULL && priv->name == NULL && child_idx != G_MAXUINT)
+			g_string_append_printf(str, "@%u", child_idx);
+		g_string_append_printf(str, " [%.2fms]", fu_progress_get_duration(self) * 1000.f);
+		g_string_append(str, priv->children->len > 0 ? ":\n" : "\n");
+	}
+	for (guint i = 0; i < priv->children->len; i++) {
+		FuProgress *child = g_ptr_array_index(priv->children, i);
+		fu_progress_traceback_cb(child, idt + 4, i, threshold_ms, str);
+	}
+}
+
+/**
+ * fu_progress_traceback:
+ * @self: A #FuProgress
+ * @threshold_ms: value in ms, or 0 for everything
+ *
+ * Create a traceback used for profiling startup.
+ *
+ * Return value: (transfer full): string
+ *
+ * Since: 1.8.2
+ **/
+gchar *
+fu_progress_traceback(FuProgress *self)
+{
+	const gchar *tmp = g_getenv("FWUPD_PROFILE");
+	guint64 threshold_ms = 5000;
+	g_autoptr(GString) str = g_string_new(NULL);
+
+	/* allow override */
+	if (tmp != NULL) {
+		g_autoptr(GError) error_local = NULL;
+		if (!fu_strtoull(tmp, &threshold_ms, 0, G_MAXUINT, &error_local))
+			g_warning("invalid threshold value: %s", tmp);
+	}
+
+	fu_progress_traceback_cb(self, 0, G_MAXUINT, threshold_ms, str);
+	if (str->len == 0)
+		return NULL;
+	return g_string_free(g_steal_pointer(&str), FALSE);
+}
+
 static void
 fu_progress_init(FuProgress *self)
 {
 	FuProgressPrivate *priv = GET_PRIVATE(self);
+	priv->status = FWUPD_STATUS_UNKNOWN;
 	priv->percentage = G_MAXUINT;
 	priv->timer = g_timer_new();
-	priv->steps = g_ptr_array_new_with_free_func(g_free);
+	priv->timer_child = g_timer_new();
+	priv->children = g_ptr_array_new_with_free_func((GDestroyNotify)g_object_unref);
+	priv->duration = 0.f;
 }
 
 static void
@@ -931,11 +1031,16 @@ fu_progress_finalize(GObject *object)
 	FuProgress *self = FU_PROGRESS(object);
 	FuProgressPrivate *priv = GET_PRIVATE(self);
 
+	/* show any profiling stats */
+	if (priv->profile)
+		fu_progress_show_profile(self);
+
 	fu_progress_reset(self);
 	g_free(priv->id);
 	g_free(priv->name);
-	g_ptr_array_unref(priv->steps);
+	g_ptr_array_unref(priv->children);
 	g_timer_destroy(priv->timer);
+	g_timer_destroy(priv->timer_child);
 
 	G_OBJECT_CLASS(fu_progress_parent_class)->finalize(object);
 }

libfwupdplugin/fu-progress.h

@@ -73,6 +73,15 @@ typedef guint64 FuProgressFlags;
  */
 #define FU_PROGRESS_FLAG_CHILD_FINISHED (1ull << 2)
 
+/**
+ * FU_PROGRESS_FLAG_NO_TRACEBACK:
+ *
+ * The steps should not be shown in the traceback.
+ *
+ * Since: 1.8.2
+ */
+#define FU_PROGRESS_FLAG_NO_TRACEBACK (1ull << 3)
+
 FuProgress *
 fu_progress_new(const gchar *id);
 const gchar *
@@ -103,8 +112,12 @@ void
 fu_progress_set_percentage_full(FuProgress *self, gsize progress_done, gsize progress_total);
 guint
 fu_progress_get_percentage(FuProgress *self);
+gdouble
+fu_progress_get_duration(FuProgress *self);
 void
 fu_progress_set_profile(FuProgress *self, gboolean profile);
+gboolean
+fu_progress_get_profile(FuProgress *self);
 void
 fu_progress_reset(FuProgress *self);
 void
@@ -121,3 +134,5 @@ FuProgress *
 fu_progress_get_child(FuProgress *self);
 void
 fu_progress_sleep(FuProgress *self, guint delay_ms);
+gchar *
+fu_progress_traceback(FuProgress *self);

libfwupdplugin/fu-self-test.c

@@ -3125,17 +3125,26 @@ fu_progress_func(void)
 			 G_CALLBACK(fu_progress_percentage_changed_cb),
 			 &helper);
 
+	g_assert_cmpfloat_with_epsilon(fu_progress_get_duration(progress), 0.f, 0.001);
+
+	fu_progress_set_profile(progress, TRUE);
 	fu_progress_set_steps(progress, 5);
 	g_assert_cmpint(helper.last_percentage, ==, 0);
 
+	g_usleep(20 * 1000);
 	fu_progress_step_done(progress);
 	g_assert_cmpint(helper.updates, ==, 2);
 	g_assert_cmpint(helper.last_percentage, ==, 20);
 
-	for (guint i = 0; i < 4; i++)
+	for (guint i = 0; i < 4; i++) {
+		g_usleep(20 * 1000);
 		fu_progress_step_done(progress);
+	}
+
 	g_assert_cmpint(helper.last_percentage, ==, 100);
 	g_assert_cmpint(helper.updates, ==, 6);
+	g_assert_cmpfloat_with_epsilon(fu_progress_get_duration(progress), 0.1f, 0.01);
+	g_debug("\n%s", fu_progress_traceback(progress));
 }
 
 static void
@@ -3362,6 +3371,7 @@ main(int argc, char **argv)
 	(void)g_setenv("FWUPD_SYSCONFDIR", testdatadir, TRUE);
 	(void)g_setenv("FWUPD_OFFLINE_TRIGGER", "/tmp/fwupd-self-test/system-update", TRUE);
 	(void)g_setenv("FWUPD_LOCALSTATEDIR", "/tmp/fwupd-self-test/var", TRUE);
+	(void)g_setenv("FWUPD_PROFILE", "1", TRUE);
 
 	g_test_add_func("/fwupd/common{strnsplit}", fu_strsplit_func);
 	g_test_add_func("/fwupd/common{memmem}", fu_common_memmem_func);

libfwupdplugin/fwupdplugin.map

@@ -969,8 +969,11 @@ LIBFWUPDPLUGIN_1.8.2 {
     fu_path_mkdir_parent;
     fu_path_rmtree;
     fu_progress_add_step;
+    fu_progress_get_duration;
     fu_progress_get_name;
+    fu_progress_get_profile;
     fu_progress_set_name;
+    fu_progress_traceback;
     fu_string_append;
     fu_string_append_kb;
     fu_string_append_ku;

src/fu-daemon.c

@@ -2242,6 +2242,13 @@ fu_daemon_setup(FuDaemon *self, const gchar *socket_address, GError **error)
 	}
 	fu_progress_step_done(progress);
 
+	/* a good place to do the traceback */
+	if (fu_progress_get_profile(progress)) {
+		g_autofree gchar *str = fu_progress_traceback(progress);
+		if (str != NULL)
+			g_print("\n%s\n", str);
+	}
+
 	/* success */
 	return TRUE;
 }

src/fu-tool.c

@@ -3981,6 +3981,13 @@ main(int argc, char *argv[])
 		return EXIT_FAILURE;
 	}
 
+	/* a good place to do the traceback */
+	if (fu_progress_get_profile(priv->progress)) {
+		g_autofree gchar *str = fu_progress_traceback(priv->progress);
+		if (str != NULL)
+			g_print("\n%s\n", str);
+	}
+
 	/* success */
 	return EXIT_SUCCESS;
 }