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>

diff --git a/progress.c b/progress.c
index 75633e9c5e91a959e624ea38898933ea20d1daaa..6d2dcff0b6920037463f217d3d699305e8ccc491 100644 (file)
--- 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
index d2d088d9a0c31752739e1fdb118677278aabaf4f..1ed1df351cb178562d21ab204f2b5c85d3206ba2 100755 (executable)
--- 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