Skip to content

Commit

Permalink
trace2: add absolute elapsed time to start event
Browse files Browse the repository at this point in the history 
Add elapsed process time to "start" event to measure
the performance of early process startup.

Signed-off-by: Jeff Hostetler <[email protected]>
Signed-off-by: Junio C Hamano <[email protected]>
  • Loading branch information
@jeffhostetler @gitster
jeffhostetler authored and gitster committed Apr 16, 2019
1 parent a089724 commit 39f4317
Show file tree
Hide file tree
Showing 7 changed files with 30 additions and 17 deletions.
11 changes: 6 additions & 5 deletions Documentation/technical/api-trace2.txt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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}
Expand Down Expand Up @@ -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"]
}
------------
Expand Down Expand Up @@ -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)
...
Expand Down Expand Up @@ -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)
...
Expand Down Expand Up @@ -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
Expand Down
12 changes: 6 additions & 6 deletions t/t0211-trace2-perf.sh
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down
8 changes: 7 additions & 1 deletion trace2.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
1 change: 1 addition & 0 deletions trace2/tr2_tgt.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
5 changes: 4 additions & 1 deletion trace2/tr2_tgt_event.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
3 changes: 2 additions & 1 deletion trace2/tr2_tgt_normal.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down
7 changes: 4 additions & 3 deletions trace2/tr2_tgt_perf.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

Expand Down

0 comments on commit 39f4317

Please sign in to comment.