Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[HUMMEL Michel]

Hello,
I am testing the perf command of my new centos 6.2 server, and I don't understand something.
My Conf :
################################################################
$ grep name /proc/cpuinfo
model name      : Intel(R) Xeon(R) CPU           E5620  @ 2.40GHz
$ uname -a
Linux xxxxxxxx 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22 GMT 2011 x86_64 x86_64 x86_64 GNU/Linux
$ perf --version
perf version 2.6.32-220.el6.x86_64.debug
$ perf test
 1: vmlinux symtab matches kallsyms: FAILED!

 2: detect open syscall event: Ok
 3: detect open syscall event on all cpus: Ok
 4: read samples using the mmap interface: Ok
################################################################

I wrote a simple test case which is calling two functions.
The first one "good_perfo"  does the same as the second "bad_perfo" but more efficiently (lesser cache miss ...).

Gprof profile confirms this :
################################################################
$ gprof -p ./test_perfo
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
 76.14     38.75    38.75        1    38.75    38.75  bad_perfo
 23.70     50.81    12.06        1    12.06    12.06  good_perfo
################################################################

but perf don't want to give me the good answer when I asking for two events : cycles and instructions  :
################################################################
$ perf record -e  cycles,instructions  -o perf.data.cycles.instructions ./test_perfo
$ perf report -i perf.data.cycles.instructions --stdio
# Events: 5K cycles
#
# Overhead  Command      Shared Object                      Symbol
# ........  .......  .................  ..........................
#
    99.35%  test_perfo  test_perfo         [.] good_perfo
     0.14%  test_perfo  [kernel.kallsyms]  [k] clear_page_c
     0.08%  test_perfo  [kernel.kallsyms]  [k] page_fault
     0.05%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt


# Events: 5K instructions
#
# Overhead  Command      Shared Object                     Symbol
# ........  .......  .................  .........................
#
    99.93%  test_perfo  test_perfo         [.] good_perfo
     0.02%  test_perfo  [kernel.kallsyms]  [k] __run_hrtimer
     0.02%  test_perfo  [kernel.kallsyms]  [k] inode_has_perm
     0.02%  test_perfo  [kernel.kallsyms]  [k] update_wall_time

################################################################

The bad_perfo function is not appearing in the profile (and I am sure that it should !) 
Now if I do 2 separate records, one for the cycles and one for the instructions, the profile seems to be good :

################################################################
$ perf record -e  cycles  -o perf.data.cycles ./test_perfo
$ perf report -i perf.data.cycles --stdio
# Events: 51K cycles
#
# Overhead  Command      Shared Object                      Symbol
# ........  .......  .................  ..........................
#
    76.20%  test_perfo  test_perfo         [.] bad_perfo
    23.36%  test_perfo  test_perfo         [.] good_perfo
     0.03%  test_perfo  [kernel.kallsyms]  [k] apic_timer_interrupt
     0.02%  test_perfo  [kernel.kallsyms]  [k] do_softirq
     0.02%  test_perfo  [kernel.kallsyms]  [k] avc_has_perm_noaudit

$ perf record -e  instructions  -o perf.data.instructions ./test_perfo
$ perf report -i perf.data.instructions --stdio
# Events: 45K instructions
#
# Overhead  Command      Shared Object                    Symbol
# ........  .......  .................  ........................
#
    49.95%  test_perfo  test_perfo         [.] bad_perfo
    49.94%  test_perfo  test_perfo         [.] good_perfo
     0.01%  test_perfo  [kernel.kallsyms]  [k] raise_softirq
     0.01%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt
     0.01%  test_perfo  [kernel.kallsyms]  [k] kmem_cache_alloc_notrace
################################################################

Is I missed something with the perf command or this is a bug ?


I found a Quick&Dirty solution :
Using the -D ( Collect data without buffering ) option give me the good profile :
################################################################
$ perf record -D -e  cycles,instructions  -o perf.data.cycles.instructions ./test_perfo
$ perf report -i perf.data.cycles.instructions --stdio
# Events: 51K cycles
#
# Overhead  Command      Shared Object                      Symbol
# ........  .......  .................  ..........................
#
    76.20%  test_perfo  test_perfo         [.] bad_perfo
    22.99%  test_perfo  test_perfo         [.] good_perfo
     0.10%  test_perfo  [kernel.kallsyms]  [k] _spin_lock
     0.05%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt
  
