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

[Tom Zanussi <zanussi@kernel.org>]

On Sat, 2022-08-20 at 11:31 +0900, Masami Hiramatsu wrote:
> 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=pi
> > > d: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...) 

It was just assumed that you'd always want to see the hitcount, so it
was added unconditionally as the first value.  I don't think we can
just drop it at this point if another value is specified and the
hitcount isn't, but we could add another section that could be used to
tailor the display to get rid of it e.g.

 echo hist:keys=pid:vals=hitcount:sort=pid:size=2048:display=no_hitcount,...

The display= section could be used to add other customization
possibilities in the future.

What do you think?

As for the anomalies I pointed out with the hitcount in your patches,
I'm thinking that adding a patch that allows the user to add multiple
hitcounts as with any other value should make the problems go away -
let me create a patch to do that and then you shouldn't have to make
any changes to yours..

Tom

> 
> > 
> > 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=2
> > 048 [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>
> > 
> 
>