Re: [PATCH 6/9] trace2: add timer events to perf and event target formats
- From
Derrick Stolee <stolee@gmail.com>
- Date
- Dec 21, 2021, 14:20 UTC
- Message-ID
- <8f62bae5-0026-c2c8-baa0-fd50b8d1668c@gmail.com>
- In-Reply-To
- <c5d5ff05e6ca5729993133ce0b6b94af2503808a.1640012469.git.gitgitgadget@gmail.com>
On 12/20/2021 10:01 AM, Jeff Hostetler via GitGitGadget wrote:
Show 13 quoted lines
> +`"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 intervalCould 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/
Show 5 quoted lines
> + * 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/
Show 16 quoted lines
> + * -- 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.)
Show 15 quoted lines
> + 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