:
# Events: 51K cycles
#
# Overhead  Command      Shared Object                      Symbol
# ........  .......  .................  ..........................
#
    76.20%  test_perfo  test_perfo         [.] bad_perfo
    22.99%  test_perfo  test_perfo         [.] good_perfo
     0.10%  test_perfo  [kernel.kallsyms]  [k] _spin_lock
     0.05%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt 
################################################################

Thank for any help,
Michel Hummel

Re: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[Michael Ellerman]

On Wed, 2012-05-23 at 18:06 +0200, HUMMEL Michel wrote:
> Hello,
> I am testing the perf command of my new centos 6.2 server, and I don't understand something.
> 
> I wrote a simple test case which is calling two functions.
> The first one "good_perfo"  does the same as the second "bad_perfo"
> but more efficiently (lesser cache miss ...).

Does it make any difference if you rewrite your test to run bad_perfo
first, and then good_perfo?

cheers

Re: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[Namhyung Kim]

Hi,

On Wed, 23 May 2012 18:06:59 +0200, HUMMEL Michel wrote:
> Hello,
> I am testing the perf command of my new centos 6.2 server, and I don't understand something.
> My Conf :
> ################################################################
> $ grep name /proc/cpuinfo
> model name      : Intel(R) Xeon(R) CPU           E5620  @ 2.40GHz
> $ uname -a
> Linux xxxxxxxx 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22 GMT 2011 x86_64 x86_64 x86_64 GNU/Linux
> $ perf --version
> perf version 2.6.32-220.el6.x86_64.debug
> $ perf test
>  1: vmlinux symtab matches kallsyms: FAILED!
>
>  2: detect open syscall event: Ok
>  3: detect open syscall event on all cpus: Ok
>  4: read samples using the mmap interface: Ok
> ################################################################
>
> I wrote a simple test case which is calling two functions.
> The first one "good_perfo"  does the same as the second "bad_perfo" but more efficiently (lesser cache miss ...).
>
> Gprof profile confirms this :
> ################################################################
> $ gprof -p ./test_perfo
> Flat profile:
>
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls   s/call   s/call  name
>  76.14     38.75    38.75        1    38.75    38.75  bad_perfo
>  23.70     50.81    12.06        1    12.06    12.06  good_perfo
> ################################################################
>
> but perf don't want to give me the good answer when I asking for two events : cycles and instructions  :
> ################################################################
> $ perf record -e  cycles,instructions  -o perf.data.cycles.instructions ./test_perfo
> $ perf report -i perf.data.cycles.instructions --stdio
> # Events: 5K cycles
> #

One thing I noticed is the number of events in this run is much smaller
than others (5K to 51K). Probably it can be a reason of the inaccuracy,
but I'm not sure. Maybe increasing sampling freq (-F) or adding the 'u'
modifier on events can help.

Thanks,
Namhyung


