From: Jeff Hostetler <jeffhost@xxxxxxxxxxxxx>
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@xxxxxxxxxxxxx>
---
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
