perf annotate: Bugfixes

Currently perf-annotate with --print-line can print -nan(0x8000000000000) because of division by zero when calculating percent.

So if a sum of samples is zero, skip calculating percent.

Before:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    -nan    7.04 a.c:38
   25.14    -nan    0.00 a.c:34
   16.26    -nan   56.34 a.c:31
   15.88    -nan    1.41 a.c:37
    5.67    -nan    0.00 a.c:39
    1.13    -nan   35.21 a.c:26
    0.95    -nan    0.00 a.c:44
    0.57    -nan    0.00 a.c:32
 Percent                 |      Source code & Disassembly of a.out for cycles (529 samples)
-----------------------------------------------------------------------------------------
                         :

...

 a.c:26    0.57    -nan    4.23 :         40081a:       mov    %edi,-0x24(%rbp)
 a.c:26    0.00    -nan    9.86 :         40081d:       mov    %rsi,-0x30(%rbp)

...

After:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    0.00    7.04 a.c:38
   25.14    0.00    0.00 a.c:34
   16.26    0.00   56.34 a.c:31
   15.88    0.00    1.41 a.c:37
    5.67    0.00    0.00 a.c:39
    1.13    0.00   35.21 a.c:26
    0.95    0.00    0.00 a.c:44
    0.57    0.00    0.00 a.c:32
 Percent                 |      Source code & Disassembly of old for cycles (529 samples)
-----------------------------------------------------------------------------------------
                         :

...

a.c:26    0.57    0.00    4.23 :         40081a:       mov    %edi,-0x24(%rbp)
a.c:26    0.00    0.00    9.86 :         40081d:       mov    %rsi,-0x30(%rbp)

...

Cc Namhyung Kim <[email protected]>

Cc Jiri Olsa <[email protected]>

Signed-off-by Taeung Song <[email protected]>

---
 tools/perf/util/annotate.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

tools/perf/util/annotate.c +7 -3

