git@vger.kernel.org list mirror (unofficial, one of many)
 help / color / Atom feed
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 v2 2/7] trace2: add absolute elapsed time to start event
Date: Fri, 29 Mar 2019 10:04:26 -0700 (PDT)
Message-ID: <c15f783c26ea426688b488c2522dd9c9072cc1bf.1553879063.git.gitgitgadget@gmail.com> (raw)
In-Reply-To: <pull.169.v2.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


  parent reply index

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   ` Jeff Hostetler via GitGitGadget [this message]
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 6/7] trace2: clarify UTC datetime formatting Jeff Hostetler via GitGitGadget
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-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 09/10] trace2: make SIDs more unique 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-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         ` [PATCH v5 03/11] trace2: add absolute elapsed time to start event Jeff Hostetler via GitGitGadget
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 08/11] trace2: clarify UTC datetime formatting 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 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 publically 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=c15f783c26ea426688b488c2522dd9c9072cc1bf.1553879063.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)

Archives are clonable:
	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

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.org/gmane.comp.version-control.git

 note: .onion URLs require Tor: https://www.torproject.org/

AGPL code for this site: git clone https://public-inbox.org/ public-inbox