| Message ID | c5d5ff05e6ca5729993133ce0b6b94af2503808a.1640012469.git.gitgitgadget@gmail.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | Trace2 stopwatch timers and global counters | expand |
On Mon, Dec 20 2021, Jeff Hostetler via GitGitGadget wrote: > 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 > } FWIW this seems like a time not to bump the version per the proposed approach in: https://lore.kernel.org/git/211201.86zgpk9u3t.gmgdl@evledraar.gmail.com/ Not directly related to this series, which just preserves the status quo, but it would be nice to get feedback on that proposal from you. > [...] > + * Verison 1: original version A typo of "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; > + nit: Odd placement of \n\n > + 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; Both for this... > + 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); [...] > +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); ...and this, wouldn't it be better/more readable to retain the uint64_t for the math, and just cast if needed when we're doing the formatting?
On 12/20/21 11:39 AM, Ævar Arnfjörð Bjarmason wrote: > > On Mon, Dec 20 2021, Jeff Hostetler via GitGitGadget wrote: > >> 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> >>... >> 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 >> } > > FWIW this seems like a time not to bump the version per the proposed > approach in: > https://lore.kernel.org/git/211201.86zgpk9u3t.gmgdl@evledraar.gmail.com/ > > Not directly related to this series, which just preserves the status > quo, but it would be nice to get feedback on that proposal from you. Frankly, my eyes glazed over every time I tried to read it.... Your proposal looks fine. And yes, our assumptions are that because we have structured data, new event types and/or new fields can be added and safely ignored by JSON parsers, so we should be OK. So we're assuming that only if we drop events or fields or change the meaning of one of them, would a parser need to react and so we can limit version bumps to those instances. I'm OK with this. I'll let you draft the wording in api-trace2.txt to explain the how/when/why we want to update the version number in the future. Thanks. > >> [...] >> + * Verison 1: original version > > A typo of "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" >> I'll roll this back in my next version. >> /* >> * 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; >> + > > nit: Odd placement of \n\n > >> + 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; > > Both for this... > >> + 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); > > [...] > >> +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); > > ....and this, wouldn't it be better/more readable to retain the uint64_t > for the math, and just cast if needed when we're doing the formatting? > I had those expressions inline at first and it really junked up the lines and made things hard to read -- partially because of the need to wrap the lines a lot. I went with the local t_* temp vars to make it more clear what we were doing. This style also matched the existing code in _tgt_event.c for `t_abs` and `t_rel` in all of the fn_*. Jeff
On 12/20/2021 10:01 AM, Jeff Hostetler via GitGitGadget wrote: > +`"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 Could you specify the units for these t_* entries? I'm guessing seconds based on the example, but I've seen similar timers using milliseconds instead so it's best to be super clear here. > +/* > + * Stopwatch timer event. This function writes the previously accumlated s/accumlated/accumulated/ > + * 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 s/cummulative/cumulative/ > + * -- 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); > 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 ... > +static void fn_timer(uint64_t us_elapsed_absolute, (I was going to complain about the generic name here, but it's static to the tr2_tgt_event.c file, so that's fine.) > + 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; Looks like seconds here. At first glance, I thought this large division might cause some loss of precision. However, the structure of floating point numbers means we probably don't lose that much. It might be worth _considering_ using milliseconds (only divide by 1000.0) but I'm probably just being paranoid here. Thanks, -Stolee
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, };