Re: [PATCH 2/4] perf annotate: Avoid division by zero when calculating percent

From: Arnaldo Carvalho de Melo
Date: Tue Mar 21 2017 - 10:31:58 EST


Em Tue, Mar 21, 2017 at 11:14:07AM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Tue, Mar 21, 2017 at 07:20:20AM +0900, Taeung Song escreveu:
> > And,
> > I tested by perf-stat on the same situation as below.
> >
> > $ perf stat -e "{cycles,page-faults,branch-misses}" ./old <input.txt
> > 6623856
>
> Please always try to spell out all the steps needed to get to some
> result, for instance, in this case the info above, that you are asking
> for three counters to be recorded at once probably has the key to
> reproduce this, as I think that you may run your workload and sometimes
> not get one page fault, leading tho that division by zero, but I have to
> try to reproduce it now that I have this clue.

Bingo!

[root@jouet ~]# perf record -e "{cycles,page-faults,branch-misses}" usleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.020 MB perf.data (20 samples) ]
[root@jouet ~]# perf annotate -l --stdio 2>&1 | grep -w nan | head
100.00 -nan 100.00 msr.h:104
0.00 -nan 0.00 : ffffffff81060bf0: mov %edi,%ecx
0.00 -nan 0.00 : ffffffff81060bf2: mov %esi,%eax
0.00 -nan 0.00 : ffffffff81060bf4: wrmsr
msr.h:104 100.00 -nan 100.00 : ffffffff81060bf6: nopl 0x0(%rax,%rax,1)
0.00 -nan 0.00 : ffffffff81060bfb: retq
0.00 -nan 0.00 : ffffffff81060bfc: push %rbp
0.00 -nan 0.00 : ffffffff81060bfd: mov %esi,%eax
0.00 -nan 0.00 : ffffffff81060bff: mov %rdx,%rsi
0.00 -nan 0.00 : ffffffff81060c02: shl $0x20,%rsi
[root@jouet ~]#

So, if we don't use -l/--print-line we get:

[root@jouet ~]# perf annotate --stdio --no-source native_write_msr
Percent | Source code & Disassembly of vmlinux for cycles (3 samples)
-------------------------------------------------------------------------------------------
: ffffffff81060bf0 <native_write_msr>:
: __wrmsr():
0.00 0.00 0.00 : ffffffff81060bf0: mov %edi,%ecx
0.00 0.00 0.00 : ffffffff81060bf2: mov %esi,%eax
0.00 0.00 0.00 : ffffffff81060bf4: wrmsr
: arch_static_branch():
100.00 0.00 100.00 : ffffffff81060bf6: nopl 0x0(%rax,%rax,1)
: native_write_msr():
0.00 0.00 0.00 : ffffffff81060bfb: retq
0.00 0.00 0.00 : ffffffff81060bfc: push %rbp
0.00 0.00 0.00 : ffffffff81060bfd: mov %esi,%eax
0.00 0.00 0.00 : ffffffff81060bff: mov %rdx,%rsi
0.00 0.00 0.00 : ffffffff81060c02: shl $0x20,%rsi
0.00 0.00 0.00 : ffffffff81060c06: mov %eax,%edx
0.00 0.00 0.00 : ffffffff81060c08: mov %rsp,%rbp
0.00 0.00 0.00 : ffffffff81060c0b: or %rdx,%rsi
0.00 0.00 0.00 : ffffffff81060c0e: xor %edx,%edx
0.00 0.00 0.00 : ffffffff81060c10: callq ffffffff81457df0 <do_trace_write_msr>
0.00 0.00 0.00 : ffffffff81060c15: pop %rbp
0.00 0.00 0.00 : ffffffff81060c16: retq
[root@jouet ~]#

I.e. one column per event in that group, and no -nan, all is well.

But if we ask for --lines it gets b0rked:

[root@jouet ~]# perf annotate --stdio --no-source native_write_msr --print-line

Sorted summary for file /lib/modules/4.11.0-rc2+/build/vmlinux
----------------------------------------------

100.00 -nan 100.00 msr.h:104
Percent | Source code & Disassembly of vmlinux for cycles (3 samples)
-------------------------------------------------------------------------------------------
: ffffffff81060bf0 <native_write_msr>:
: __wrmsr():
0.00 -nan 0.00 : ffffffff81060bf0: mov %edi,%ecx
0.00 -nan 0.00 : ffffffff81060bf2: mov %esi,%eax
0.00 -nan 0.00 : ffffffff81060bf4: wrmsr
: arch_static_branch():
msr.h:104 100.00 -nan 100.00 : ffffffff81060bf6: nopl 0x0(%rax,%rax,1)
: native_write_msr():
0.00 -nan 0.00 : ffffffff81060bfb: retq
0.00 -nan 0.00 : ffffffff81060bfc: push %rbp
0.00 -nan 0.00 : ffffffff81060bfd: mov %esi,%eax
0.00 -nan 0.00 : ffffffff81060bff: mov %rdx,%rsi
0.00 -nan 0.00 : ffffffff81060c02: shl $0x20,%rsi
0.00 -nan 0.00 : ffffffff81060c06: mov %eax,%edx
0.00 -nan 0.00 : ffffffff81060c08: mov %rsp,%rbp
0.00 -nan 0.00 : ffffffff81060c0b: or %rdx,%rsi
0.00 -nan 0.00 : ffffffff81060c0e: xor %edx,%edx
0.00 -nan 0.00 : ffffffff81060c10: callq ffffffff81457df0 <do_trace_write_msr>
0.00 -nan 0.00 : ffffffff81060c15: pop %rbp
0.00 -nan 0.00 : ffffffff81060c16: retq
[root@jouet ~]#

I don't have that much time to continue pursuing this, try to continue
investigating, I'll try to help and to fix this later.

- Arnaldo