lazy frame push causes wrong call graph
I've observed an anomaly in call chain recording that appears to be attributable to gcc's [mis]handling of frame pointers, and would appreciate any feedback from perf maintainers or long-time users on whether this is a new problem, a known issue, or some mistake on my part.
Context:
x86_64
Linux mainline kernel version 3.6.7
gcc version 4.7.2
When the attached test program is compiled with
gcc -std=gnu99 -O0 -g -fno-omit-frame-pointer -o val4_O0 val4.c
and profiled with
perf record -e cpu-cycles -c 1000000 -g ./val4_O0
the report is as expected:
50.11% val4_O0 val4_O0 [.] fn1
|
--- fn1
fn2
main
__libc_start_main
49.17% val4_O0 val4_O0 [.] fn2
|
--- fn2
main
__libc_start_mainHowever, when the program is instead compiled with
gcc -std=gnu99 -O1 -g -fno-omit-frame-pointer -o val4_O1 val4.c
main disappears from half of the call chains:
49.72% val4_O1 val4_O1 [.] fn1
|
--- fn1
fn2
main
__libc_start_main
49.68% val4_O1 val4_O1 [.] fn2
|
--- fn2
__libc_start_mainDownstream impact includes incorrect accounting of total time by gprof2dot, as shown in the attached dot graphs.
Reviewing the disassemblies of fn2 (attached), I gather that the critical change was the movement of push %rbp from the top of the function down to just before the call of fn1.
OProfile documents the known issue that samples taken before the call frame is constructed will have an anomalous call chain
(http://oprofile.sourceforge.net/doc/interpreting-callgraph.html), but what happened here seems worse than par for that course. The "untimely" sampling occurs as the rule rather than the exception. In the absence of any further information, I'd be inclined to say that gcc broke the contract for what no-omit-frame-pointer should do. Yes, the frame pointer is there, but it's managed in a way that defeats the purpose (or at least, perf's purpose).
Thanks for any feedback on whether this a gcc bug, old news, or a mistake on my part,
Signature · 1 line
David Flater, National Institute of Standards and Technology, U.S.A.
/* val4.c 2012-12-07 09:26
Reference executable for demonstrating perf call graph anomaly.
The expected distribution of time is approximately
main total 100% self 0%
fn2 total 100% self 50%
fn1 total 50% self 50% Language -std=gnu99 (with gcc-specific attributes). Original versions tested: x86_64, gcc 4.7.2, mainline kernel 3.6.7.
*/
#ifndef INNERLOOP
#define INNERLOOP 100000000
#endif
#include <inttypes.h>
#include <math.h>
#include <stdio.h>
uint64_t accumulator=1;
double adder=0;
void fn1() __attribute__((noinline));
void fn2() __attribute__((noinline));
void fn1() {
for (uint64_t looper=0; looper<INNERLOOP; ++looper)
adder += M_PI*3, accumulator = accumulator*3 + adder; }
void fn2() {
for (uint64_t looper=0; looper<INNERLOOP; ++looper)
adder += M_PI*3, accumulator = accumulator*3 + adder;
fn1();
}
int main() {
fn2();
printf ("%" PRIu64 " %f\n", accumulator, adder); return 0;
}
val4_O0: file format elf64-x86-64
00000000004005d1 <fn2>:
4005d1: push %rbp 4005d2: mov %rsp,%rbp 4005d5: sub $0x10,%rsp 4005d9: movq $0x0,-0x8(%rbp) 4005e1: jmpq 40067a <fn2+0xa9> 4005e6: movsd 0x200532(%rip),%xmm1 # 600b20 <adder> 4005ee: movsd 0x1e2(%rip),%xmm0 # 4007d8 <_IO_stdin_used+0x10> 4005f6: addsd %xmm1,%xmm0 4005fa: movsd %xmm0,0x20051e(%rip) # 600b20 <adder> 400602: mov 0x2004ff(%rip),%rdx # 600b08 <accumulator> 400609: mov %rdx,%rax 40060c: add %rax,%rax 40060f: add %rdx,%rax 400612: test %rax,%rax 400615: js 40061e <fn2+0x4d> 400617: cvtsi2sd %rax,%xmm0 40061c: jmp 400633 <fn2+0x62> 40061e: mov %rax,%rdx 400621: shr %rdx 400624: and $0x1,%eax 400627: or %rax,%rdx 40062a: cvtsi2sd %rdx,%xmm0 40062f: addsd %xmm0,%xmm0 400633: movsd 0x2004e5(%rip),%xmm1 # 600b20 <adder> 40063b: addsd %xmm1,%xmm0 40063f: ucomisd 0x199(%rip),%xmm0 # 4007e0 <_IO_stdin_used+0x18> 400647: jae 400650 <fn2+0x7f> 400649: cvttsd2si %xmm0,%rax 40064e: jmp 40066e <fn2+0x9d> 400650: movsd 0x188(%rip),%xmm1 # 4007e0 <_IO_stdin_used+0x18> 400658: subsd %xmm1,%xmm0 40065c: cvttsd2si %xmm0,%rax 400661: movabs $0x8000000000000000,%rdx 40066b: xor %rdx,%rax 40066e: mov %rax,0x200493(%rip) # 600b08 <accumulator> 400675: addq $0x1,-0x8(%rbp) 40067a: cmpq $0x5f5e0ff,-0x8(%rbp) 400682: jbe 4005e6 <fn2+0x15> 400688: mov $0x0,%eax 40068d: callq 40051c <fn1>
400692: leaveq
400693: retq
val4_O1: file format elf64-x86-64
00000000004005af <fn2>:
4005af: movsd 0x200511(%rip),%xmm0 # 600ac8 <adder> 4005b7: mov 0x2004f2(%rip),%rax # 600ab0 <accumulator> 4005be: mov $0x5f5e100,%edx 4005c3: movsd 0x1ad(%rip),%xmm3 # 400778 <_IO_stdin_used+0x10> 4005cb: movsd 0x1ad(%rip),%xmm2 # 400780 <_IO_stdin_used+0x18> 4005d3: movapd %xmm2,%xmm4 4005d7: movabs $0x8000000000000000,%rsi 4005e1: addsd %xmm3,%xmm0 4005e5: lea (%rax,%rax,2),%rax 4005e9: test %rax,%rax 4005ec: js 4005f5 <fn2+0x46> 4005ee: cvtsi2sd %rax,%xmm1 4005f3: jmp 40060a <fn2+0x5b> 4005f5: mov %rax,%rcx 4005f8: shr %rcx 4005fb: and $0x1,%eax 4005fe: or %rax,%rcx 400601: cvtsi2sd %rcx,%xmm1 400606: addsd %xmm1,%xmm1 40060a: addsd %xmm0,%xmm1 40060e: ucomisd %xmm2,%xmm1 400612: jae 40061b <fn2+0x6c> 400614: cvttsd2si %xmm1,%rax 400619: jmp 400627 <fn2+0x78> 40061b: subsd %xmm4,%xmm1 40061f: cvttsd2si %xmm1,%rax 400624: xor %rsi,%rax 400627: sub $0x1,%rdx 40062b: jne 4005e1 <fn2+0x32> 40062d: push %rbp 40062e: mov %rsp,%rbp 400631: movsd %xmm0,0x20048f(%rip) # 600ac8 <adder> 400639: mov %rax,0x200470(%rip) # 600ab0 <accumulator> 400640: mov $0x0,%eax 400645: callq 40051c <fn1> 40064a: pop %rbp
40064b: retq