[RFC] Performance Events 'Samples' report

[RFC] Performance Events 'Samples' report

[Cliff Wickman]

From: Cliff Wickman <cpw@sgi.com>

The perf command's report prints clock periods under the heading of 'Samples'.
Our applications people have been confused by this "Samples" heading.

perf report -n

# Overhead  Samples            Command         Shared Object                            Symbol
# ........ ..........  ...............  ....................  ................................
#
    99.41%1522136216246         pthreads  pthreads              [.] work_function
     0.33% 4980298302             perf  [kernel.kallsyms]     [k] clear_page_c
     ....

It would be more compact to print the number of samples.  And that would
be consistent with the heading.

Below is the code that displays the periods.  I don't see that the number
of samples is available here, but probably easily could be.
I presume that clock periods are derived from #samples * sample period.

perf/util/hist.c

 640 
 641         if (symbol_conf.show_nr_samples) {
 642                 if (sep)
 643                         ret += snprintf(s + ret, size - ret, "%c%" PRIu64,      *sep, period);
 644                 else
 645                         ret += snprintf(s + ret, size - ret, "%11" PRIu64,      period);
 646         }
 647 

Signed-off-by: Cliff Wickman <cpw@sgi.com>

Re: [RFC] Performance Events 'Samples' report

[Arnaldo Carvalho de Melo]

Em Thu, Feb 24, 2011 at 06:15:26PM -0600, Cliff Wickman escreveu:
> From: Cliff Wickman <cpw@sgi.com>
> 
> The perf command's report prints clock periods under the heading of 'Samples'.
> Our applications people have been confused by this "Samples" heading.
> 
> perf report -n
> 
> # Overhead  Samples            Command         Shared Object                            Symbol
> # ........ ..........  ...............  ....................  ................................
> #
>     99.41%1522136216246         pthreads  pthreads              [.] work_function
>      0.33% 4980298302             perf  [kernel.kallsyms]     [k] clear_page_c
>      ....
> 
> It would be more compact to print the number of samples.  And that would
> be consistent with the heading.
> 
> Below is the code that displays the periods.  I don't see that the number
> of samples is available here, but probably easily could be.
> I presume that clock periods are derived from #samples * sample period.
> 
> perf/util/hist.c
> 
>  640 
>  641         if (symbol_conf.show_nr_samples) {
>  642                 if (sep)
>  643                         ret += snprintf(s + ret, size - ret, "%c%" PRIu64,      *sep, period);
>  644                 else
>  645                         ret += snprintf(s + ret, size - ret, "%11" PRIu64,      period);
>  646         }
>  647 

Wasn't this fixed by:

commit fec9cbd15b9e99bab9bc50f1ed7e20a1087d7c6d
Author: Arnaldo Carvalho de Melo <acme@redhat.com>
Date:   Thu Feb 17 10:37:23 2011 -0200

    perf hists: Print number of samples, not the period sum
    
    So that we match the header where we state the number of events with the
    "Samples" column when using 'perf report -n/--show-nr-samples':
    
     [root@emilia ~]# perf record -a sleep 1
     [ perf record: Woken up 1 times to write data ]
     [ perf record: Captured and wrote 0.111 MB perf.data (~4860 samples) ]
     [root@emilia ~]# perf report --stdio --show-nr-samples
     # Events: 11  cycles
     #
     # Overhead  Samples        Command       Shared Object                        Symbol
     # ........ ..........  ...........  ..................  ............................
     #
         16.65%          1        sleep  [kernel.kallsyms]   [k] unmap_vmas
         16.10%          1         perf  libpthread-2.12.so  [.] __pthread_cleanup_push_defer
         15.79%          2         perf  [kernel.kallsyms]   [k] format_decode
         12.88%          1  kworker/1:2  [kernel.kallsyms]   [k] cache_reap
         10.69%          1      swapper  [kernel.kallsyms]   [k] _raw_spin_lock
          7.55%          1        sleep  [kernel.kallsyms]   [k] prepare_exec_creds
          6.00%          1         perf  [jbd2]              [k] start_this_handle
          5.29%          1         perf  [kernel.kallsyms]   [k] seq_read
          4.75%          1         perf  [kernel.kallsyms]   [k] get_pid_task
          4.30%          1         perf  [kernel.kallsyms]   [k] _raw_spin_unlock_irqrestore
    
     #
     # (For a higher level overview, try: perf report --sort comm,dso)
     #
     [root@emilia ~]#
    
    Reported-by: Stephane Eranian <eranian@google.com>
    Acked-by: Stephane Eranian <eranian@google.com>
    Cc: Frederic Weisbecker <fweisbec@gmail.com>
    Cc: Ingo Molnar <mingo@elte.hu>
    Cc: Mike Galbraith <efault@gmx.de>
    Cc: Paul Mackerras <paulus@samba.org>
    Cc: Peter Zijlstra <peterz@infradead.org>
    Cc: Stephane Eranian <eranian@google.com>
    Cc: Tom Zanussi <tzanussi@gmail.com>
    LKML-Reference: <new-submission>
    Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

?

Please try using tip/perf/core.

- Arnaldo

Re: [RFC] Performance Events 'Samples' report

[Ingo Molnar]

* Arnaldo Carvalho de Melo <acme@ghostprotocols.net> wrote:

> Wasn't this fixed by:
> 
> commit fec9cbd15b9e99bab9bc50f1ed7e20a1087d7c6d
> Author: Arnaldo Carvalho de Melo <acme@redhat.com>
> Date:   Thu Feb 17 10:37:23 2011 -0200
> 
>     perf hists: Print number of samples, not the period sum

Yeah. I'll cherry-pick it over into perf/urgent, ok? It's been reported by several 
people (I noticed it too) and the old numbers really made little sense - and the fix 
is really simple.

Thanks,

	Ingo