Merge branch 'es/trace-log-progress'

gitster · gitster · commit d98abce68f4b · 2020-05-14T14:39:45.000-07:00
Teach codepaths that show progress meter to also use the
start_progress() and the stop_progress() calls as a "region" to be
traced.

* es/trace-log-progress:
  trace2: log progress time and throughput
diff --git a/progress.c b/progress.c
@@ -265,6 +265,7 @@ static struct progress *start_progress_delay(const char *title, uint64_t total,
 	progress->title_len = utf8_strwidth(title);
 	progress->split = 0;
 	set_progress_signal();
+	trace2_region_enter("progress", title, the_repository);
 	return progress;
 }
 
@@ -320,6 +321,22 @@ void stop_progress(struct progress **p_progress)
 {
 	finish_if_sparse(*p_progress);
 
+	if (p_progress && *p_progress) {
+		trace2_data_intmax("progress", the_repository, "total_objects",
+				   (*p_progress)->total);
+
+		if ((*p_progress)->throughput)
+			trace2_data_intmax("progress", the_repository,
+					   "total_bytes",
+					   (*p_progress)->throughput->curr_total);
+	}
+
+	trace2_region_leave("progress",
+			    p_progress && *p_progress
+				? (*p_progress)->title
+				: NULL,
+			    the_repository);
+
 	stop_progress_msg(p_progress, _("done"));
 }
 
diff --git a/t/t0500-progress-display.sh b/t/t0500-progress-display.sh
@@ -283,4 +283,30 @@ test_expect_success 'cover up after throughput shortens a lot' '
 	test_i18ncmp expect out
 '
 
+test_expect_success 'progress generates traces' '
+	cat >in <<-\EOF &&
+	throughput 102400 1000
+	update
+	progress 10
+	throughput 204800 2000
+	update
+	progress 20
+	throughput 307200 3000
+	update
+	progress 30
+	throughput 409600 4000
+	update
+	progress 40
+	EOF
+
+	GIT_TRACE2_EVENT="$(pwd)/trace.event" test-tool progress --total=40 \
+		"Working hard" <in 2>stderr &&
+
+	# t0212/parse_events.perl intentionally omits regions and data.
+	grep -e "region_enter" -e "\"category\":\"progress\"" trace.event &&
+	grep -e "region_leave" -e "\"category\":\"progress\"" trace.event &&
+	grep "\"key\":\"total_objects\",\"value\":\"40\"" trace.event &&
+	grep "\"key\":\"total_bytes\",\"value\":\"409600\"" trace.event
+'
+
 test_done
