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>
Emily Shaffer committed
May 12, 2020 at 14:44 UTC
98a136474082cdc7228d7e0e45672c5274fab701
2 files changed
+43
progress.c
+17
@@ -265,6 +265,7 @@ static struct progress *start_progress_delay(const char *title, uint64_t total,
265
progress->title_len = utf8_strwidth(title);
266
progress->split = 0;
267
set_progress_signal();
268
+ trace2_region_enter("progress", title, the_repository);
269
return progress;
270
}
271
@@ -320,6 +321,22 @@ void stop_progress(struct progress **p_progress)
321
{
322
finish_if_sparse(*p_progress);
323
324
+ if (p_progress && *p_progress) {
325
+ trace2_data_intmax("progress", the_repository, "total_objects",
326
+ (*p_progress)->total);
327
+
328
+ if ((*p_progress)->throughput)
329
+ trace2_data_intmax("progress", the_repository,
330
+ "total_bytes",
331
+ (*p_progress)->throughput->curr_total);
332
+ }
333
+
334
+ trace2_region_leave("progress",
335
+ p_progress && *p_progress
336
+ ? (*p_progress)->title
337
+ : NULL,
338
+ the_repository);
339
+
340
stop_progress_msg(p_progress, _("done"));
341
}
342
t/t0500-progress-display.sh
+26
@@ -283,4 +283,30 @@ test_expect_success 'cover up after throughput shortens a lot' '
283
test_i18ncmp expect out
284
'
285
286
+test_expect_success 'progress generates traces' '
287
+ cat >in <<-\EOF &&
288
+ throughput 102400 1000
289
+ update
290
+ progress 10
291
+ throughput 204800 2000
292
+ update
293
+ progress 20
294
+ throughput 307200 3000
295
+ update
296
+ progress 30
297
+ throughput 409600 4000
298
+ update
299
+ progress 40
300
+ EOF
301
+
302
+ GIT_TRACE2_EVENT="$(pwd)/trace.event" test-tool progress --total=40 \
303
+ "Working hard" <in 2>stderr &&
304
+
305
+ # t0212/parse_events.perl intentionally omits regions and data.
306
+ grep -e "region_enter" -e "\"category\":\"progress\"" trace.event &&
307
+ grep -e "region_leave" -e "\"category\":\"progress\"" trace.event &&
308
+ grep "\"key\":\"total_objects\",\"value\":\"40\"" trace.event &&
309
+ grep "\"key\":\"total_bytes\",\"value\":\"409600\"" trace.event
310
+'
311
+
312
test_done