git.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: "Jeff Hostetler via GitGitGadget" <gitgitgadget@gmail.com>
To: git@vger.kernel.org
Cc: Jeff Hostetler <jeffhost@microsoft.com>,
	Jeff Hostetler <jeffhost@microsoft.com>
Subject: [PATCH 6/9] trace2: add timer events to perf and event target formats
Date: Mon, 20 Dec 2021 15:01:06 +0000	[thread overview]
Message-ID: <c5d5ff05e6ca5729993133ce0b6b94af2503808a.1640012469.git.gitgitgadget@gmail.com> (raw)
In-Reply-To: <pull.1099.git.1640012469.gitgitgadget@gmail.com>

From: Jeff Hostetler <jeffhost@microsoft.com>

Teach Trace2 "perf" and "event" formats to handle "timer" events for
stopwatch timers.  Update API documentation accordingly.

In a future commit, stopwatch timers will be added to the Trace2 API
and it will emit these "timer" events.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 Documentation/technical/api-trace2.txt | 25 +++++++++++++++-
 trace2/tr2_tgt.h                       | 25 ++++++++++++++++
 trace2/tr2_tgt_event.c                 | 40 +++++++++++++++++++++++++-
 trace2/tr2_tgt_normal.c                |  1 +
 trace2/tr2_tgt_perf.c                  | 29 +++++++++++++++++++
 5 files changed, 118 insertions(+), 2 deletions(-)

diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt
index bb13ca3db8b..e6ed94ba814 100644
--- a/Documentation/technical/api-trace2.txt
+++ b/Documentation/technical/api-trace2.txt
@@ -391,7 +391,7 @@ only present on the "start" and "atexit" events.
 {
 	"event":"version",
 	...
-	"evt":"3",		       # EVENT format version
+	"evt":"4",		       # EVENT format version
 	"exe":"2.20.1.155.g426c96fcdb" # git version
 }
 ------------
@@ -815,6 +815,29 @@ The "value" field may be an integer or a string.
 }
 ------------
 
+`"timer"`::
+	This event is generated at the end of the program and contains
+	statistics for a global stopwatch timer.
++
+------------
+{
+	"event":"timer",
+	...
+	"name":"test",      # timer name
+	"count":42,         # number of start+stop intervals
+	"t_total":1.234,    # sum of all intervals (by thread or globally)
+	"t_min":0.1,        # shortest interval
+	"t_max":0.9,        # longest interval
+}
+------------
++
+Stopwatch timer data is independently collected by each thread and then
+aggregated for the whole program, so the total time reported here
+may exceed the "atexit" elapsed time of the program.
++
+Timer events may represent an individual thread or a summation across
+the entire program.  Summation events will have a unique thread name.
+
 == Example Trace2 API Usage
 
 Here is a hypothetical usage of the Trace2 API showing the intended
diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h
index 65f94e15748..1f548eb4b93 100644
--- a/trace2/tr2_tgt.h
+++ b/trace2/tr2_tgt.h
@@ -96,6 +96,30 @@ typedef void(tr2_tgt_evt_printf_va_fl_t)(const char *file, int line,
 					 uint64_t us_elapsed_absolute,
 					 const char *fmt, va_list ap);
 
+/*
+ * Stopwatch timer event.  This function writes the previously accumlated
+ * stopwatch timer values to the event streams.  Unlike other Trace2 API
+ * events, this is decoupled from the data collection.
+ *
+ * This does not take a (file,line) pair because a timer event reports
+ * the cummulative time spend in the timer over a series of intervals
+ * -- it does not represent a single usage (like region or data events
+ * do).
+ *
+ * The thread name is optional.  If non-null it will override the
+ * value inherited from the caller's TLS CTX.  This allows data
+ * for global timers to be reported without associating it with a
+ * single thread.
+ */
+typedef void(tr2_tgt_evt_timer_t)(uint64_t us_elapsed_absolute,
+				  const char *thread_name,
+				  const char *category,
+				  const char *timer_name,
+				  uint64_t interval_count,
+				  uint64_t us_total_time,
+				  uint64_t us_min_time,
+				  uint64_t us_max_time);
+
 /*
  * "vtable" for a TRACE2 target.  Use NULL if a target does not want
  * to emit that message.
@@ -132,6 +156,7 @@ struct tr2_tgt {
 	tr2_tgt_evt_data_fl_t                   *pfn_data_fl;
 	tr2_tgt_evt_data_json_fl_t              *pfn_data_json_fl;
 	tr2_tgt_evt_printf_va_fl_t              *pfn_printf_va_fl;
+	tr2_tgt_evt_timer_t                     *pfn_timer;
 };
 /* clang-format on */
 
diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
index 4ce50944298..9b3905b920c 100644
--- a/trace2/tr2_tgt_event.c
+++ b/trace2/tr2_tgt_event.c
@@ -19,8 +19,13 @@ static struct tr2_dst tr2dst_event = { TR2_SYSENV_EVENT, 0, 0, 0, 0 };
  * interpretation of existing events or fields. Smaller changes, such as adding
  * a new field to an existing event, do not require an increment to the EVENT
  * format version.
+ *
+ * Verison 1: original version
+ * Version 2: added "too_many_files" event
+ * Version 3: added "child_ready" event
+ * Version 4: added "timer" event
  */
-#define TR2_EVENT_VERSION "3"
+#define TR2_EVENT_VERSION "4"
 
 /*
  * Region nesting limit for messages written to the event target.
@@ -615,6 +620,38 @@ static void fn_data_json_fl(const char *file, int line,
 	}
 }
 
+static void fn_timer(uint64_t us_elapsed_absolute,
+		     const char *thread_name,
+		     const char *category,
+		     const char *timer_name,
+		     uint64_t interval_count,
+		     uint64_t us_total_time,
+		     uint64_t us_min_time,
+		     uint64_t us_max_time)
+{
+	const char *event_name = "timer";
+	struct json_writer jw = JSON_WRITER_INIT;
+	double t_abs = (double)us_elapsed_absolute / 1000000.0;
+
+	double t_total = (double)us_total_time / 1000000.0;
+	double t_min   = (double)us_min_time   / 1000000.0;
+	double t_max   = (double)us_max_time   / 1000000.0;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw, thread_name);
+	jw_object_double(&jw, "t_abs", 6, t_abs);
+	jw_object_string(&jw, "name", timer_name);
+	jw_object_intmax(&jw, "count", interval_count);
+	jw_object_double(&jw, "t_total", 6, t_total);
+	jw_object_double(&jw, "t_min", 6, t_min);
+	jw_object_double(&jw, "t_max", 6, t_max);
+
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
 struct tr2_tgt tr2_tgt_event = {
 	&tr2dst_event,
 
@@ -646,4 +683,5 @@ struct tr2_tgt tr2_tgt_event = {
 	fn_data_fl,
 	fn_data_json_fl,
 	NULL, /* printf */
+	fn_timer,
 };
diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c
index 58d9e430f05..23a7e78dcaa 100644
--- a/trace2/tr2_tgt_normal.c
+++ b/trace2/tr2_tgt_normal.c
@@ -355,4 +355,5 @@ struct tr2_tgt tr2_tgt_normal = {
 	NULL, /* data */
 	NULL, /* data_json */
 	fn_printf_va_fl,
+	NULL, /* timer */
 };
diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
index 47293e99d4b..7597cb52ed5 100644
--- a/trace2/tr2_tgt_perf.c
+++ b/trace2/tr2_tgt_perf.c
@@ -554,6 +554,34 @@ static void fn_printf_va_fl(const char *file, int line,
 	strbuf_release(&buf_payload);
 }
 
