trace2: add absolute elapsed time to start event

Add elapsed process time to "start" event to measure
the performance of early process startup.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>

diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt
index f37fccf1da6db437c569625cb060244d00823b13..baaa1153bb898a7b21208448ca93e29c6c7eaf21 100644 (file)
--- a/Documentation/technical/api-trace2.txt
+++ b/Documentation/technical/api-trace2.txt
@@ -60,7 +60,7 @@ git version 2.20.1.155.g426c96fcdb
 ------------
 $ cat ~/log.perf
 12:28:42.620675 common-main.c:38                  | d0 | main                     | version      |     |           |           |            | 2.20.1.155.g426c96fcdb
-12:28:42.621001 common-main.c:39                  | d0 | main                     | start        |     |           |           |            | git version
+12:28:42.621001 common-main.c:39                  | d0 | main                     | start        |     |  0.001173 |           |            | git version
 12:28:42.621111 git.c:432                         | d0 | main                     | cmd_name     |     |           |           |            | version (version)
 12:28:42.621225 git.c:662                         | d0 | main                     | exit         |     |  0.001227 |           |            | code:0
 12:28:42.621259 trace2/tr2_tgt_perf.c:211         | d0 | main                     | atexit       |     |  0.001265 |           |            | code:0
@@ -79,7 +79,7 @@ git version 2.20.1.155.g426c96fcdb
 ------------
 $ cat ~/log.event
 {"event":"version","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.620713","file":"common-main.c","line":38,"evt":"1","exe":"2.20.1.155.g426c96fcdb"}
-{"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"argv":["git","version"]}
+{"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"t_abs":0.001173,"argv":["git","version"]}
 {"event":"cmd_name","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621122","file":"git.c","line":432,"name":"version","hierarchy":"version"}
 {"event":"exit","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621236","file":"git.c","line":662,"t_abs":0.001227,"code":0}
 {"event":"atexit","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621268","file":"trace2/tr2_tgt_event.c","line":163,"t_abs":0.001265,"code":0}
@@ -601,6 +601,7 @@ from all events and the `time` field is only present on the "start" and
 {
        "event":"start",
        ...
+       "t_abs":0.001227, # elapsed time in seconds
        "argv":["git","version"]
 }
 ------------
@@ -1118,7 +1119,7 @@ $ git status
 
 $ cat ~/log.perf
 d0 | main                     | version      |     |           |           |            | 2.20.1.160.g5676107ecd.dirty
-d0 | main                     | start        |     |           |           |            | git status
+d0 | main                     | start        |     |  0.001173 |           |            | git status
 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
 d0 | main                     | cmd_name     |     |           |           |            | status (status)
 ...
@@ -1163,7 +1164,7 @@ $ git status
 ...
 $ cat ~/log.perf
 d0 | main                     | version      |     |           |           |            | 2.20.1.162.gb4ccea44db.dirty
-d0 | main                     | start        |     |           |           |            | git status
+d0 | main                     | start        |     |  0.001173 |           |            | git status
 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
 d0 | main                     | cmd_name     |     |           |           |            | status (status)
 ...
@@ -1219,7 +1220,7 @@ $ git status
 ...
 $ cat ~/log.perf
 d0 | main                     | version      |     |           |           |            | 2.20.1.156.gf9916ae094.dirty
-d0 | main                     | start        |     |           |           |            | git status
+d0 | main                     | start        |     |  0.001173 |           |            | git status
 d0 | main                     | def_repo     | r1  |           |           |            | worktree:/Users/jeffhost/work/gfw
 d0 | main                     | cmd_name     |     |           |           |            | status (status)
 d0 | main                     | region_enter | r1  |  0.001791 |           | index      | label:do_read_index .git/index

diff --git a/t/t0211-trace2-perf.sh b/t/t0211-trace2-perf.sh
index 953e2f78471f647312c4b53920a4d71f24f9c4d5..c9694b29f7be36bfdc58068be97b159c5d11079a 100755 (executable)
--- a/t/t0211-trace2-perf.sh
+++ b/t/t0211-trace2-perf.sh
@@ -50,7 +50,7 @@ test_expect_success 'perf stream, return code 0' '
        perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
        cat >expect <<-EOF &&
                d0|main|version|||||$V
-               d0|main|start|||||_EXE_ trace2 001return 0
+               d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0
                d0|main|cmd_name|||||trace2 (trace2)
                d0|main|exit||_T_ABS_|||code:0
                d0|main|atexit||_T_ABS_|||code:0
@@ -64,7 +64,7 @@ test_expect_success 'perf stream, return code 1' '
        perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
        cat >expect <<-EOF &&
                d0|main|version|||||$V
-               d0|main|start|||||_EXE_ trace2 001return 1
+               d0|main|start||_T_ABS_|||_EXE_ trace2 001return 1
                d0|main|cmd_name|||||trace2 (trace2)
                d0|main|exit||_T_ABS_|||code:1
                d0|main|atexit||_T_ABS_|||code:1
@@ -82,7 +82,7 @@ test_expect_success 'perf stream, error event' '
        perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
        cat >expect <<-EOF &&
                d0|main|version|||||$V
-               d0|main|start|||||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
+               d0|main|start||_T_ABS_|||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
                d0|main|cmd_name|||||trace2 (trace2)
                d0|main|error|||||hello world
                d0|main|error|||||this is a test
@@ -128,15 +128,15 @@ test_expect_success 'perf stream, child processes' '
        perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
        cat >expect <<-EOF &&
                d0|main|version|||||$V
-               d0|main|start|||||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
+               d0|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
                d0|main|cmd_name|||||trace2 (trace2)
                d0|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 004child test-tool trace2 001return 0
                d1|main|version|||||$V
-               d1|main|start|||||_EXE_ trace2 004child test-tool trace2 001return 0
+               d1|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 001return 0
                d1|main|cmd_name|||||trace2 (trace2/trace2)
                d1|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 001return 0
                d2|main|version|||||$V
-               d2|main|start|||||_EXE_ trace2 001return 0
+               d2|main|start||_T_ABS_|||_EXE_ trace2 001return 0
                d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
                d2|main|exit||_T_ABS_|||code:0
                d2|main|atexit||_T_ABS_|||code:0

diff --git a/trace2.c b/trace2.c
index 6dd51e6aa502b3f822d5eeffb340362a76ee18f4..1c180062dd2fd92470e95f74bc2eaf740847b00c 100644 (file)
--- a/trace2.c
+++ b/trace2.c
@@ -182,13 +182,19 @@ void trace2_cmd_start_fl(const char *file, int line, const char **argv)
 {
        struct tr2_tgt *tgt_j;
        int j;
+       uint64_t us_now;
+       uint64_t us_elapsed_absolute;
 
        if (!trace2_enabled)
                return;
 
+       us_now = getnanotime() / 1000;
+       us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
+
        for_each_wanted_builtin (j, tgt_j)
                if (tgt_j->pfn_start_fl)
-                       tgt_j->pfn_start_fl(file, line, argv);
+                       tgt_j->pfn_start_fl(file, line, us_elapsed_absolute,
+                                           argv);
 }
 
 int trace2_cmd_exit_fl(const char *file, int line, int code)

diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h
index 297bb8ffbe498358b41e697c892c259871a6a937..7b904692123e28074458fce0c0afe06922caa607 100644 (file)
--- a/trace2/tr2_tgt.h
+++ b/trace2/tr2_tgt.h
@@ -15,6 +15,7 @@ typedef void(tr2_tgt_term_t)(void);
 typedef void(tr2_tgt_evt_version_fl_t)(const char *file, int line);
 
 typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line,
+                                    uint64_t us_elapsed_absolute,
                                     const char **argv);
 typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line,
                                    uint64_t us_elapsed_absolute, int code);

diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
index 107cb5317d2270ccf8b54727fb55f4526a503c24..89a4d3ae9a56e909d254f1f8df4b577a34c65deb 100644 (file)
--- a/trace2/tr2_tgt_event.c
+++ b/trace2/tr2_tgt_event.c
@@ -122,13 +122,16 @@ static void fn_version_fl(const char *file, int line)
        jw_release(&jw);
 }
 
-static void fn_start_fl(const char *file, int line, const char **argv)
+static void fn_start_fl(const char *file, int line,
+                       uint64_t us_elapsed_absolute, const char **argv)
 {
        const char *event_name = "start";
        struct json_writer jw = JSON_WRITER_INIT;
+       double t_abs = (double)us_elapsed_absolute / 1000000.0;
 
        jw_object_begin(&jw, 0);
        event_fmt_prepare(event_name, file, line, NULL, &jw);
+       jw_object_double(&jw, "t_abs", 6, t_abs);
        jw_object_inline_begin_array(&jw, "argv");
        jw_array_argv(&jw, argv);
        jw_end(&jw);

diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c
index 547183d5b64169acfc1e8f9b1f62501de36240ef..57f3e18f5bcc1424da5dfb3aa83ae07994e5b4da 100644 (file)
--- a/trace2/tr2_tgt_normal.c
+++ b/trace2/tr2_tgt_normal.c
@@ -81,7 +81,8 @@ static void fn_version_fl(const char *file, int line)
        strbuf_release(&buf_payload);
 }
 
-static void fn_start_fl(const char *file, int line, const char **argv)
+static void fn_start_fl(const char *file, int line,
+                       uint64_t us_elapsed_absolute, const char **argv)
 {
        struct strbuf buf_payload = STRBUF_INIT;
 

diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
index f0746fcf868ccab0408333bb954e7d531843af7d..9c3b4d8a0f4b813982a3c23d57e04a8984a24641 100644 (file)
--- a/trace2/tr2_tgt_perf.c
+++ b/trace2/tr2_tgt_perf.c
@@ -159,15 +159,16 @@ static void fn_version_fl(const char *file, int line)
        strbuf_release(&buf_payload);
 }
 
-static void fn_start_fl(const char *file, int line, const char **argv)
+static void fn_start_fl(const char *file, int line,
+                       uint64_t us_elapsed_absolute, const char **argv)
 {
        const char *event_name = "start";
        struct strbuf buf_payload = STRBUF_INIT;
 
        sq_quote_argv_pretty(&buf_payload, argv);
 
-       perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
-                        &buf_payload);
+       perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+                        NULL, NULL, &buf_payload);
        strbuf_release(&buf_payload);
 }