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

[Derrick Stolee <stolee@gmail.com>]

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