From: David Flater Subject: lazy frame push causes wrong call graph Date: Fri, 7 Dec 2012 13:59:19 -0500 Message-ID: <50C23C87.6030201@nist.gov> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="------------080007060400030802080304" Return-path: Received: from wsget1.nist.gov ([129.6.13.150]:45711 "EHLO wsget1.nist.gov" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751745Ab2LGTEz (ORCPT ); Fri, 7 Dec 2012 14:04:55 -0500 Sender: linux-perf-users-owner@vger.kernel.org List-ID: To: Perf Users --------------080007060400030802080304 Content-Type: text/plain; charset="ISO-8859-1" Content-Transfer-Encoding: 7bit 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_main However, 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_main Downstream 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, -- David Flater, National Institute of Standards and Technology, U.S.A. --------------080007060400030802080304 Content-Type: text/plain; charset="windows-1252"; name="val4.c" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="val4.c" /* 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 #include #include uint64_t accumulator=1; double adder=0; void fn1() __attribute__((noinline)); void fn2() __attribute__((noinline)); void fn1() { for (uint64_t looper=0; looper: 4005d1: push %rbp 4005d2: mov %rsp,%rbp 4005d5: sub $0x10,%rsp 4005d9: movq $0x0,-0x8(%rbp) 4005e1: jmpq 40067a 4005e6: movsd 0x200532(%rip),%xmm1 # 600b20 4005ee: movsd 0x1e2(%rip),%xmm0 # 4007d8 <_IO_stdin_used+0x10> 4005f6: addsd %xmm1,%xmm0 4005fa: movsd %xmm0,0x20051e(%rip) # 600b20 400602: mov 0x2004ff(%rip),%rdx # 600b08 400609: mov %rdx,%rax 40060c: add %rax,%rax 40060f: add %rdx,%rax 400612: test %rax,%rax 400615: js 40061e 400617: cvtsi2sd %rax,%xmm0 40061c: jmp 400633 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 40063b: addsd %xmm1,%xmm0 40063f: ucomisd 0x199(%rip),%xmm0 # 4007e0 <_IO_stdin_used+0x18> 400647: jae 400650 400649: cvttsd2si %xmm0,%rax 40064e: jmp 40066e 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 400675: addq $0x1,-0x8(%rbp) 40067a: cmpq $0x5f5e0ff,-0x8(%rbp) 400682: jbe 4005e6 400688: mov $0x0,%eax 40068d: callq 40051c 400692: leaveq 400693: retq --------------080007060400030802080304 Content-Type: text/plain; charset="windows-1252"; name="O1_disassembly.txt" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="O1_disassembly.txt" val4_O1: file format elf64-x86-64 00000000004005af : 4005af: movsd 0x200511(%rip),%xmm0 # 600ac8 4005b7: mov 0x2004f2(%rip),%rax # 600ab0 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 4005ee: cvtsi2sd %rax,%xmm1 4005f3: jmp 40060a 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 400614: cvttsd2si %xmm1,%rax 400619: jmp 400627 40061b: subsd %xmm4,%xmm1 40061f: cvttsd2si %xmm1,%rax 400624: xor %rsi,%rax 400627: sub $0x1,%rdx 40062b: jne 4005e1 40062d: push %rbp 40062e: mov %rsp,%rbp 400631: movsd %xmm0,0x20048f(%rip) # 600ac8 400639: mov %rax,0x200470(%rip) # 600ab0 400640: mov $0x0,%eax 400645: callq 40051c 40064a: pop %rbp 40064b: retq --------------080007060400030802080304--