From: "Jeff Hostetler via GitGitGadget" <gitgitgadget@gmail.com> To: git@vger.kernel.org Cc: gitster@pobox.com, peff@peff.net, jrnieder@gmail.com, steadmon@google.com, avarab@gmail.com, Junio C Hamano <gitster@pobox.com>, Jeff Hostetler <jeffhost@microsoft.com> Subject: [PATCH v5 03/11] trace2: add absolute elapsed time to start event Date: Mon, 29 Apr 2019 13:14:15 -0700 (PDT) Message-ID: <175371fb54cbf41e5cf90d8d23ec5fde30036266.1556568852.git.gitgitgadget@gmail.com> (raw) In-Reply-To: <pull.169.v5.git.gitgitgadget@gmail.com> From: Jeff Hostetler <jeffhost@microsoft.com> Add elapsed process time to "start" event to measure the performance of early process startup. Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com> --- Documentation/technical/api-trace2.txt | 11 ++++++----- t/t0211-trace2-perf.sh | 12 ++++++------ trace2.c | 8 +++++++- trace2/tr2_tgt.h | 1 + trace2/tr2_tgt_event.c | 5 ++++- trace2/tr2_tgt_normal.c | 3 ++- trace2/tr2_tgt_perf.c | 7 ++++--- 7 files changed, 30 insertions(+), 17 deletions(-) diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt index f37fccf1da..baaa1153bb 100644 --- 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 953e2f7847..c9694b29f7 100755 --- 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 6dd51e6aa5..1c180062dd 100644 --- 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 297bb8ffbe..7b90469212 100644 --- 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 107cb5317d..89a4d3ae9a 100644 --- 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 547183d5b6..57f3e18f5b 100644 --- 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 f0746fcf86..9c3b4d8a0f 100644 --- 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); } -- gitgitgadget
next prev parent reply other threads:[~2019-04-29 20:14 UTC|newest] Thread overview: 68+ messages / expand[flat|nested] mbox.gz Atom feed top 2019-03-28 13:30 [PATCH 0/4] trace2: load trace2 settings from system config Jeff Hostetler via GitGitGadget 2019-03-28 13:30 ` [PATCH 1/4] trace2: refactor setting process starting time Jeff Hostetler via GitGitGadget 2019-03-28 13:31 ` [PATCH 2/4] trace2: add absolute elapsed time to start event Jeff Hostetler via GitGitGadget 2019-03-28 13:31 ` [PATCH 3/4] trace2: find exec-dir before trace2 initialization Jeff Hostetler via GitGitGadget 2019-03-28 13:31 ` [PATCH 4/4] trace2: use system config for default trace2 settings Jeff Hostetler via GitGitGadget 2019-03-28 14:36 ` Ævar Arnfjörð Bjarmason 2019-03-28 18:50 ` Jeff Hostetler 2019-03-28 21:28 ` Josh Steadmon 2019-03-29 17:04 ` [PATCH v2 0/7] trace2: load trace2 settings from system config Jeff Hostetler via GitGitGadget 2019-03-29 17:04 ` [PATCH v2 1/7] trace2: refactor setting process starting time Jeff Hostetler via GitGitGadget 2019-03-29 17:04 ` [PATCH v2 2/7] trace2: add absolute elapsed time to start event Jeff Hostetler via GitGitGadget 2019-03-29 17:04 ` [PATCH v2 3/7] trace2: find exec-dir before trace2 initialization Jeff Hostetler via GitGitGadget 2019-03-29 17:04 ` [PATCH v2 4/7] trace2: use system config for default trace2 settings Jeff Hostetler via GitGitGadget 2019-04-01 21:00 ` Josh Steadmon 2019-04-01 21:06 ` Jeff Hostetler 2019-04-03 0:01 ` Jonathan Nieder 2019-04-03 0:00 ` Jonathan Nieder 2019-04-09 15:58 ` Jeff Hostetler 2019-03-29 17:04 ` [PATCH v2 5/7] trace2: report peak memory usage of the process Jeff Hostetler via GitGitGadget 2019-03-29 22:16 ` Ævar Arnfjörð Bjarmason 2019-04-01 21:05 ` Jeff Hostetler 2019-03-29 17:04 ` [PATCH v2 7/7] trace2: make SIDs more unique Jeff Hostetler via GitGitGadget 2019-03-29 22:12 ` Ævar Arnfjörð Bjarmason 2019-04-01 21:16 ` Jeff Hostetler 2019-03-29 17:04 ` [PATCH v2 6/7] trace2: clarify UTC datetime formatting Jeff Hostetler via GitGitGadget 2019-04-01 21:02 ` [PATCH v2 0/7] trace2: load trace2 settings from system config Josh Steadmon 2019-04-11 15:18 ` [PATCH v3 00/10] " Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 01/10] config: initialize opts structure in repo_read_config() Jeff Hostetler via GitGitGadget 2019-04-12 3:52 ` Jonathan Nieder 2019-04-15 14:34 ` Johannes Schindelin 2019-04-11 15:18 ` [PATCH v3 03/10] trace2: add absolute elapsed time to start event Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 02/10] trace2: refactor setting process starting time Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 04/10] trace2: find exec-dir before trace2 initialization Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 05/10] config: add read_very_early_config() Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 06/10] trace2: use system/global config for default trace2 settings Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 07/10] trace2: report peak memory usage of the process Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 08/10] trace2: clarify UTC datetime formatting Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 10/10] trace2: update docs to describe system/global config settings Jeff Hostetler via GitGitGadget 2019-04-11 15:18 ` [PATCH v3 09/10] trace2: make SIDs more unique Jeff Hostetler via GitGitGadget 2019-04-12 2:29 ` [PATCH v3 00/10] trace2: load trace2 settings from system config Junio C Hamano 2019-04-12 13:47 ` Jeff Hostetler 2019-04-15 20:39 ` [PATCH v4 " Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 01/10] config: initialize opts structure in repo_read_config() Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 02/10] trace2: refactor setting process starting time Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 03/10] trace2: add absolute elapsed time to start event Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 04/10] trace2: find exec-dir before trace2 initialization Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 05/10] config: add read_very_early_config() Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 06/10] trace2: use system/global config for default trace2 settings Jeff Hostetler via GitGitGadget 2019-04-27 13:43 ` SZEDER Gábor 2019-04-29 19:03 ` Jeff Hostetler 2019-04-15 20:39 ` [PATCH v4 08/10] trace2: clarify UTC datetime formatting Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 07/10] trace2: report peak memory usage of the process Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 09/10] trace2: make SIDs more unique Jeff Hostetler via GitGitGadget 2019-04-15 20:39 ` [PATCH v4 10/10] trace2: update docs to describe system/global config settings Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 00/11] trace2: load trace2 settings from system config Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 01/11] config: initialize opts structure in repo_read_config() Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 02/11] trace2: refactor setting process starting time Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` Jeff Hostetler via GitGitGadget [this message] 2019-04-29 20:14 ` [PATCH v5 04/11] trace2: find exec-dir before trace2 initialization Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 05/11] config: add read_very_early_config() Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 06/11] trace2: use system/global config for default trace2 settings Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 07/11] trace2: report peak memory usage of the process Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 09/11] trace2: make SIDs more unique Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 08/11] trace2: clarify UTC datetime formatting Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 10/11] trace2: update docs to describe system/global config settings Jeff Hostetler via GitGitGadget 2019-04-29 20:14 ` [PATCH v5 11/11] trace2: fixup access problem on /etc/gitconfig in read_very_early_config Jeff Hostetler via GitGitGadget 2019-04-29 20:21 ` [PATCH v5 00/11] trace2: load trace2 settings from system config Jeff Hostetler 2019-05-07 1:18 ` Junio C Hamano
Reply instructions: You may reply publicly to this message via plain-text email using any one of the following methods: * Save the following mbox file, import it into your mail client, and reply-to-all from there: mbox Avoid top-posting and favor interleaved quoting: https://en.wikipedia.org/wiki/Posting_style#Interleaved_style List information: http://vger.kernel.org/majordomo-info.html * Reply using the --to, --cc, and --in-reply-to switches of git-send-email(1): git send-email \ --in-reply-to=175371fb54cbf41e5cf90d8d23ec5fde30036266.1556568852.git.gitgitgadget@gmail.com \ --to=gitgitgadget@gmail.com \ --cc=avarab@gmail.com \ --cc=git@vger.kernel.org \ --cc=gitster@pobox.com \ --cc=jeffhost@microsoft.com \ --cc=jrnieder@gmail.com \ --cc=peff@peff.net \ --cc=steadmon@google.com \ /path/to/YOUR_REPLY https://kernel.org/pub/software/scm/git/docs/git-send-email.html * If your mail client supports setting the In-Reply-To header via mailto: links, try the mailto: link
git@vger.kernel.org list mirror (unofficial, one of many) This inbox may be cloned and mirrored by anyone: git clone --mirror https://public-inbox.org/git git clone --mirror http://ou63pmih66umazou.onion/git git clone --mirror http://czquwvybam4bgbro.onion/git git clone --mirror http://hjrcffqmbrq6wope.onion/git # If you have public-inbox 1.1+ installed, you may # initialize and index your mirror using the following commands: public-inbox-init -V1 git git/ https://public-inbox.org/git \ git@vger.kernel.org public-inbox-index git Example config snippet for mirrors. Newsgroups are available over NNTP: nntp://news.public-inbox.org/inbox.comp.version-control.git nntp://ou63pmih66umazou.onion/inbox.comp.version-control.git nntp://czquwvybam4bgbro.onion/inbox.comp.version-control.git nntp://hjrcffqmbrq6wope.onion/inbox.comp.version-control.git nntp://news.gmane.io/gmane.comp.version-control.git note: .onion URLs require Tor: https://www.torproject.org/ code repositories for the project(s) associated with this inbox: https://80x24.org/mirrors/git.git AGPL code for this site: git clone https://public-inbox.org/public-inbox.git