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>
Jeff Hostetler committed
Apr 15, 2019 at 13:39 UTC
39f43177442d44d8a945c3ff6a8c08f481539763
7 files changed
+30
-17
Documentation/technical/api-trace2.txt
+6
-5
@@ -60,7 +60,7 @@ git version 2.20.1.155.g426c96fcdb
60
------------
61
$ cat ~/log.perf
62
12:28:42.620675 common-main.c:38 | d0 | main | version | | | | | 2.20.1.155.g426c96fcdb
63
-12:28:42.621001 common-main.c:39 | d0 | main | start | | | | | git version
63
+12:28:42.621001 common-main.c:39 | d0 | main | start | | 0.001173 | | | git version
64
12:28:42.621111 git.c:432 | d0 | main | cmd_name | | | | | version (version)
65
12:28:42.621225 git.c:662 | d0 | main | exit | | 0.001227 | | | code:0
66
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
79
------------
80
$ cat ~/log.event
81
{"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"}
82
-{"event":"start","sid":"1547659722619736-11614","thread":"main","time":"2019-01-16 17:28:42.621027","file":"common-main.c","line":39,"argv":["git","version"]}
82
+{"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"]}
83
{"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"}
84
{"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}
85
{"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
601
{
602
"event":"start",
603
...
604
+ "t_abs":0.001227, # elapsed time in seconds
605
"argv":["git","version"]
606
}
607
------------
@@ -1118,7 +1119,7 @@ $ git status
1119
1120
$ cat ~/log.perf
1121
d0 | main | version | | | | | 2.20.1.160.g5676107ecd.dirty
1121
-d0 | main | start | | | | | git status
1122
+d0 | main | start | | 0.001173 | | | git status
1123
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1124
d0 | main | cmd_name | | | | | status (status)
1125
...
@@ -1163,7 +1164,7 @@ $ git status
1164
...
1165
$ cat ~/log.perf
1166
d0 | main | version | | | | | 2.20.1.162.gb4ccea44db.dirty
1166
-d0 | main | start | | | | | git status
1167
+d0 | main | start | | 0.001173 | | | git status
1168
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1169
d0 | main | cmd_name | | | | | status (status)
1170
...
@@ -1219,7 +1220,7 @@ $ git status
1220
...
1221
$ cat ~/log.perf
1222
d0 | main | version | | | | | 2.20.1.156.gf9916ae094.dirty
1222
-d0 | main | start | | | | | git status
1223
+d0 | main | start | | 0.001173 | | | git status
1224
d0 | main | def_repo | r1 | | | | worktree:/Users/jeffhost/work/gfw
1225
d0 | main | cmd_name | | | | | status (status)
1226
d0 | main | region_enter | r1 | 0.001791 | | index | label:do_read_index .git/index
t/t0211-trace2-perf.sh
+6
-6
@@ -50,7 +50,7 @@ test_expect_success 'perf stream, return code 0' '
50
perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
51
cat >expect <<-EOF &&
52
d0|main|version|||||$V
53
- d0|main|start|||||_EXE_ trace2 001return 0
53
+ d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0
54
d0|main|cmd_name|||||trace2 (trace2)
55
d0|main|exit||_T_ABS_|||code:0
56
d0|main|atexit||_T_ABS_|||code:0
@@ -64,7 +64,7 @@ test_expect_success 'perf stream, return code 1' '
64
perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
65
cat >expect <<-EOF &&
66
d0|main|version|||||$V
67
- d0|main|start|||||_EXE_ trace2 001return 1
67
+ d0|main|start||_T_ABS_|||_EXE_ trace2 001return 1
68
d0|main|cmd_name|||||trace2 (trace2)
69
d0|main|exit||_T_ABS_|||code:1
70
d0|main|atexit||_T_ABS_|||code:1
@@ -82,7 +82,7 @@ test_expect_success 'perf stream, error event' '
82
perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
83
cat >expect <<-EOF &&
84
d0|main|version|||||$V
85
- d0|main|start|||||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
85
+ d0|main|start||_T_ABS_|||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
86
d0|main|cmd_name|||||trace2 (trace2)
87
d0|main|error|||||hello world
88
d0|main|error|||||this is a test
@@ -128,15 +128,15 @@ test_expect_success 'perf stream, child processes' '
128
perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
129
cat >expect <<-EOF &&
130
d0|main|version|||||$V
131
- d0|main|start|||||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
131
+ d0|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
132
d0|main|cmd_name|||||trace2 (trace2)
133
d0|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 004child test-tool trace2 001return 0
134
d1|main|version|||||$V
135
- d1|main|start|||||_EXE_ trace2 004child test-tool trace2 001return 0
135
+ d1|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 001return 0
136
d1|main|cmd_name|||||trace2 (trace2/trace2)
137
d1|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 001return 0
138
d2|main|version|||||$V
139
- d2|main|start|||||_EXE_ trace2 001return 0
139
+ d2|main|start||_T_ABS_|||_EXE_ trace2 001return 0
140
d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
141
d2|main|exit||_T_ABS_|||code:0
142
d2|main|atexit||_T_ABS_|||code:0
trace2.c
+7
-1
@@ -182,13 +182,19 @@ void trace2_cmd_start_fl(const char *file, int line, const char **argv)
182
{
183
struct tr2_tgt *tgt_j;
184
int j;
185
+ uint64_t us_now;
186
+ uint64_t us_elapsed_absolute;
187
188
if (!trace2_enabled)
189
return;
190
191
+ us_now = getnanotime() / 1000;
192
+ us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
193
+
194
for_each_wanted_builtin (j, tgt_j)
195
if (tgt_j->pfn_start_fl)
191
- tgt_j->pfn_start_fl(file, line, argv);
196
+ tgt_j->pfn_start_fl(file, line, us_elapsed_absolute,
197
+ argv);
198
}
199
200
int trace2_cmd_exit_fl(const char *file, int line, int code)
trace2/tr2_tgt.h
+1
@@ -15,6 +15,7 @@ typedef void(tr2_tgt_term_t)(void);
15
typedef void(tr2_tgt_evt_version_fl_t)(const char *file, int line);
16
17
typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line,
18
+ uint64_t us_elapsed_absolute,
19
const char **argv);
20
typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line,
21
uint64_t us_elapsed_absolute, int code);
trace2/tr2_tgt_event.c
+4
-1
@@ -122,13 +122,16 @@ static void fn_version_fl(const char *file, int line)
122
jw_release(&jw);
123
}
124
125
-static void fn_start_fl(const char *file, int line, const char **argv)
125
+static void fn_start_fl(const char *file, int line,
126
+ uint64_t us_elapsed_absolute, const char **argv)
127
{
128
const char *event_name = "start";
129
struct json_writer jw = JSON_WRITER_INIT;
130
+ double t_abs = (double)us_elapsed_absolute / 1000000.0;
131
132
jw_object_begin(&jw, 0);
133
event_fmt_prepare(event_name, file, line, NULL, &jw);
134
+ jw_object_double(&jw, "t_abs", 6, t_abs);
135
jw_object_inline_begin_array(&jw, "argv");
136
jw_array_argv(&jw, argv);
137
jw_end(&jw);
trace2/tr2_tgt_normal.c
+2
-1
@@ -81,7 +81,8 @@ static void fn_version_fl(const char *file, int line)
81
strbuf_release(&buf_payload);
82
}
83
84
-static void fn_start_fl(const char *file, int line, const char **argv)
84
+static void fn_start_fl(const char *file, int line,
85
+ uint64_t us_elapsed_absolute, const char **argv)
86
{
87
struct strbuf buf_payload = STRBUF_INIT;
88
trace2/tr2_tgt_perf.c
+4
-3
@@ -159,15 +159,16 @@ static void fn_version_fl(const char *file, int line)
159
strbuf_release(&buf_payload);
160
}
161
162
-static void fn_start_fl(const char *file, int line, const char **argv)
162
+static void fn_start_fl(const char *file, int line,
163
+ uint64_t us_elapsed_absolute, const char **argv)
164
{
165
const char *event_name = "start";
166
struct strbuf buf_payload = STRBUF_INIT;
167
168
sq_quote_argv_pretty(&buf_payload, argv);
169
169
- perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
170
- &buf_payload);
170
+ perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
171
+ NULL, NULL, &buf_payload);
172
strbuf_release(&buf_payload);
173
}
174