Mailing List Archive

Em Mon, Mar 20, 2017 at 11:56:55AM +0900, Taeung Song escreveu:
> 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


> 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 <namhyung@kernel.org>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Signed-off-by: Taeung Song <treeze.taeung@gmail.com>
> ---
> tools/perf/util/annotate.c | 10 +++++++---
> 1 file changed, 7 insertions(+), 3 deletions(-)
>
> diff --git a/tools/perf/util/annotate.c b/tools/perf/util/annotate.c
> index fc91c6b..9bb43cd 100644
> --- a/tools/perf/util/annotate.c
> +++ b/tools/perf/util/annotate.c
> @@ -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

On 03/21/2017 03:15 AM, Arnaldo Carvalho de Melo wrote:
> Em Mon, Mar 20, 2017 at 11:56:55AM +0900, Taeung Song escreveu:
>> 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
>
>
>> 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 <namhyung@kernel.org>
>> Cc: Jiri Olsa <jolsa@redhat.com>
>> Signed-off-by: Taeung Song <treeze.taeung@gmail.com>
>> ---
>> tools/perf/util/annotate.c | 10 +++++++---
>> 1 file changed, 7 insertions(+), 3 deletions(-)
>>
>> diff --git a/tools/perf/util/annotate.c b/tools/perf/util/annotate.c
>> index fc91c6b..9bb43cd 100644
>> --- a/tools/perf/util/annotate.c
>> +++ b/tools/perf/util/annotate.c
>> @@ -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

On 03/21/2017 07:11 AM, Taeung Song wrote:
> 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
>
> On 03/21/2017 03:15 AM, Arnaldo Carvalho de Melo wrote:
>> Em Mon, Mar 20, 2017 at 11:56:55AM +0900, Taeung Song escreveu:
>>> 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
>>
>>
>>> 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 <namhyung@kernel.org>
>>> Cc: Jiri Olsa <jolsa@redhat.com>
>>> Signed-off-by: Taeung Song <treeze.taeung@gmail.com>
>>> ---
>>> tools/perf/util/annotate.c | 10 +++++++---
>>> 1 file changed, 7 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/tools/perf/util/annotate.c b/tools/perf/util/annotate.c
>>> index fc91c6b..9bb43cd 100644
>>> --- a/tools/perf/util/annotate.c
>>> +++ b/tools/perf/util/annotate.c
>>> @@ -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:
> 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.

Thanks,

- Arnaldo


> 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
>
> On 03/21/2017 07:11 AM, Taeung Song wrote:
> > 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
> >
> > On 03/21/2017 03:15 AM, Arnaldo Carvalho de Melo wrote:
> > > Em Mon, Mar 20, 2017 at 11:56:55AM +0900, Taeung Song escreveu:
> > > > 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
> > >
> > >
> > > > 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 <namhyung@kernel.org>
> > > > Cc: Jiri Olsa <jolsa@redhat.com>
> > > > Signed-off-by: Taeung Song <treeze.taeung@gmail.com>
> > > > ---
> > > > tools/perf/util/annotate.c | 10 +++++++---
> > > > 1 file changed, 7 insertions(+), 3 deletions(-)
> > > >
> > > > diff --git a/tools/perf/util/annotate.c b/tools/perf/util/annotate.c
> > > > index fc91c6b..9bb43cd 100644
> > > > --- a/tools/perf/util/annotate.c
> > > > +++ b/tools/perf/util/annotate.c
> > > > @@ -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 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

Hi,

On 03/21/2017 11:21 PM, Arnaldo Carvalho de Melo wrote:
> 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.
>

Okey, I found the cause about -nan and sent this patch to you.

But do you want to get other way to fix this problem ?
instead of this patch ?

Or change the commit message ?

Thanks,
Taeung

On 03/21/2017 11:21 PM, Arnaldo Carvalho de Melo wrote:
> 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.

The reason is the below if statement at util/annotate.c:910.

881 double disasm__calc_percent(struct annotation *notes, int evidx, s64
offset,
...
904 struct sym_hist *h = annotation__histogram(notes,
evidx);
905 unsigned int hits = 0;
906
907 while (offset < end)
908 hits += h->addr[offset++];
909
910 if (h->sum) {
911 *nr_samples = hits;
912 percent = 100.0 * hits / h->sum;
913 }
914 }

The if statement 'if (h->sum)' prevent division by zero, so all is well.

So I sent this patch because of same reason
adding the if statement 'if (h->sum)' in symbol__get_source_line().

But will resend v2 with more clearly commit log message!
I think previous log message is a bit insufficient..

Thanks,
Taeung

>
> 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
>