trace2: log progress time and throughput

Rather than teaching only one operation, like 'git fetch', how to write
down throughput to traces, we can learn about a wide range of user
operations that may seem slow by adding tooling to the progress library
itself. Operations which display progress are likely to be slow-running
and the kind of thing we want to monitor for performance anyways. By
showing object counts and data transfer size, we should be able to
make some derived measurements to ensure operations are scaling the way
we expect.

Signed-off-by: Emily Shaffer <emilyshaffer@google.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
This commit is contained in:
Emily Shaffer 2020-05-12 14:44:20 -07:00 committed by Junio C Hamano
parent b994622632
commit 98a1364740
2 changed files with 43 additions and 0 deletions

View File

@ -265,6 +265,7 @@ static struct progress *start_progress_delay(const char *title, uint64_t total,
progress->title_len = utf8_strwidth(title); progress->title_len = utf8_strwidth(title);
progress->split = 0; progress->split = 0;
set_progress_signal(); set_progress_signal();
trace2_region_enter("progress", title, the_repository);
return progress; return progress;
} }
@ -320,6 +321,22 @@ void stop_progress(struct progress **p_progress)
{ {
finish_if_sparse(*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")); stop_progress_msg(p_progress, _("done"));
} }

View File

@ -283,4 +283,30 @@ test_expect_success 'cover up after throughput shortens a lot' '
test_i18ncmp expect out 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 test_done