错误的性能回溯答案

【问题标题】：Wrong Perf Backtraces错误的性能回溯
【发布时间】：2020-07-01 02:39:00
【问题描述】：

我使用Perf 在evince 基准测试中提取调用图。使用的命令如下：

sudo perf record -d --call-graph dwarf -c 10000 -e mem_load_uops_retired.l3_miss:uppp /opt/evince-3.28.4/bin/evince

我使用Perf script 提取了回溯，发现有许多损坏的回溯实例。有些包含重复的冗余函数调用，例如：

EvJobScheduler 10021  8653.926478:        100 mem_load_uops_retired.l3_miss:uppp:     7fffd1062a00         5080022 N/A|SNP N/A|TLB N/A|LCK N/A
   7ffff4b07207 tcache_get+0x197 (inlined)
   7ffff4b07207 __GI___libc_malloc+0x197 (inlined)
   7fffd9872fb9 gmalloc+0x59 (inlined)
   7fffd9872fb9 gmallocn+0x59 (/usr/lib/x86_64-linux-gnu/libpoppler.so.73.0.0)
   7fffd9872fb9 gmallocn+0x59 (/usr/lib/x86_64-linux-gnu/libpoppler.so.73.0.0)
   7fffd9951e6f _ZN8TextLine8coalesceEP10UnicodeMap+0xff (/usr/lib/x86_64-linux-gnu/libpoppler.so.73.0.0)
   7fffd9952f82 _ZN9TextBlock8coalesceEP10UnicodeMapd+0x752 (/usr/lib/x86_64-linux-gnu/libpoppler.so.73.0.0)
   7fffd995bc37 _ZN8TextPage8coalesceEbdb+0x1507 (/usr/lib/x86_64-linux-gnu/libpoppler.so.73.0.0)
   7fffd995cb71 _ZN13TextOutputDev7endPageEv+0x31 (/usr/lib/x86_64-linux-gnu/libpoppler.so.73.0.0)
   7fffe803c6d2 _ZL26poppler_page_get_text_pageP12_PopplerPage+0x92 (/usr/lib/x86_64-linux-gnu/libpoppler-glib.so.8.9.0)
   7fffe803deb3 poppler_page_get_selection_region+0x63 (/usr/lib/x86_64-linux-gnu/libpoppler-glib.so.8.9.0)
   7fffe82ab650 [unknown] (/opt/evince-3.28.4/lib/evince/4/backends/libpdfdocument.so)
   7ffff795f165 ev_job_page_data_run+0x2f5 (/opt/evince-3.28.4/lib/libevview3.so.3.0.0)
   7ffff7961309 ev_job_thread+0xe9 (inlined)
   7ffff7961309 ev_job_thread_proxy+0xe9 (/opt/evince-3.28.4/lib/libevview3.so.3.0.0)
   7ffff5492194 g_thread_proxy+0x54 (/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0.5600.4)
   7ffff4e686da start_thread+0xda (/lib/x86_64-linux-gnu/libpthread-2.27.so)
   7ffff4b9188e __GI___clone+0x3e (inlined)

有两个连续的gmallocs() 这是不正确的。有些是函数调用是调用者和被调用者不匹配，例如：

