Re: [PATCH v2 0/2] tracing/hist: Add percentage histogram suffixes

[Masami Hiramatsu (Google) <mhiramat@kernel.org>]

On Thu, 18 Aug 2022 15:41:30 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> Hi Masami,
> 
> On Fri, 2022-08-05 at 10:35 +0900, Masami Hiramatsu (Google) wrote:
> > Hi,
> > 
> > Here is the 2nd version of .percent and .graph suffixes for histogram
> > trigger to show the value in percentage and in bar-graph respectively.
> > 
> > This version uses div64_*() for calculating percentages and show an
> > error if it fails to calculate it.
> > 
> 
> > This will help us to check the trend of the histogram instantly
> > without the post processing tool.
> > 
> > Here shows the example of the percentage and the bar graph of
> > the runtime of the running tasks.
> > 
> > /sys/kernel/tracing # echo hist:keys=pid:vals=runtime.percent,runtime.graph:sort
> > =pid >> events/sched/sched_stat_runtime/trigger
> > /sys/kernel/tracing # sleep 10
> > /sys/kernel/tracing # cat events/sched/sched_stat_runtime/hist
> > # event histogram
> > #
> > # trigger info: hist:keys=pid:vals=hitcount,runtime.percent,runtime.graph:sort=pid:size=2048 [active]
> > #
> > 
> > { pid:          8 } hitcount:         11  runtime:       4.11  runtime: #                   
> > { pid:          9 } hitcount:          4  runtime:       1.28  runtime:                     
> > { pid:         14 } hitcount:         10  runtime:       2.22  runtime:                     
> > { pid:         15 } hitcount:          1  runtime:       0.07  runtime:                     
> > { pid:         16 } hitcount:         21  runtime:       3.35  runtime: #                   
> > { pid:         57 } hitcount:          6  runtime:       2.41  runtime: #                   
> > { pid:         61 } hitcount:         42  runtime:       9.79  runtime: ####                
> > { pid:         66 } hitcount:          5  runtime:       0.69  runtime:                     
> > { pid:        147 } hitcount:         36  runtime:      45.33  runtime: ####################
> > { pid:       8548 } hitcount:          9  runtime:      17.25  runtime: #######             
> > { pid:       8549 } hitcount:          8  runtime:      13.43  runtime: #####    
> > 
> 
> This is a really nice new feature, thanks for adding it!

Thanks!

> 
> I did notice some anomalies when it comes to hitcount, though.  For
> instance, If I do similar to above with hitcount:
> 
>   # echo 'hist:keys=pid:vals=hitcount.percent,hitcount.graph:sort=pid'
>     >> sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
>   
>   # cat hist
> 
>   # event histogram
>   #
>   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048 [active]
>   { pid:         16 } hitcount:       2.11
>   { pid:         63 } hitcount:       6.33
>   { pid:         64 } hitcount:       6.33
> 
> it only shows one column with percent, no graph.

Hmm, curious. Also, the trigger info seems odd.

> 
> Similarly, if I do just hitcount and hitcount.graph, I only get the graph,
> no straight hitcount:
> 
>   # echo 'hist:keys=pid:vals=hitcount,hitcount.graph:sort=pid'
>     >> sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
> 
>   # cat hist
>   # event histogram
>   #
>   # trigger info: hist:keys=pid:vals=hitcount:sort=pid:size=2048 active]
>   #
> 
>   { pid:         16 } hitcount: ######              
>   { pid:         63 } hitcount: ##########          
>   { pid:         64 } hitcount: ##########
> 
> I think it's because there's only one hitcount variable serving both
> PERCENT and GRAPH flags, and never gets to GRAPH if both are set.  So
> needs to iterate over both flags for hitcount to see which or if both
> are set.

Ah, I thought if I specify the hitcount twice, there would be 2 hitcount
fields, but actually it is not.

>  Also, in order to just print the straight hitcount if one of
> the other flags is set probably needs another flag for that case.

Yes, because hitcount is shown only once.

> 
> Also, the trigger info string always only shows 'vals=hitcount' even if
> percent or graph is set.

yes, the hitcount seeems to be special. Would you know why hitcount
is always shown and handled in such unique way?
(If user skips setting vals, it is natual to use hitcount by default, but
 if user specifies any vals, I would like to drop hitcount...) 

> 
> Finally, I'm wondering if labeling the percent column as percent would
> make things clearer in cases where you have the straight value along
> with the percent e.g. currently we have:
> 
>   # echo hist:keys=pid:vals=runtime,runtime.percent:sort=pid 
>     >>/sys/kernel/debug/tracing/events/sched/sched_stat_runtime/trigger
>   # cat hist
>   # event histogram
>   #
>   # trigger info: hist:keys=pid:vals=hitcount,runtime,runtime.percent:sort=pid:size=2048 [active]
>   #
> 
>   { pid:         16 } hitcount:          3  runtime:      50742  runtime:       0.36
>   { pid:         63 } hitcount:          6  runtime:     123394  runtime:       0.88
> 
> which seeems a little confusing, 2 runtime fields with different values.  Maybe something like?:
> 
>   { pid:         16 } hitcount:          3  runtime:      50742  runtime (%):       0.36
>   { pid:         63 } hitcount:          6  runtime:     123394  runtime (%):       0.88
> 
> Just a thought..

Ah, that's a good idea.
Let me update the series.

Thank you!

> 
> Tom
> 
> >            
> > 
> > Totals:
> >     Hits: 153
> >     Entries: 11
> >     Dropped: 0
> > 
> > 
> > Thank you,
> > 
> > ---
> > 
> > Masami Hiramatsu (Google) (2):
> >       tracing: Add .percent suffix option to histogram values
> >       tracing: Add .graph suffix option to histogram value
> > 
> > 
> >  kernel/trace/trace.c             |    3 +
> >  kernel/trace/trace_events_hist.c |  129 ++++++++++++++++++++++++++++++++++++--
> >  2 files changed, 124 insertions(+), 8 deletions(-)
> > 
> > --
> > Masami Hiramatsu (Google) <mhiramat@kernel.org>
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>