git/list[1] front-page[2] threads[3] people[4] search[5] about
 

[PATCH 6/9] trace2: add timer events to perf and event target formats

From
JGJeff Hostetler via GitGitGadget <gitgitgadget@gmail.com>
Date
Dec 20, 2021, 15:01 UTC
Message-ID
<c5d5ff05e6ca5729993133ce0b6b94af2503808a.1640012469.git.gitgitgadget@gmail.com>
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
Previous: Jeff Hostetler via GitGitGadgetNext: Ævar Arnfjörð Bjarmason
Message 22 of 55 in “Trace2 stopwatch timers and global counters”
  1. 0/9 Trace2 stopwatch timers and global countersJeff Hostetler via GitGitGadget, Dec 20, 2021
  2. 1/9 trace2: use size_t alloc,nr_open_regions in tr2tls_thread_ctxJeff Hostetler via GitGitGadget, Dec 20, 2021
  3. 2/9 trace2: convert tr2tls_thread_ctx.thread_name from strbuf to char*Jeff Hostetler via GitGitGadget, Dec 20, 2021
  4. Ævar Arnfjörð BjarmasonDec 20, 2021
  5. Jeff HostetlerDec 20, 2021
  6. Ævar Arnfjörð BjarmasonDec 20, 2021
  7. Jeff HostetlerDec 22, 2021
  8. Junio C HamanoDec 21, 2021
  9. Junio C HamanoDec 21, 2021
  10. Jeff HostetlerDec 22, 2021
  11. Junio C HamanoDec 22, 2021
  12. 3/9 trace2: defer free of TLS CTX until program exit.Jeff Hostetler via GitGitGadget, Dec 20, 2021
  13. Junio C HamanoDec 21, 2021
  14. Jeff HostetlerDec 22, 2021
  15. Junio C HamanoDec 22, 2021
  16. Jeff HostetlerDec 22, 2021
  17. Johannes SixtDec 23, 2021
  18. Junio C HamanoDec 23, 2021
  19. Jeff HostetlerDec 27, 2021
  20. 4/9 trace2: add thread-name override to event targetJeff Hostetler via GitGitGadget, Dec 20, 2021
  21. 5/9 trace2: add thread-name override to perf targetJeff Hostetler via GitGitGadget, Dec 20, 2021
  22. 6/9 trace2: add timer events to perf and event target formatsJeff Hostetler via GitGitGadget, Dec 20, 2021
  23. Ævar Arnfjörð BjarmasonDec 20, 2021
  24. Jeff HostetlerDec 20, 2021
  25. Derrick StoleeDec 21, 2021
  26. 8/9 trace2: add counter events to perf and event target formatsJeff Hostetler via GitGitGadget, Dec 20, 2021
  27. Ævar Arnfjörð BjarmasonDec 20, 2021
  28. Jeff HostetlerDec 22, 2021
  29. 7/9 trace2: add stopwatch timersJeff Hostetler via GitGitGadget, Dec 20, 2021
  30. Ævar Arnfjörð BjarmasonDec 20, 2021
  31. Jeff HostetlerDec 22, 2021
  32. Derrick StoleeDec 21, 2021
  33. Jeff HostetlerDec 22, 2021
  34. 9/9 trace2: add global countersJeff Hostetler via GitGitGadget, Dec 20, 2021
  35. Ævar Arnfjörð BjarmasonDec 20, 2021
  36. Jeff HostetlerDec 22, 2021
  37. Derrick StoleeDec 21, 2021
  38. Matheus TavaresDec 21, 2021
  39. 0/9 Trace2 stopwatch timers and global countersJeff Hostetler via GitGitGadget, Dec 28, 2021
  40. 1/9 trace2: use size_t alloc,nr_open_regions in tr2tls_thread_ctxJeff Hostetler via GitGitGadget, Dec 28, 2021
  41. Ævar Arnfjörð BjarmasonDec 29, 2021
  42. 2/9 trace2: convert tr2tls_thread_ctx.thread_name from strbuf to flex arrayJeff Hostetler via GitGitGadget, Dec 28, 2021
  43. Ævar Arnfjörð BjarmasonDec 29, 2021
  44. Jeff HostetlerDec 29, 2021
  45. 3/9 trace2: defer free of thread local storage until program exit.Jeff Hostetler via GitGitGadget, Dec 28, 2021
  46. 4/9 trace2: add thread-name override to event targetJeff Hostetler via GitGitGadget, Dec 28, 2021
  47. 7/9 trace2: add stopwatch timersJeff Hostetler via GitGitGadget, Dec 28, 2021
  48. 5/9 trace2: add thread-name override to perf targetJeff Hostetler via GitGitGadget, Dec 28, 2021
  49. Ævar Arnfjörð BjarmasonDec 29, 2021
  50. Jeff HostetlerDec 29, 2021
  51. 6/9 trace2: add timer events to perf and event target formatsJeff Hostetler via GitGitGadget, Dec 28, 2021
  52. 8/9 trace2: add counter events to perf and event target formatsJeff Hostetler via GitGitGadget, Dec 28, 2021
  53. 9/9 trace2: add global countersJeff Hostetler via GitGitGadget, Dec 28, 2021
  54. Ævar Arnfjörð BjarmasonDec 29, 2021
  55. Jeff HostetlerDec 30, 2021

Read the whole thread, see it on lore, or plain text.

$ cat FOOTERMessages come from the public archive at lore.kernel.org/git, fetched every hour. The front page is chosen and written each morning by an AI editor and can be wrong; the threads themselves are the record. About and API. For agents: an MCP server at https://gitlist.dev/mcp, and any thread, story or person page as Markdown by adding .md to its URL (or sending Accept: text/markdown). Details in /llms.txt.