Re: [RFC/PATCH] perf stat: Show sample events stat for a data file

[Namhyung Kim <namhyung@kernel.org>]

Hi Peter,

On Wed, Apr 29, 2015 at 11:27:51AM +0200, Peter Zijlstra wrote:
> On Wed, Apr 29, 2015 at 04:27:45PM +0900, Namhyung Kim wrote:
> > Add --input option to 'perf stat' so that it can show event stats of the
> > file.  I would like to use a short '-i' option to be compatible with
> > other commands but it was already taken by '--no-inherit' option, so it
> > only supports the long option.
> > 
> > The example output looks like below:
> > 
> >   $ perf record -a sleep 1
> >   [ perf record: Woken up 1 times to write data ]
> >   [ perf record: Captured and wrote 0.635 MB perf.data (1946 samples) ]
> > 
> >   $ perf stat --input perf.data
> > 
> >     Total event stats for 'perf.data' file:
> > 
> >               TOTAL events:       6837
> >                MMAP events:        116
> >                COMM events:        375
> >                EXIT events:          2
> >            THROTTLE events:         12
> >          UNTHROTTLE events:         11
> >                FORK events:        374
> >              SAMPLE events:       1946
> >               MMAP2 events:       3999
> >      FINISHED_ROUND events:          2
> > 
> >    Sample event stats:
> > 
> >          361,255,234      cycles
> >                1,946      samples                   #   sampling ratio  12.162% (486/4000)
> > 
> >          0.998581085 second time sampled
> 
> It would be nice if this thing could support 'perf record -s' which
> enables perf_event_attr::inherit_stat, which in turn results in
> PERF_RECORD_READ entries after every PERF_RECORD_EXIT which give the
> total number of events for each recorded task.

Hmm.. this is one of the areas that I don't understand what's going
on.  It'd be nice if you can help me understand and possibly improve
the doc too.

So the combination of 'perf record -s' and 'perf report -T' should
show some per-thread counter values, right?  I've found a bug on it.

Anyway, I don't understand the numbers it shows.

  $ perf record -s -- perf bench sched messaging
  # Running 'sched/messaging' benchmark:
  # 20 sender and receiver processes per group
  # 10 groups == 400 processes run

       Total time: 0.192 [sec]
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.376 MB perf.data (6806 samples) ]


  $ perf report -T --stdio
  ...
  #  PID   TID           cycles           cycles                cycles                cycles                cycles
    9728  9728          5865527                0                     0                     0                     0
    9686  9686                0                0               5692534                     0                     0
    9650  9650                0                0                     0                     0                     0
    9649  9649          5578209                0                     0                     0                     0
    9685  9685          6227490                0                     0                     0                     0
    9596  9596                0  140483569056856                     0                     0                     0
    9837  9837           120079  140483569056856                     0                     0                     0
    9561  9561                0  140483569056856                     0                     0                     0
    9475  9475                0         46264256                     0                 14012                 14172
  ...

  $ perf stat --input perf.data

   Total event stats for 'perf.data.inherit' file:

             TOTAL events:       9370
              MMAP events:        140
              COMM events:          2
              EXIT events:        401
              FORK events:        400
              READ events:       1600
            SAMPLE events:       6806
             MMAP2 events:         20
    FINISHED_ROUND events:          1

   Sample event stats:

     2,984,107,504      cycles
             6,806      samples                   #   sampling ratio  161.107% (6444/4000)

       0.264032172 second time sampled

So the cycles values on 'perf report -T' are a lot more than the value
of perf stat.  And I have no idea why it shows 5 different cycles for
each thread.  Could you shed some light on this?

Thanks,
Namhyung