> # Overhead  Command      Shared Object                      Symbol
> # ........  .......  .................  ..........................
> #
>     99.35%  test_perfo  test_perfo         [.] good_perfo
>      0.14%  test_perfo  [kernel.kallsyms]  [k] clear_page_c
>      0.08%  test_perfo  [kernel.kallsyms]  [k] page_fault
>      0.05%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt
>
>
> # Events: 5K instructions
> #
> # Overhead  Command      Shared Object                     Symbol
> # ........  .......  .................  .........................
> #
>     99.93%  test_perfo  test_perfo         [.] good_perfo
>      0.02%  test_perfo  [kernel.kallsyms]  [k] __run_hrtimer
>      0.02%  test_perfo  [kernel.kallsyms]  [k] inode_has_perm
>      0.02%  test_perfo  [kernel.kallsyms]  [k] update_wall_time
>
> ################################################################
>
> The bad_perfo function is not appearing in the profile (and I am sure that it should !) 
> Now if I do 2 separate records, one for the cycles and one for the instructions, the profile seems to be good :
>
> ################################################################
> $ perf record -e  cycles  -o perf.data.cycles ./test_perfo
> $ perf report -i perf.data.cycles --stdio
> # Events: 51K cycles
> #
> # Overhead  Command      Shared Object                      Symbol
> # ........  .......  .................  ..........................
> #
>     76.20%  test_perfo  test_perfo         [.] bad_perfo
>     23.36%  test_perfo  test_perfo         [.] good_perfo
>      0.03%  test_perfo  [kernel.kallsyms]  [k] apic_timer_interrupt
>      0.02%  test_perfo  [kernel.kallsyms]  [k] do_softirq
>      0.02%  test_perfo  [kernel.kallsyms]  [k] avc_has_perm_noaudit
>
> $ perf record -e  instructions  -o perf.data.instructions ./test_perfo
> $ perf report -i perf.data.instructions --stdio
> # Events: 45K instructions
> #
> # Overhead  Command      Shared Object                    Symbol
> # ........  .......  .................  ........................
> #
>     49.95%  test_perfo  test_perfo         [.] bad_perfo
>     49.94%  test_perfo  test_perfo         [.] good_perfo
>      0.01%  test_perfo  [kernel.kallsyms]  [k] raise_softirq
>      0.01%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt
>      0.01%  test_perfo  [kernel.kallsyms]  [k] kmem_cache_alloc_notrace
> ################################################################
>
> Is I missed something with the perf command or this is a bug ?
>
>
> I found a Quick&Dirty solution :
> Using the -D ( Collect data without buffering ) option give me the good profile :
> ################################################################
> $ perf record -D -e  cycles,instructions  -o perf.data.cycles.instructions ./test_perfo
> $ perf report -i perf.data.cycles.instructions --stdio
> # Events: 51K cycles
> #
> # Overhead  Command      Shared Object                      Symbol
> # ........  .......  .................  ..........................
> #
>     76.20%  test_perfo  test_perfo         [.] bad_perfo
>     22.99%  test_perfo  test_perfo         [.] good_perfo
>      0.10%  test_perfo  [kernel.kallsyms]  [k] _spin_lock
>      0.05%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt
>   
> :
> # Events: 51K cycles
> #
> # Overhead  Command      Shared Object                      Symbol
> # ........  .......  .................  ..........................
> #
>     76.20%  test_perfo  test_perfo         [.] bad_perfo
>     22.99%  test_perfo  test_perfo         [.] good_perfo
>      0.10%  test_perfo  [kernel.kallsyms]  [k] _spin_lock
>      0.05%  test_perfo  [kernel.kallsyms]  [k] hrtimer_interrupt 
> ################################################################
>
> Thank for any help,
> Michel Hummel

RE: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[HUMMEL Michel]

I've written the test to run bad_perfo first, and then good_perfo and now only bad_perfo is in the report :

$ perf record -e  cycles,instructions  -o perf.data.cycles.instructions2 ./test_perfo2
$ perf report -i perf.data.cycles.instructions2 --stdio
# Events: 8K cycles
#
# Overhead  Command      Shared Object                     Symbol
# ........  .......  .................  .........................
#
    99.52%  test_perfo2  test_perfo2        [.] bad_perfo
     0.06%  test_perfo2  [kernel.kallsyms]  [k] copy_page_c
     0.05%  test_perfo2  [kernel.kallsyms]  [k] apic_timer_interrupt
     0.04%  test_perfo2  [kernel.kallsyms]  [k] run_timer_softirq


# Events: 8K instructions
#
# Overhead  Command      Shared Object                   Symbol
# ........  .......  .................  .......................
#
    99.82%  test_perfo2  test_perfo2        [.] bad_perfo
     0.04%  test_perfo2  ld-2.12.so         [.] _dl_lookup_symbol_x
     0.01%  test_perfo2  [kernel.kallsyms]  [k] clear_page_c
     0.01%  test_perfo2  [kernel.kallsyms]  [k] update_wall_time


Michel Hummel
THALES SERVICES SSE/DSC
Tél : +33 (0)5 62 88 76 29
Parc technologique du Canal - 3 avenue de l'Europe – Campus 2 Bât.D • 31400 Toulouse • France www.thalesgroup.com



-----Message d'origine-----
De : Michael Ellerman [mailto:michael@ellerman.id.au] 
Envoyé : jeudi 24 mai 2012 02:33
À : HUMMEL Michel
Cc : linux-perf-users@vger.kernel.org
Objet : Re: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

On Wed, 2012-05-23 at 18:06 +0200, HUMMEL Michel wrote:
> Hello,
> I am testing the perf command of my new centos 6.2 server, and I don't understand something.
> 
> I wrote a simple test case which is calling two functions.
> The first one "good_perfo"  does the same as the second "bad_perfo"
> but more efficiently (lesser cache miss ...).

Does it make any difference if you rewrite your test to run bad_perfo
first, and then good_perfo?

cheers

RE: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[HUMMEL Michel]