index fc91c6b..9bb43cd 100644
@@ -1665,11 +1665,15 @@ static int symbol__get_source_line(struct symbol *sym, struct map *map,
 		src_line->nr_pcnt = nr_pcnt;
 
 		for (k = 0; k < nr_pcnt; k++) {
+			double percent = 0.0;
+
 			h = annotation__histogram(notes, evidx + k);
-			src_line->samples[k].percent = 100.0 * h->addr[i] / h->sum;
+			if (h->sum)
+				percent = 100.0 * h->addr[i] / h->sum;
 
-			if (src_line->samples[k].percent > percent_max)
-				percent_max = src_line->samples[k].percent;
+			if (percent > percent_max)
+				percent_max = percent;
+			src_line->samples[k].percent = percent;
 		}
 
 		if (percent_max <= 0.5)

Signature · 1 line

2.7.4

Em Mon, Mar 20, 2017 at 11:56:55AM +0900, Taeung Song escreveu:

Quoted 5 lines

Currently perf-annotate with --print-line can print -nan(0x8000000000000) because of division by zero when calculating percent.

So if a sum of samples is zero, skip calculating percent.

Tried to reproduce it here, couldn't, syswide record:

[root@jouet ~]# perf evlist -v
cycles: size: 112, { sample_period, sample_freq }: 4000, sample_type: IP|TID|TIME|CPU|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1, freq: 1, task: 1, sample_id_all: 1, exclude_guest: 1, mmap2: 1, comm_exec: 1 [root@jouet ~]# perf annotate --stdio -l 2> /dev/null | grep -i nan
[root@jouet ~]#

Can you please send me a perf.data file with this problem? I have to go thru the code to see how this can take place...

- Arnaldo

Quoted 82 lines

Before:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    -nan    7.04 a.c:38
   25.14    -nan    0.00 a.c:34
   16.26    -nan   56.34 a.c:31
   15.88    -nan    1.41 a.c:37
    5.67    -nan    0.00 a.c:39
    1.13    -nan   35.21 a.c:26
    0.95    -nan    0.00 a.c:44
    0.57    -nan    0.00 a.c:32
 Percent                 |      Source code & Disassembly of a.out for cycles (529 samples)
-----------------------------------------------------------------------------------------
                         :

...

 a.c:26    0.57    -nan    4.23 :         40081a:       mov    %edi,-0x24(%rbp)
 a.c:26    0.00    -nan    9.86 :         40081d:       mov    %rsi,-0x30(%rbp)

...

After:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    0.00    7.04 a.c:38
   25.14    0.00    0.00 a.c:34
   16.26    0.00   56.34 a.c:31
   15.88    0.00    1.41 a.c:37
    5.67    0.00    0.00 a.c:39
    1.13    0.00   35.21 a.c:26
    0.95    0.00    0.00 a.c:44
    0.57    0.00    0.00 a.c:32
 Percent                 |      Source code & Disassembly of old for cycles (529 samples)
-----------------------------------------------------------------------------------------
                         :

...

a.c:26    0.57    0.00    4.23 :         40081a:       mov    %edi,-0x24(%rbp)
a.c:26    0.00    0.00    9.86 :         40081d:       mov    %rsi,-0x30(%rbp)

...

Cc Namhyung Kim <[email protected]>

Cc Jiri Olsa <[email protected]>

Signed-off-by Taeung Song <[email protected]>

---
 tools/perf/util/annotate.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

tools/perf/util/annotate.c +7 -4

index fc91c6b..9bb43cd 100644
@@ -1665,11 +1665,15 @@ static int symbol__get_source_line(struct symbol *sym, struct map *map,
 		src_line->nr_pcnt = nr_pcnt;
 
 		for (k = 0; k < nr_pcnt; k++) {
+			double percent = 0.0;
+
 			h = annotation__histogram(notes, evidx + k);
-			src_line->samples[k].percent = 100.0 * h->addr[i] / h->sum;
+			if (h->sum)
+				percent = 100.0 * h->addr[i] / h->sum;
 
-			if (src_line->samples[k].percent > percent_max)
-				percent_max = src_line->samples[k].percent;
+			if (percent > percent_max)
+				percent_max = percent;
+			src_line->samples[k].percent = percent;
 		}
 
 		if (percent_max <= 0.5)
--

2.7.4

Hi Arnaldo :)

Here the perf.data is,
https://www.dropbox.com/s/nr4nnv8g3cipluf/perf.data?dl=1&pl=1

I tested as below.

  $ perf record -e "{cycles,page-faults,branch-misses}" ./old <input.txt

  $ perf annotate --stdio -l -f 2> /dev/null | grep -i nan | head -3
   29.04    -nan    1.52 old_pack_knapsack.c:34
   28.27    -nan    0.00 old_pack_knapsack.c:38
   16.37    -nan    0.00 old_pack_knapsack.c:37

Thanks,
Taeung

Quoted 114 lines · Arnaldo Carvalho de Melo

Em Mon, Mar 20, 2017 at 11:56:55AM +0900, Taeung Song escreveu:

Quoted 5 lines

Currently perf-annotate with --print-line can print -nan(0x8000000000000) because of division by zero when calculating percent.

So if a sum of samples is zero, skip calculating percent.

Tried to reproduce it here, couldn't, syswide record:

[root@jouet ~]# perf evlist -v
cycles: size: 112, { sample_period, sample_freq }: 4000, sample_type:
IP|TID|TIME|CPU|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1,
freq: 1, task: 1, sample_id_all: 1, exclude_guest: 1, mmap2: 1,
comm_exec: 1
[root@jouet ~]# perf annotate --stdio -l 2> /dev/null | grep -i nan [root@jouet ~]#

Can you please send me a perf.data file with this problem? I have to go thru the code to see how this can take place...

- Arnaldo

Quoted 91 lines

Before:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    -nan    7.04 a.c:38
   25.14    -nan    0.00 a.c:34
   16.26    -nan   56.34 a.c:31
   15.88    -nan    1.41 a.c:37
    5.67    -nan    0.00 a.c:39
    1.13    -nan   35.21 a.c:26
    0.95    -nan    0.00 a.c:44
    0.57    -nan    0.00 a.c:32

Percent | Source code & Disassembly of a.out
for cycles (529 samples)
-----------------------------------------------------------------------------------------

                         :

...

a.c:26 0.57 -nan 4.23 : 40081a: mov
%edi,-0x24(%rbp)
a.c:26 0.00 -nan 9.86 : 40081d: mov
%rsi,-0x30(%rbp)

...

After:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    0.00    7.04 a.c:38
   25.14    0.00    0.00 a.c:34
   16.26    0.00   56.34 a.c:31
   15.88    0.00    1.41 a.c:37
    5.67    0.00    0.00 a.c:39
    1.13    0.00   35.21 a.c:26
    0.95    0.00    0.00 a.c:44
    0.57    0.00    0.00 a.c:32

Percent | Source code & Disassembly of old for
cycles (529 samples)
-----------------------------------------------------------------------------------------

                         :

...

a.c:26 0.57 0.00 4.23 : 40081a: mov
%edi,-0x24(%rbp)
a.c:26 0.00 0.00 9.86 : 40081d: mov
%rsi,-0x30(%rbp)

...

Cc Namhyung Kim <[email protected]>

Cc Jiri Olsa <[email protected]>

Signed-off-by Taeung Song <[email protected]>

---
 tools/perf/util/annotate.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

tools/perf/util/annotate.c +7 -3

index fc91c6b..9bb43cd 100644
@@ -1665,11 +1665,15 @@ static int symbol__get_source_line(struct
 symbol *sym, struct map *map,
         src_line->nr_pcnt = nr_pcnt;
 
         for (k = 0; k < nr_pcnt; k++) {
+            double percent = 0.0;
+
             h = annotation__histogram(notes, evidx + k);
-            src_line->samples[k].percent = 100.0 * h->addr[i] / h->sum;
+            if (h->sum)
+                percent = 100.0 * h->addr[i] / h->sum;
 
-            if (src_line->samples[k].percent > percent_max)
-                percent_max = src_line->samples[k].percent;
+            if (percent > percent_max)
+                percent_max = percent;
+            src_line->samples[k].percent = percent;
         }
 

         if (percent_max <= 0.5)

--
2.7.4

And,
I tested by perf-stat on the same situation as below.

  $ perf stat -e "{cycles,page-faults,branch-misses}" ./old <input.txt
  6623856

   Performance counter stats for './old':

       472,007,763      cycles                            (99.85%)
                71      page-faults                       (99.85%)
           220,073      branch-misses                     (99.85%)

       0.170768608 seconds time elapsed

Many times, the number of samples 'page-faults' was 68 ~ 71. In spite of it, how did the below 'h->sum' is zero..

util/annotate.c:1660~1661

1660 h = annotation__histogram(notes, evidx + k);
1661 src_line->samples[k].percent = 100.0 * h->addr[i] / h->sum;

This patch just add if statement 'if (h->sum)' to handle the case that h->sum is zero. But now I wonder how h->sum could be zero..

I'll dig the problem to find the root cause of it, too !

Thanks,
Taeung

Quoted 133 lines · Taeung Song

Hi Arnaldo :)

Here the perf.data is,
https://www.dropbox.com/s/nr4nnv8g3cipluf/perf.data?dl=1&pl=1

I tested as below.

  $ perf record -e "{cycles,page-faults,branch-misses}" ./old <input.txt

  $ perf annotate --stdio -l -f 2> /dev/null | grep -i nan | head -3
   29.04    -nan    1.52 old_pack_knapsack.c:34
   28.27    -nan    0.00 old_pack_knapsack.c:38
   16.37    -nan    0.00 old_pack_knapsack.c:37

Thanks,
Taeung

Quoted 114 lines · Arnaldo Carvalho de Melo

Em Mon, Mar 20, 2017 at 11:56:55AM +0900, Taeung Song escreveu:

Quoted 5 lines

Currently perf-annotate with --print-line can print -nan(0x8000000000000) because of division by zero when calculating percent.

So if a sum of samples is zero, skip calculating percent.

Tried to reproduce it here, couldn't, syswide record:

[root@jouet ~]# perf evlist -v
cycles: size: 112, { sample_period, sample_freq }: 4000, sample_type:
IP|TID|TIME|CPU|PERIOD, disabled: 1, inherit: 1, mmap: 1, comm: 1,
freq: 1, task: 1, sample_id_all: 1, exclude_guest: 1, mmap2: 1,
comm_exec: 1
[root@jouet ~]# perf annotate --stdio -l 2> /dev/null | grep -i nan [root@jouet ~]#

Can you please send me a perf.data file with this problem? I have to go thru the code to see how this can take place...

- Arnaldo

Quoted 91 lines

Before:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    -nan    7.04 a.c:38
   25.14    -nan    0.00 a.c:34
   16.26    -nan   56.34 a.c:31
   15.88    -nan    1.41 a.c:37
    5.67    -nan    0.00 a.c:39
    1.13    -nan   35.21 a.c:26
    0.95    -nan    0.00 a.c:44
    0.57    -nan    0.00 a.c:32

Percent | Source code & Disassembly of a.out
for cycles (529 samples)
-----------------------------------------------------------------------------------------

                         :

...

a.c:26 0.57 -nan 4.23 : 40081a: mov
%edi,-0x24(%rbp)
a.c:26 0.00 -nan 9.86 : 40081d: mov
%rsi,-0x30(%rbp)

...

After:

    $ perf annotate --stdio -l

Sorted summary for file /home/taeung/workspace/a.out
----------------------------------------------

   32.89    0.00    7.04 a.c:38
   25.14    0.00    0.00 a.c:34
   16.26    0.00   56.34 a.c:31
   15.88    0.00    1.41 a.c:37
    5.67    0.00    0.00 a.c:39
    1.13    0.00   35.21 a.c:26
    0.95    0.00    0.00 a.c:44
    0.57    0.00    0.00 a.c:32

Percent | Source code & Disassembly of old for
cycles (529 samples)
-----------------------------------------------------------------------------------------

                         :

...

a.c:26 0.57 0.00 4.23 : 40081a: mov
%edi,-0x24(%rbp)
a.c:26 0.00 0.00 9.86 : 40081d: mov
%rsi,-0x30(%rbp)

...

Cc Namhyung Kim <[email protected]>

Cc Jiri Olsa <[email protected]>

Signed-off-by Taeung Song <[email protected]>

---
 tools/perf/util/annotate.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

tools/perf/util/annotate.c +7 -3

index fc91c6b..9bb43cd 100644
@@ -1665,11 +1665,15 @@ static int symbol__get_source_line(struct
 symbol *sym, struct map *map,
         src_line->nr_pcnt = nr_pcnt;
 
         for (k = 0; k < nr_pcnt; k++) {
+            double percent = 0.0;
+
             h = annotation__histogram(notes, evidx + k);
-            src_line->samples[k].percent = 100.0 * h->addr[i] / h->sum;
+            if (h->sum)
+                percent = 100.0 * h->addr[i] / h->sum;
 
-            if (src_line->samples[k].percent > percent_max)
-                percent_max = src_line->samples[k].percent;
+            if (percent > percent_max)
+                percent_max = percent;
+            src_line->samples[k].percent = percent;
         }
 

         if (percent_max <= 0.5)

--
2.7.4

Em Tue, Mar 21, 2017 at 07:20:20AM +0900, Taeung Song escreveu:

Quoted 5 lines

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.

Em Tue, Mar 21, 2017 at 11:14:07AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 7 lines

Em Tue, Mar 21, 2017 at 07:20:20AM +0900, Taeung Song escreveu:

Quoted 5 lines

And,
I tested by perf-stat on the same situation as below.

  $ perf stat -e "{cycles,page-faults,branch-misses}" ./old <input.txt
  6623856

Quoted 6 lines

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.

Em Tue, Mar 21, 2017 at 11:14:07AM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 7 lines

Em Tue, Mar 21, 2017 at 07:20:20AM +0900, Taeung Song escreveu:

Quoted 5 lines

And,
I tested by perf-stat on the same situation as below.

  $ perf stat -e "{cycles,page-faults,branch-misses}" ./old <input.txt
  6623856

Quoted 6 lines

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

grep -v "file name" in the objdump command cause a side effect eliminating filename:linenr of output of 'objdump -l' if the object file name and source file name are about the same so fix it.

The objdump command in symbol__disassemble() can be as below

    $ objdump -l -d -S -C /home/taeung/hello --start-address=...

    /home/taeung/hello:     file format elf64-x86-64

    Disassembly of section .text:

    0000000000400526 <main>:
    main():
    /home/taeung/hello.c:4

    void main()
    {
      400526:	55                   	push   %rbp
      400527:	48 89 e5             	mov    %rsp,%rbp
    /home/taeung/hello.c:5
    ...

But currently it use grep -v "file name" e.g. "/home/taeung/hello" in the objdump command to remove the first line containing file name and file format such as,

Before:

    $ objdump -l -d -S -C /home/taeung/hello | grep /home/taeung/hello

But it cause a side effect removing filename:linenr because the object file and source file has same name e.g. "/home/taueng/hello", "/home/taeung/hello.c"

So more exactly grep -v as below
to correctly remove the one line
e.g. "/home/taeung/hello: file format elf64-x86-64"

After:

    $ objdump -l -d -S -C /home/taeung/hello | grep /home/taeung/hello:

Cc Namhyung Kim <[email protected]>

Cc Jiri Olsa <[email protected]>

Signed-off-by Taeung Song <[email protected]>

---
 tools/perf/util/annotate.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

tools/perf/util/annotate.c +0 -0

index 63130ec..e49eb7e 100644

tools/perf/util/annotate.c +0 -0

 		 objdump_path ? objdump_path : "objdump",
 		 disassembler_style ? "-M " : "",
 		 disassembler_style ? disassembler_style : "",

Signature · 1 line

2.7.4

Em Mon, Mar 20, 2017 at 11:56:57AM +0900, Taeung Song escreveu:

Quoted 39 lines

grep -v "file name" in the objdump command cause a side effect eliminating filename:linenr of output of 'objdump -l' if the object file name and source file name are about the same so fix it.

The objdump command in symbol__disassemble() can be as below

    $ objdump -l -d -S -C /home/taeung/hello --start-address=...

    /home/taeung/hello:     file format elf64-x86-64

    Disassembly of section .text:

    0000000000400526 <main>:
    main():
    /home/taeung/hello.c:4

    void main()
    {
      400526:	55                   	push   %rbp
      400527:	48 89 e5             	mov    %rsp,%rbp
    /home/taeung/hello.c:5
    ...

But currently it use grep -v "file name" e.g. "/home/taeung/hello" in the objdump command to remove the first line containing file name and file format such as,

Before:

    $ objdump -l -d -S -C /home/taeung/hello | grep /home/taeung/hello

But it cause a side effect removing filename:linenr because the object file and source file has same name e.g. "/home/taueng/hello", "/home/taeung/hello.c"

So more exactly grep -v as below
to correctly remove the one line
e.g. "/home/taeung/hello: file format elf64-x86-64"

Quoted 2 lines

After:

    $ objdump -l -d -S -C /home/taeung/hello | grep /home/taeung/hello:

What environment is this? I tried to reproduce this here but got different results, and I had to figure out the 'perf record' you used, you forgot to mention it, i.e. 'perf record ./hello' doesn't work, one has to use 'perf record /full/path/to/hello', anyway, with my

environemnt, which is:

[root@jouet ~]# objdump -v
GNU objdump version 2.26.1-1.fc25

I end up getting:

Sorted summary for file /home/acme/c/hello
----------------------------------------------

   52.67 hello.c:7
   47.32 hello.c:8
 Percent |      Source code & Disassembly of hello for cycles:u (83555 samples)
-------------------------------------------------------------------------------
         :      00000000004004f6 <main>:
         :      main():
         :      #include <stdio.h>
         :
         :      int main(void)
         :      {
    0.00 :        4004f6:       push   %rbp
    0.00 :        4004f7:       mov    %rsp,%rbp
    0.00 :        4004fa:       sub    $0x10,%rsp
         :              unsigned long long i;
         :              printf("hello, world\n");
    0.00 :        4004fe:       mov    $0x4005d0,%edi
    0.00 :        400503:       callq  4003f0 <puts@plt>
         :              while (i < (unsigned long long)-1) {
    0.00 :        400508:       jmp    40052d <main+0x37>
         :                      i *= 171;
 hello.c:8    8.66 :      40050a:       mov    -0x8(%rbp),%rdx
    0.01 :        40050e:       mov    %rdx,%rax
    0.00 :        400511:       shl    $0x3,%rax
 hello.c:8    0.84 :      400515:       add    %rdx,%rax
 hello.c:8    8.60 :      400518:       add    %rax,%rax
 hello.c:8    3.46 :      40051b:       add    %rdx,%rax
 hello.c:8    8.57 :      40051e:       lea    0x0(,%rax,8),%rdx
    8.65 :        400526:       add    %rdx,%rax
    8.56 :        400529:       mov    %rax,-0x8(%rbp)

<SNIP>

Which looks ok, i.e. since this version of objdump puts just the basename (hello.c), that grep doesn't nuke it.

But yeah, your patch is more robust, just fix what I described below, i.e. use quotes in the grep -v bit, probably.

- Arnaldo

Quoted 7 lines

Cc Namhyung Kim <[email protected]>

Cc Jiri Olsa <[email protected]>

Signed-off-by Taeung Song <[email protected]>

---
 tools/perf/util/annotate.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

tools/perf/util/annotate.c int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na · line 1446

Quoted 10 lines

tools/perf/util/annotate.c +1 -1

index 63130ec..e49eb7e 100644
@@ -1443,7 +1443,7 @@ int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na
 	snprintf(command, sizeof(command),
 		 "%s %s%s --start-address=0x%016" PRIx64
 		 " --stop-address=0x%016" PRIx64
-		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s|expand",
+		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s: |expand",

Are you sure this works as you expect? I.e. both lines will have '%s:'

that space just before the '|' will not be considered by grep

Quoted 9 lines

tools/perf/util/annotate.c int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na · line 1446

Quoted 7 lines

+++ b/tools/perf/util/annotate.c

tools/perf/util/annotate.c +1 -1

@@ -1443,7 +1443,7 @@ int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na
 	snprintf(command, sizeof(command),
 		 "%s %s%s --start-address=0x%016" PRIx64
 		 " --stop-address=0x%016" PRIx64
-		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s|expand",
+		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s: |expand",

Are you sure this works as you expect? I.e. both lines will have '%s:'

Yes, if we do, we can exactly the only below line without the side effect IMHO.

Em Wed, Mar 22, 2017 at 01:19:49AM +0900, Taeung Song escreveu:

Quoted 10 lines · Arnaldo Carvalho de Melo

Quoted 9 lines

tools/perf/util/annotate.c int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na · line 1446

Quoted 7 lines

+++ b/tools/perf/util/annotate.c

tools/perf/util/annotate.c +1 -1

@@ -1443,7 +1443,7 @@ int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na
 	snprintf(command, sizeof(command),
 		 "%s %s%s --start-address=0x%016" PRIx64
 		 " --stop-address=0x%016" PRIx64
-		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s|expand",
+		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s: |expand",

Are you sure this works as you expect? I.e. both lines will have '%s:'

Quoted 2 lines

Yes, if we do, we can exactly the only below line without the side effect IMHO.

yeah, because the .c is not there, ok gotcha, will get your new commit log message, massage it a bit and apply the patch.

Em Tue, Mar 21, 2017 at 03:29:50PM -0300, Arnaldo Carvalho de Melo escreveu:

Quoted 15 lines

Em Wed, Mar 22, 2017 at 01:19:49AM +0900, Taeung Song escreveu:

Quoted 13 lines · Arnaldo Carvalho de Melo

Quoted 9 lines

tools/perf/util/annotate.c int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na · line 1446

Quoted 7 lines

+++ b/tools/perf/util/annotate.c

tools/perf/util/annotate.c +1 -1

@@ -1443,7 +1443,7 @@ int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na
 	snprintf(command, sizeof(command),
 		 "%s %s%s --start-address=0x%016" PRIx64
 		 " --stop-address=0x%016" PRIx64
-		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s|expand",
+		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s: |expand",

Are you sure this works as you expect? I.e. both lines will have '%s:'

Yes, if we do, we can exactly the only below line without the side effect IMHO.

Quoted 2 lines

yeah, because the .c is not there, ok gotcha, will get your new commit log message, massage it a bit and apply the patch.

Nah, with all this in mind, the original message is good enough, sorry for the confusion with the .c and the space after ':' (that I removed, needless and potentially confusing, as we saw here).

- Arnaldo

Em Mon, Mar 20, 2017 at 11:56:57AM +0900, Taeung Song escreveu:

Quoted 39 lines

grep -v "file name" in the objdump command cause a side effect eliminating filename:linenr of output of 'objdump -l' if the object file name and source file name are about the same so fix it.

The objdump command in symbol__disassemble() can be as below

    $ objdump -l -d -S -C /home/taeung/hello --start-address=...

    /home/taeung/hello:     file format elf64-x86-64

    Disassembly of section .text:

    0000000000400526 <main>:
    main():
    /home/taeung/hello.c:4

    void main()
    {
      400526:	55                   	push   %rbp
      400527:	48 89 e5             	mov    %rsp,%rbp
    /home/taeung/hello.c:5
    ...

But currently it use grep -v "file name" e.g. "/home/taeung/hello" in the objdump command to remove the first line containing file name and file format such as,

Before:

    $ objdump -l -d -S -C /home/taeung/hello | grep /home/taeung/hello

But it cause a side effect removing filename:linenr because the object file and source file has same name e.g. "/home/taueng/hello", "/home/taeung/hello.c"

So more exactly grep -v as below
to correctly remove the one line
e.g. "/home/taeung/hello: file format elf64-x86-64"

Quoted 2 lines

After:

    $ objdump -l -d -S -C /home/taeung/hello | grep /home/taeung/hello:

What environment is this? I tried to reproduce this here but got different results, and I had to figure out the 'perf record' you used, you forgot to mention it, i.e. 'perf record ./hello' doesn't work, one has to use 'perf record /full/path/to/hello', anyway, with my

environemnt, which is:

[root@jouet ~]# objdump -v
GNU objdump version 2.26.1-1.fc25

I end up getting:

Sorted summary for file /home/acme/c/hello
----------------------------------------------

   52.67 hello.c:7
   47.32 hello.c:8
 Percent |      Source code & Disassembly of hello for cycles:u (83555 samples)
-------------------------------------------------------------------------------
         :      00000000004004f6 <main>:
         :      main():
         :      #include <stdio.h>
         :
         :      int main(void)
         :      {
    0.00 :        4004f6:       push   %rbp
    0.00 :        4004f7:       mov    %rsp,%rbp
    0.00 :        4004fa:       sub    $0x10,%rsp
         :              unsigned long long i;
         :              printf("hello, world\n");
    0.00 :        4004fe:       mov    $0x4005d0,%edi
    0.00 :        400503:       callq  4003f0 <puts@plt>
         :              while (i < (unsigned long long)-1) {
    0.00 :        400508:       jmp    40052d <main+0x37>
         :                      i *= 171;
 hello.c:8    8.66 :      40050a:       mov    -0x8(%rbp),%rdx
    0.01 :        40050e:       mov    %rdx,%rax
    0.00 :        400511:       shl    $0x3,%rax
 hello.c:8    0.84 :      400515:       add    %rdx,%rax
 hello.c:8    8.60 :      400518:       add    %rax,%rax
 hello.c:8    3.46 :      40051b:       add    %rdx,%rax
 hello.c:8    8.57 :      40051e:       lea    0x0(,%rax,8),%rdx
    8.65 :        400526:       add    %rdx,%rax
    8.56 :        400529:       mov    %rax,-0x8(%rbp)

<SNIP>

Which looks ok, i.e. since this version of objdump puts just the basename (hello.c), that grep doesn't nuke it.

But yeah, your patch is more robust, just fix what I described below, i.e. use quotes in the grep -v bit, probably.

- Arnaldo

Quoted 7 lines

Cc Namhyung Kim <[email protected]>

Cc Jiri Olsa <[email protected]>

Signed-off-by Taeung Song <[email protected]>

---
 tools/perf/util/annotate.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

tools/perf/util/annotate.c int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na · line 1446

Quoted 10 lines

tools/perf/util/annotate.c +1 -1

index 63130ec..e49eb7e 100644
@@ -1443,7 +1443,7 @@ int symbol__disassemble(struct symbol *sym, struct map *map, const char *arch_na
 	snprintf(command, sizeof(command),
 		 "%s %s%s --start-address=0x%016" PRIx64
 		 " --stop-address=0x%016" PRIx64
-		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s|expand",
+		 " -l -d %s %s -C %s 2>/dev/null|grep -v %s: |expand",

Are you sure this works as you expect? I.e. both lines will have '%s:'

that space just before the '|' will not be considered by grep