+static void fn_timer(uint64_t us_elapsed_absolute,
+		     const char *thread_name,
+		     const char *category,
+		     const char *timer_name,
+		     uint64_t interval_count,
+		     uint64_t us_total_time,
+		     uint64_t us_min_time,
+		     uint64_t us_max_time)
+{
+	const char *event_name = "timer";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	double t_total = (double)us_total_time / 1000000.0;
+	double t_min   = (double)us_min_time   / 1000000.0;
+	double t_max   = (double)us_max_time   / 1000000.0;
+
+	strbuf_addf(&buf_payload, "name:%s", timer_name);
+	strbuf_addf(&buf_payload, " count:%"PRIu64, interval_count);
+	strbuf_addf(&buf_payload, " total:%9.6f", t_total);
+	strbuf_addf(&buf_payload, " min:%9.6f", t_min);
+	strbuf_addf(&buf_payload, " max:%9.6f", t_max);
+
+	perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
+			 &us_elapsed_absolute, NULL,
+			 category, &buf_payload, thread_name);
+	strbuf_release(&buf_payload);
+}
+
 struct tr2_tgt tr2_tgt_perf = {
 	&tr2dst_perf,
 
@@ -585,4 +613,5 @@ struct tr2_tgt tr2_tgt_perf = {
 	fn_data_fl,
 	fn_data_json_fl,
 	fn_printf_va_fl,
+	fn_timer,
 };
-- 
gitgitgadget


  parent reply	other threads:[~2021-12-20 15:21 UTC|newest]

Thread overview: 55+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2021-12-20 15:01 [PATCH 0/9] Trace2 stopwatch timers and global counters Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` [PATCH 1/9] trace2: use size_t alloc,nr_open_regions in tr2tls_thread_ctx Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` [PATCH 2/9] trace2: convert tr2tls_thread_ctx.thread_name from strbuf to char* Jeff Hostetler via GitGitGadget
2021-12-20 16:31   ` Ævar Arnfjörð Bjarmason
2021-12-20 19:07     ` Jeff Hostetler
2021-12-20 19:35       ` Ævar Arnfjörð Bjarmason
2021-12-22 16:32         ` Jeff Hostetler
2021-12-21  7:33     ` Junio C Hamano
2021-12-21  7:22   ` Junio C Hamano
2021-12-22 16:28     ` Jeff Hostetler
2021-12-22 19:57       ` Junio C Hamano
2021-12-20 15:01 ` [PATCH 3/9] trace2: defer free of TLS CTX until program exit Jeff Hostetler via GitGitGadget
2021-12-21  7:30   ` Junio C Hamano
2021-12-22 21:59     ` Jeff Hostetler
2021-12-22 22:56       ` Junio C Hamano
2021-12-22 23:04         ` Jeff Hostetler
2021-12-23  7:38         ` Johannes Sixt
2021-12-23 18:18           ` Junio C Hamano
2021-12-27 18:51             ` Jeff Hostetler
2021-12-20 15:01 ` [PATCH 4/9] trace2: add thread-name override to event target Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` [PATCH 5/9] trace2: add thread-name override to perf target Jeff Hostetler via GitGitGadget
2021-12-20 15:01 ` Jeff Hostetler via GitGitGadget [this message]
2021-12-20 16:39   ` [PATCH 6/9] trace2: add timer events to perf and event target formats Ævar Arnfjörð Bjarmason
2021-12-20 19:44     ` Jeff Hostetler
2021-12-21 14:20   ` Derrick Stolee
2021-12-20 15:01 ` [PATCH 7/9] trace2: add stopwatch timers Jeff Hostetler via GitGitGadget
2021-12-20 16:42   ` Ævar Arnfjörð Bjarmason
2021-12-22 21:38     ` Jeff Hostetler
2021-12-21 14:45   ` Derrick Stolee
2021-12-22 21:57     ` Jeff Hostetler
2021-12-20 15:01 ` [PATCH 8/9] trace2: add counter events to perf and event target formats Jeff Hostetler via GitGitGadget
2021-12-20 16:51   ` Ævar Arnfjörð Bjarmason
2021-12-22 22:56     ` Jeff Hostetler
2021-12-20 15:01 ` [PATCH 9/9] trace2: add global counters Jeff Hostetler via GitGitGadget
2021-12-20 17:14   ` Ævar Arnfjörð Bjarmason
2021-12-22 22:18     ` Jeff Hostetler
2021-12-21 14:51 ` [PATCH 0/9] Trace2 stopwatch timers and " Derrick Stolee
2021-12-21 23:27   ` Matheus Tavares
2021-12-28 19:36 ` [PATCH v2 " Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 1/9] trace2: use size_t alloc,nr_open_regions in tr2tls_thread_ctx Jeff Hostetler via GitGitGadget
2021-12-29  0:48     ` Ævar Arnfjörð Bjarmason
2021-12-28 19:36   ` [PATCH v2 2/9] trace2: convert tr2tls_thread_ctx.thread_name from strbuf to flex array Jeff Hostetler via GitGitGadget
2021-12-29  1:11     ` Ævar Arnfjörð Bjarmason
2021-12-29 16:46       ` Jeff Hostetler
2021-12-28 19:36   ` [PATCH v2 3/9] trace2: defer free of thread local storage until program exit Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 4/9] trace2: add thread-name override to event target Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 5/9] trace2: add thread-name override to perf target Jeff Hostetler via GitGitGadget
2021-12-29  1:48     ` Ævar Arnfjörð Bjarmason
2021-12-29 17:15       ` Jeff Hostetler
2021-12-28 19:36   ` [PATCH v2 6/9] trace2: add timer events to perf and event target formats Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 7/9] trace2: add stopwatch timers Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 8/9] trace2: add counter events to perf and event target formats Jeff Hostetler via GitGitGadget
2021-12-28 19:36   ` [PATCH v2 9/9] trace2: add global counters Jeff Hostetler via GitGitGadget
2021-12-29  1:54   ` [PATCH v2 0/9] Trace2 stopwatch timers and " Ævar Arnfjörð Bjarmason
2021-12-30 16:42     ` Jeff Hostetler

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

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=c5d5ff05e6ca5729993133ce0b6b94af2503808a.1640012469.git.gitgitgadget@gmail.com \
    --to=gitgitgadget@gmail.com \
    --cc=git@vger.kernel.org \
    --cc=jeffhost@microsoft.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
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).