-----Message d'origine-----
De : linux-perf-users-owner@vger.kernel.org [mailto:linux-perf-users-owner@vger.kernel.org] De la part de Namhyung Kim
Envoyé : jeudi 24 mai 2012 02:45
À : HUMMEL Michel
Cc : linux-perf-users@vger.kernel.org
Objet : Re: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

Hi,

On Wed, 23 May 2012 18:06:59 +0200, HUMMEL Michel wrote:
> Hello,
> I am testing the perf command of my new centos 6.2 server, and I don't understand something.
> My Conf :
> ################################################################
> $ grep name /proc/cpuinfo
> model name      : Intel(R) Xeon(R) CPU           E5620  @ 2.40GHz
> $ uname -a
> Linux xxxxxxxx 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22 GMT 2011 x86_64 x86_64 x86_64 GNU/Linux
> $ perf --version
> perf version 2.6.32-220.el6.x86_64.debug
> $ perf test
>  1: vmlinux symtab matches kallsyms: FAILED!
>
>  2: detect open syscall event: Ok
>  3: detect open syscall event on all cpus: Ok
>  4: read samples using the mmap interface: Ok
> ################################################################
>
> I wrote a simple test case which is calling two functions.
> The first one "good_perfo"  does the same as the second "bad_perfo" but more efficiently (lesser cache miss ...).
>
> Gprof profile confirms this :
> ################################################################
> $ gprof -p ./test_perfo
> Flat profile:
>
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls   s/call   s/call  name
>  76.14     38.75    38.75        1    38.75    38.75  bad_perfo
>  23.70     50.81    12.06        1    12.06    12.06  good_perfo
> ################################################################
>
> but perf don't want to give me the good answer when I asking for two events : cycles and instructions  :
> ################################################################
> $ perf record -e  cycles,instructions  -o perf.data.cycles.instructions ./test_perfo
> $ perf report -i perf.data.cycles.instructions --stdio
> # Events: 5K cycles
> #

One thing I noticed is the number of events in this run is much smaller
than others (5K to 51K). Probably it can be a reason of the inaccuracy,
but I'm not sure. Maybe increasing sampling freq (-F) or adding the 'u'
modifier on events can help.

Thanks,
Namhyung




Increasing the frequency doesn't change the profile :

$  perf record -F100000 -e  cycles,instructions  -o perf.data.cycles.instructions3 ./test_perfo

 [ perf record: Captured and wrote 2.015 MB perf.data.cycles.instructions3 (~88048 samples) ]
Processed 0 events and LOST 66!

Check IO/CPU overload!

$ perf report -i perf.data.cycles.instructions3 --stdio
Processed 0 events and LOST 66!

Check IO/CPU overload!

# Events: 22K cycles
#
# Overhead  Command      Shared Object                            Symbol
# ........  .......  .................  ................................
#
    95.85%  test_perfo  test_perfo         [.] good_perfo
     2.73%  test_perfo  [kernel.kallsyms]  [k] clear_page_c
     0.23%  test_perfo  [kernel.kallsyms]  [k] page_fault
     0.06%  test_perfo  [kernel.kallsyms]  [k] __alloc_pages_nodemask

# Events: 21K instructions
#
# Overhead  Command      Shared Object                       Symbol
# ........  .......  .................  ...........................
#
    99.71%  test_perfo  test_perfo         [.] good_perfo
     0.03%  test_perfo  [kernel.kallsyms]  [k] clear_page_c
     0.03%  test_perfo  [kernel.kallsyms]  [k] get_page_from_freelist
     0.02%  test_perfo  [kernel.kallsyms]  [k] handle_mm_fault

#
# (For a higher level overview, try: perf report --sort comm,dso)
#


Michel Hummel

Re: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[David Ahern]

On 5/24/12 1:14 AM, HUMMEL Michel wrote:
> I've written the test to run bad_perfo first, and then good_perfo and now only bad_perfo is in the report :
>
> $ perf record -e  cycles,instructions  -o perf.data.cycles.instructions2 ./test_perfo2
> $ perf report -i perf.data.cycles.instructions2 --stdio
> # Events: 8K cycles
> #
> # Overhead  Command      Shared Object                     Symbol
> # ........  .......  .................  .........................
> #
>      99.52%  test_perfo2  test_perfo2        [.] bad_perfo
>       0.06%  test_perfo2  [kernel.kallsyms]  [k] copy_page_c
>       0.05%  test_perfo2  [kernel.kallsyms]  [k] apic_timer_interrupt
>       0.04%  test_perfo2  [kernel.kallsyms]  [k] run_timer_softirq
>
>
> # Events: 8K instructions
> #
> # Overhead  Command      Shared Object                   Symbol
> # ........  .......  .................  .......................
> #
>      99.82%  test_perfo2  test_perfo2        [.] bad_perfo
>       0.04%  test_perfo2  ld-2.12.so         [.] _dl_lookup_symbol_x
>       0.01%  test_perfo2  [kernel.kallsyms]  [k] clear_page_c
>       0.01%  test_perfo2  [kernel.kallsyms]  [k] update_wall_time
>

