lkml.org 
[lkml]   [2012]   [Jan]   [26]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectShift by one instruction in the perf annotate output
Date
Hello,

Using perf and zooming up to the annotated assembler, I noticed a “shift by
one” issue between the assembler instructions and the reported consumed cycles
in the left margin.
Each time a given instruction is expensive, the high event count appears on
the line right after.
In order to validate that feeling, I tried to put an expensive instruction
(division) inside a block of cheaper instructions (no operation). And here is
the output of perf annotate:

0,00 : 40041d: nop
0,00 : 40041e: nop
5,31 : 40041f: nop
0,00 : 400420: divl (%rsp)
84,18 : 400423: nop
0,00 : 400424: nop
0,07 : 400425: nop

I would have expected the 84,18 count to be in front of the “divl” instruction
and not in front of the “nop” one.

I am running Linux and perf 3.2 but I remember that previous versions suffered
from the same issue.

I don’t know if it could be specific to my cpu:
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 15
model name : Intel(R) Core(TM)2 CPU 6600 @ 2.40GHz
stepping : 6
microcode : 0xd0
cpu MHz : 2394.000
cache size : 4096 KB
physical id : 0
siblings : 2
core id : 0
cpu cores : 2
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 10
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca
cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx lm
constant_tsc arch_perfmon pebs bts rep_good nopl aperfmperf pni dtes64 monitor
ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm lahf_lm dts tpr_shadow
bogomips : 4807.89
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:

This issue is not specific to the perf tool itself since I observe exactly the
same thing with OProfile.
Here is the output of opannotate for the same piece of code:

: 40041d: nop
: 40041e: nop
971 0.5636 : 40041f: nop
1 5.8e-04 : 400420: divl (%rsp)
165045 95.7904 : 400423: nop
4 0.0023 : 400424: nop
18 0.0104 : 400425: nop

Once again, the high number of samples should have been collected in “divl”
and not in “nop”.


Here is the small program I used to observe that phenomenon (x86(-64)
specific):

#include <stdlib.h>
#include <stdio.h>

void divide( int dividend,
int divisor,
int *quotient,
int *remainder )
{
for( unsigned i = 0 ; i < 1000000000 ; i++ )
__asm__ __volatile__
( "xor %%edx,%%edx;"
"nop;"
"nop;"
"nop;"
"divl %[divisor];"
"nop;"
"nop;"
"nop;"
: "=a" (*quotient), "=&d" (*remainder)
: "a" (dividend), [divisor] "m" (divisor)
);
}

int main()
{
int quotient, remainder;
divide( 1234, 100, &quotient, &remainder );
printf( "%d = %d x %d + %d\n", 1234, 100, quotient, remainder );
return EXIT_SUCCESS;
}

$ gcc -pipe -o div div.c -std=c99 -O3
$ perf record -g ./div
$ perf report -g
$ perf annotate main # -O3 made divide() inlined
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

\
 
 \ /
  Last update: 2012-01-27 00:31    [W:0.279 / U:0.020 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site