Неправильные следы Perf - PullRequest
       111

Неправильные следы Perf

1 голос
/ 20 марта 2020

Я использовал 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() звонки ‍‍‍ g_action_group_query_action() со смещением 0x64 (т.е. 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() вызывает g_action_group_query_action() со смещением 0x6c (т.е. 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() вызовов g_action_group_query_action() со смещением 0xac (т. Е. 172 в десятичном виде):

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

Как видно, ни один из них не соответствует зарегистрированному обратному следу. Возникает ли проблема, когда Perf пытается сопоставить имена функций с адресами или адреса сами по себе неверны? Как я могу исправить проблему?

1 Ответ

1 голос
/ 09 апреля 2020

Встроенные и оптимизированные оконечные вызовы - это два отдельных способа, чтобы вызовы в источнике C не появлялись в обратном следе стека времени выполнения.

Встроенная функция приведет к тому, что вызовы ее дочерних элементов будут происходить непосредственно из родительский элемент, в который он встроен, причем эта функция вообще не отображается.

Разумеется, возможно несколько уровней встраивания, что характерно для небольших функций.


Функция, заканчивающаяся на Оптимизированный jmp tailcall заставляет его выглядеть так, как будто вызываемый абонент был вызван непосредственно из его родителя. Вместо создания нового стекового фрейма ниже своего собственного, он разбирает свой собственный стековый фрейм и переходит к целевой функции, а адрес возврата все еще там. Таким образом, стековый фрейм новой функции будет использовать ту же память, которая ранее использовалась функцией, которая выполняла вызов хвоста.

Другими словами, любая последовательность call func; ret может быть заменена на jmp func. Это работает, даже если целью jmp является (заглушка plt для) библиотечной функции или косвенная цель call/jmp *printf@GOTPCREL(%rip) для кодекса стиля gcc -fno-plt.

См. Также 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, поэтому, когда leaf в конечном итоге вернется, оно будет непосредственно к bar.

Это работает с аргументами и возвращаемыми значениями, особенно с регистрами аргументов. Не всегда с аргументами стека, например, это невозможно, если leaf имеет больше аргументов стека, чем foo.

...