Can you try an upstream version of the perf binary? It should be able to 
read the data file. You can use the perf-script command to dump the 
events and look at what was recorded and which type of event (cycles vs 
instructions). Adding -R to the record will get the timestamp added to 
each sample and look at the delta time between samples. Maybe that will 
give a clue.

David

RE: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[HUMMEL Michel]

Thanks for your help,

I tried with a perf_3.2 binary but it gives me the same bad results.
I Tried to read the old record, and also to generate a new one with the 3.2 binary.

I am not sure to understand your suggestion with perf script and the -R option, can you give me more details please (sorry for my poor english).



Michel Hummel
THALES SERVICES SSE/DSC
Tél : +33 (0)5 62 88 76 29
Parc technologique du Canal - 3 avenue de l'Europe – Campus 2 Bât.D • 31400 Toulouse • France www.thalesgroup.com



-----Message d'origine-----
De : David Ahern [mailto:dsahern@gmail.com] 
Envoyé : jeudi 24 mai 2012 16:57
À : HUMMEL Michel
Cc : linux-perf-users@vger.kernel.org
Objet : Re: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

On 5/24/12 1:14 AM, HUMMEL Michel wrote:
> I've written the test to run bad_perfo first, and then good_perfo and now only bad_perfo is in the report :
>
> $ perf record -e  cycles,instructions  -o perf.data.cycles.instructions2 ./test_perfo2
> $ perf report -i perf.data.cycles.instructions2 --stdio
> # Events: 8K cycles
> #
> # Overhead  Command      Shared Object                     Symbol
> # ........  .......  .................  .........................
> #
>      99.52%  test_perfo2  test_perfo2        [.] bad_perfo
>       0.06%  test_perfo2  [kernel.kallsyms]  [k] copy_page_c
>       0.05%  test_perfo2  [kernel.kallsyms]  [k] apic_timer_interrupt
>       0.04%  test_perfo2  [kernel.kallsyms]  [k] run_timer_softirq
>
>
> # Events: 8K instructions
> #
> # Overhead  Command      Shared Object                   Symbol
> # ........  .......  .................  .......................
> #
>      99.82%  test_perfo2  test_perfo2        [.] bad_perfo
>       0.04%  test_perfo2  ld-2.12.so         [.] _dl_lookup_symbol_x
>       0.01%  test_perfo2  [kernel.kallsyms]  [k] clear_page_c
>       0.01%  test_perfo2  [kernel.kallsyms]  [k] update_wall_time
>

Can you try an upstream version of the perf binary? It should be able to 
read the data file. You can use the perf-script command to dump the 
events and look at what was recorded and which type of event (cycles vs 
instructions). Adding -R to the record will get the timestamp added to 
each sample and look at the delta time between samples. Maybe that will 
give a clue.

David

Re: Perf 2.6.32-220.el6.x86_64 problem when recording 2 counters

[David Ahern]

On 5/24/12 10:19 AM, HUMMEL Michel wrote:
> Thanks for your help,
>
> I tried with a perf_3.2 binary but it gives me the same bad results.
> I Tried to read the old record, and also to generate a new one with the 3.2 binary.
>
> I am not sure to understand your suggestion with perf script and the -R option, can you give me more details please (sorry for my poor english).


RHEL6 and 2.6.32 is fairly old from perf's perspective. I have not 
looked at RHEL6 source to see how much of the upstream code was 
backported. However, the perf.data file *should* be compatible with 
upstream perf code.

So, in an attempt to better understand why you are not getting expected 
results:

1. Add -R to your record command:
perf record -R -e cycles,instructions \
    -o perf.data.cycles.instructions2 ./test_perfo2

2. Use the 3.2 version of the perf binary to analyze the file

perf_3.2 script -i perf.data.cycles.instructions2 > samples

Look at the samples file -- it will contain each sample and the event 
that triggered it (cycles or instructions). Does looking at each sample 
give some idea as to why the report does not make sense?

David