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

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

On Sun, 21 Aug 2022 14:35:00 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> 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?

Ah, that's nice. But I would like to have "option" instead of "display"
so that we can add another options in the future. :)

> 
> 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..

Oops, I already updated mine, let me just share the v3. Anyway I will
wait your series and update it again. :)

Thank you,

> 
> 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>
> > > 
> > 
> > 
> 


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