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

[Tom Zanussi <zanussi@kernel.org>]

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!

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.

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.  Also, in order to just print the straight hitcount if one of
the other flags is set probably needs another flag for that case.

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

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

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>