evince 10015  8640.962182:        100 mem_load_uops_retired.l3_miss:uppp:     7fffdc005030         5080022 N/A|SNP N/A|TLB N/A|LCK N/A
   7ffff5a3275f g_action_get_enabled+0x3f (/usr/lib/x86_64-linux-gnu/libgio-2.0.so.0.5600.4)
   7ffff5a2ffcc g_simple_action_group_query_action+0x3c (/usr/lib/x86_64-linux-gnu/libgio-2.0.so.0.5600.4)
   7ffff7130d8c gtk_action_muxer_query_action+0xac (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff7130d4c gtk_action_muxer_query_action+0x6c (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff7130d4c gtk_action_muxer_query_action+0x6c (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff7130d4c gtk_action_muxer_query_action+0x6c (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff7130d4c gtk_action_muxer_query_action+0x6c (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff7130994 gtk_action_muxer_action_added+0x64 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff574510c g_closure_invoke+0x19c (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff575805d signal_emit_unlocked_R+0xf4d (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff5760714 g_signal_emit_valist+0xa74 (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff576112e g_signal_emit+0x8e (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff71309e2 gtk_action_muxer_action_added+0xb2 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff574510c g_closure_invoke+0x19c (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff575805d signal_emit_unlocked_R+0xf4d (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff5760714 g_signal_emit_valist+0xa74 (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff576112e g_signal_emit+0x8e (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff71309e2 gtk_action_muxer_action_added+0xb2 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff574510c g_closure_invoke+0x19c (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff575805d signal_emit_unlocked_R+0xf4d (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff5760714 g_signal_emit_valist+0xa74 (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff576112e g_signal_emit+0x8e (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff71309e2 gtk_action_muxer_action_added+0xb2 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff574510c g_closure_invoke+0x19c (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff575805d signal_emit_unlocked_R+0xf4d (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff5760714 g_signal_emit_valist+0xa74 (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff576112e g_signal_emit+0x8e (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff71309e2 gtk_action_muxer_action_added+0xb2 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff7131482 gtk_action_muxer_set_parent+0x1d2 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff73c46f8 gtk_widget_set_parent+0x198 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   7ffff73d0228 gtk_window_set_titlebar+0xb8 (/usr/lib/x86_64-linux-gnu/libgtk-3.so.0.2200.30)
   55555558d391 ev_window_init+0x2e1 (/opt/evince-3.28.4/bin/evince)
   7ffff57699c4 g_type_create_instance+0x1e4 (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff574a747 g_object_new_internal+0x2e7 (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff574c5bf g_object_new_valist+0x3cf (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   7ffff574c938 g_object_new+0x98 (/usr/lib/x86_64-linux-gnu/libgobject-2.0.so.0.5600.4)
   55555558f192 ev_window_new+0x42 (/opt/evince-3.28.4/bin/evince)
   5555555778f4 ev_application_open_recent_view+0x14 (/opt/evince-3.28.4/bin/evince)
   555555573733 load_files+0x473 (inlined)
   555555573733 main+0x473 (/opt/evince-3.28.4/bin/evince)
   7ffff4a91b96 __libc_start_main+0xe6 (/lib/x86_64-linux-gnu/libc-2.27.so)
   555555573899 _start+0x29 (/opt/evince-3.28.4/bin/evince)

这是错误的，因为：

1) gtk_action_muxer_action_added() 在偏移量0x64 处调用 ‍‍‍g_action_group_query_action()（即十进制的100）：

0x00000000000f898f <+95>:   push   %rax
0x00000000000f8990 <+96>:   callq  0x84e20 <g_action_group_query_action@plt>
0x00000000000f8995 <+101>:  test   %eax,%eax

2) gtk_action_muxer_query_action() 在偏移量0x6c 处调用g_action_group_query_action()（即十进制的108）：

0x00000000000f8d45 <+101>:  mov    %rbp,%rsi
0x00000000000f8d48 <+104>:  callq  0x84e20 <g_action_group_query_action@plt>
0x00000000000f8d4d <+109>:  pop    %rdx

3) gtk_action_muxer_query_action() 在偏移量0xac 处调用g_action_group_query_action()（即十进制的172）：

0x00000000000f8d85 <+165>:  mov    %r12,%rdx
0x00000000000f8d88 <+168>:  callq  0x84e20 <g_action_group_query_action@plt>
0x00000000000f8d8d <+173>:  pop    %rsi

可以看出，这些都与报告的回溯不匹配。当Perf 尝试将函数名称与地址匹配，或者地址错误时，是否会出现问题？如何修改问题？

【问题讨论】：

相对 call 是一个 5 字节的指令。 <+96>: callq 0x84e20 <g_action_group_query_action@plt> 的返回地址为 +101 或 +0x65，而不是 +100。即反汇编中test 指令的开始。对于您的实际问题，我没有答案，并且与回溯的匹配程度更低，但是除非我忘记了回溯通常如何与呼叫地址匹配，否则它看起来像是对问题中该细节的错误陈述。
映射正确。它们与普通执行的完全匹配。地址匹配符号（即每个单行都是正确的），但如上所示，一些调用者和被调用者确实不匹配。可能是Perf漏掉了中间的一些功能。奇怪的是，在所有运行中，问题都发生在相同的地方。
内联等优化是在编译时进行的；这将导致调用链的运行时可见部分肯定会跳过源中出现的一些调用。每次执行都会得到相同的结果并不奇怪，但它可能确实排除了某些奇怪的情况。对不起IDK了。
优化的尾调用也会影响回溯。 jmp func@plt 而不是 call func@plt; ret 使目标看起来像是由 your 父函数直接调用的。
re: gcc -fno-plt 内联间接调用而不是调用 PLT 存根的样式代码生成：请参阅 How can I call printf normally in assembly without @PLT but just call printf with -l option in gcc with standard library, / 32-bit absolute addresses no longer allowed in x86-64 Linux? / web.archive.org/web/20171111043629/http://www.macieira.org/blog/…。这与回溯或尾调用优化正交。

标签： linux disassembly callstack perf backtrace

【解决方案1】：

内联和优化尾调用是 C 源代码中的调用不会出现在运行时堆栈回溯中的两种不同方式。

内联函数将导致直接从其内联到的父级调用其子级，而此函数根本不会出现。

多层次的内联当然是可能的，并且在小函数中很常见。

以优化的jmp tailcall 结尾的函数使它看起来像被调用者是直接从其父级调用的。它没有在自己的下面创建一个新的堆栈帧，而是拆除自己的堆栈帧并跳转到目标函数，返回地址仍然存在。这样新函数的堆栈帧将使用与之前进行尾调用的函数相同的内存。

换句话说，任何call func; ret 序列都可以替换为jmp func。即使 jmp 目标是库函数的（plt 存根）或gcc -fno-plt 样式代码生成的间接call/jmp *printf@GOTPCREL(%rip) 目标，这也有效。

另见https://en.wikipedia.org/wiki/Tail_call

例如

void leaf();  // some other function
void foo() { stuff; ...;   leaf(); }    // ends with a tailcall
void bar() { stuff; foo(); stuff; }

foo 正在执行“工作”时触发的事件将具有 bar->foo 的回溯。

如果没有优化，在 "leaf" 中触发的事件将具有类似 bar->foo->leaf 的回溯。

使用优化的尾调用，它将是 bar->leaf，没有 foo，因为 foo 刚刚跳转到叶子，将其返回地址转发到 leaf，所以当 leaf 最终返回时，它将直接到 bar。

这适用于参数和返回值，尤其是寄存器参数。并不总是使用堆栈参数，例如，如果 leaf 的堆栈参数比 foo 多，这是不可能的。

【讨论】：

确实，gmallocn()s 是内联的，但不幸的是，Perf 没有直接表达它（这与Perf 的正常行为不一致）。第二种情况（重复gtk_action_muxer_query_action()s）是尾调用消除。换句话说，被调用者gtk_action_muxer_query_action+0x6c 的最后一个操作是跳转到gtk_action_muxer_query_action() 的开头。
@TheAhmad：在查看您的原始问题和评论时，我已经知道尾调用和内联。 IIRC 似乎有些调用显然来自不是调用指令的某个地方，因此您不会期望返回地址指向那里。是的，my very first comment 是关于返回地址中的一个错误。
@TheAhmad: call 推送下一条指令的地址作为返回地址。 felixcloutier.com/x86/call。（一条指令执行期间的 RIP 是下一条指令的地址，也就是调用指令本身的末尾。）ret 只是 RIP 中的一个弹出窗口；这是到该地址的间接跳转（通常由call 推送）。一个接一个是不正常的。它应该正好是下一条指令，因为这是调用返回后应该执行的指令。
我在一台新安装的 Ubuntu 18.04` 机器上检查了 off-by-1 错误（类似于我的真机），错误也在那里。我在带有 mainline linux kernel 4.x.x 的 16.04 来宾操作系统中检查了这个问题。输出格式不同，存在 no off-by-1 错误。也许，Perf 的较新版本中存在错误。
@PeterCordes - 仅供参考，perf 可以在某些模式下报告内联函数，例如 DWARF 展开，因为 DWARF 信息可以指示类似“此 IP 对应于函数 a() 内联到 b()”，在这种情况下，perf 可以在堆栈中发出 a() 和 b()，即将一个物理堆栈帧展开为多个显示的堆栈帧。