Linux Perf: различия между версиями

Материал из noname.com.ua
Перейти к навигацииПерейти к поиску
Строка 32: Строка 32:
 
</PRE>
 
</PRE>
 
* Опция -g fractal нужна для того, чтобы проценты, отражающие количество сэмплов с этой функцией и показываемые perf, были относительны вызывающей функции, количество вызовов которой берется за 100%.
 
* Опция -g fractal нужна для того, чтобы проценты, отражающие количество сэмплов с этой функцией и показываемые perf, были относительны вызывающей функции, количество вызовов которой берется за 100%.
  +
  +
<PRE>
  +
Samples: 118K of event 'cycles', Event count (approx.): 496275267116
  +
Children Self Command Shared Object Symbol
  +
+ 70.97% 0.00% swapper [kernel.kallsyms] [k] secondary_startup_64_no_verify
  +
+ 70.96% 0.01% swapper [kernel.kallsyms] [k] cpu_startup_entry
  +
+ 70.83% 0.08% swapper [kernel.kallsyms] [k] do_idle
  +
+ 67.86% 0.12% swapper [kernel.kallsyms] [k] cpuidle_idle_call
  +
+ 66.49% 0.08% swapper [kernel.kallsyms] [k] cpuidle_enter
  +
+ 65.89% 0.78% swapper [kernel.kallsyms] [k] cpuidle_enter_state
  +
+ 61.02% 0.00% swapper [kernel.kallsyms] [k] start_secondary
  +
+ 53.46% 53.46% swapper [kernel.kallsyms] [k] mwait_idle_with_hints.constprop.0
  +
+ 9.95% 0.00% swapper [kernel.kallsyms] [k] x86_64_start_kernel
  +
+ 9.95% 0.00% swapper [kernel.kallsyms] [k] x86_64_start_reservations
  +
+ 9.95% 0.00% swapper [kernel.kallsyms] [k] start_kernel
  +
+ 9.95% 0.00% swapper [kernel.kallsyms] [k] arch_call_rest_init
  +
+ 9.95% 0.00% swapper [kernel.kallsyms] [k] rest_init
  +
+ 8.95% 0.01% swapper [kernel.kallsyms] [k] asm_common_interrupt
  +
+ 8.93% 0.06% swapper [kernel.kallsyms] [k] common_interrupt
  +
+ 8.12% 0.05% zabbix_server [kernel.kallsyms] [k] entry_SYSCALL_64_after_hwframe
  +
+ 8.02% 0.03% zabbix_server [kernel.kallsyms] [k] do_syscall_64
  +
+ 7.39% 0.00% zabbix_server [unknown] [k] 0x000000000000006c
  +
+ 7.39% 0.00% zabbix_server libevent-2.1.so.7.0.1 [.] 0x00007fdc2a024600
  +
+ 6.71% 0.04% swapper [kernel.kallsyms] [k] __common_interrupt
  +
+ 6.64% 0.00% zabbix_server [unknown] [.] 0x0000561ff32d3280
  +
+ 6.62% 0.05% swapper [kernel.kallsyms] [k] handle_edge_irq
  +
+ 6.60% 0.09% zabbix_server libc.so.6 [.] epoll_wait
  +
+ 6.45% 0.02% swapper [kernel.kallsyms] [k] handle_irq_event
  +
+ 6.34% 0.04% swapper [kernel.kallsyms] [k] __handle_irq_event_percpu
  +
+ 6.23% 0.04% swapper [kernel.kallsyms] [k] hrtimer_interrupt
  +
+ 5.63% 0.06% zabbix_server [kernel.kallsyms] [k] __x64_sys_epoll_wait
  +
+ 5.49% 0.05% zabbix_server [kernel.kallsyms] [k] do_epoll_wait
  +
+ 5.29% 0.10% zabbix_server [kernel.kallsyms] [k] ep_poll
  +
+ 5.22% 0.01% swapper [kernel.kallsyms] [k] hpet_msi_interrupt_handler
  +
+ 5.00% 0.02% zabbix_server [kernel.kallsyms] [k] schedule_hrtimeout_range
  +
+ 4.97% 0.06% zabbix_server [kernel.kallsyms] [k] schedule_hrtimeout_range_clock
  +
+ 4.19% 0.04% zabbix_server [kernel.kallsyms] [k] schedule
  +
+ 4.10% 0.12% zabbix_server [kernel.kallsyms] [k] __schedule
  +
+ 3.87% 0.00% mariadbd libc.so.6 [.] 0x00007fe8000cdac3
  +
+ 3.87% 0.00% mariadbd mariadbd [.] 0x000055b951d36a26
  +
+ 3.87% 0.00% mariadbd mariadbd [.] handle_one_connection
  +
+ 3.87% 0.00% mariadbd mariadbd [.] do_handle_one_connection
  +
+ 3.86% 0.01% mariadbd mariadbd [.] do_command
  +
+ 3.79% 0.03% swapper [kernel.kallsyms] [k] clockevents_program_event
  +
+ 3.76% 0.01% mariadbd mariadbd [.] dispatch_command
  +
+ 3.73% 3.73% swapper [kernel.kallsyms] [k] hpet_clkevt_set_next_event
  +
+ 3.69% 0.00% mariadbd mariadbd [.] mysql_parse
  +
+ 3.49% 0.01% swapper [kernel.kallsyms] [k] tick_program_event
  +
+ 3.46% 0.01% mariadbd mariadbd [.] mysql_execute_command
  +
+ 3.02% 0.00% mariadbd mariadbd [.] 0x000055b9518c29dc
  +
+ 3.02% 0.00% mariadbd mariadbd [.] handle_select
  +
+ 3.01% 0.00% mariadbd mariadbd [.] mysql_select
  +
+ 2.54% 0.00% mariadbd mariadbd [.] JOIN::exec
  +
+ 2.54% 0.00% mariadbd mariadbd [.] JOIN::exec_inner
  +
+ 2.54% 0.13% swapper [kernel.kallsyms] [k] __hrtimer_run_queues
  +
+ 2.50% 0.00% mariadbd mariadbd [.] sub_select
  +
</PRE>
   
 
=11=
 
=11=

Версия 13:15, 18 марта 2024

Linux perf

Поиск проблем в ядре, пример.

Авторы

  • Основное исследование провел Денис Миргородский (email to be added!), я сделал только некоторые незначительные дополнения и оформил эту доку.

Зачем это нужно ?

Иногда хочется понять, что вообще происходит с системой, в частности мы наблюдали примерно 30-процентное проседание скорости работы хранилища (в IOPS)
после обновления Compute Node (OpenStack) с ядра 5.4 до 5.15


Введение в perf

Для тестирования, просто что бы понимать какие данные можно получить, и как с ними работать, запускаю сбор данных на "просто сервере"

Сбор данных

perf record -a -F 99 -g
  • -a, --all-cpus - собрать данные со всех процессоров
  • -F, --freq= - частота, лучше выбирать нечетную что бы избежать ситуации когда регулярные события с происходящие частотой равной или кратной частоте семплирования, не будут записаны.
  • -g нужна для захвата стек трейсов
  • Результат будет записан в файл perf.data (не указано, это значение по-умолчанию)

Другие опции сбора можно подсмотреть например здесь: Хабр

Просмотр результатов

Посмотреть полученный результат можно командой:

perf report -g fractal
  • Опция -g fractal нужна для того, чтобы проценты, отражающие количество сэмплов с этой функцией и показываемые perf, были относительны вызывающей функции, количество вызовов которой берется за 100%.
Samples: 118K of event 'cycles', Event count (approx.): 496275267116
  Children      Self  Command          Shared Object                   Symbol
+   70.97%     0.00%  swapper          [kernel.kallsyms]               [k] secondary_startup_64_no_verify
+   70.96%     0.01%  swapper          [kernel.kallsyms]               [k] cpu_startup_entry
+   70.83%     0.08%  swapper          [kernel.kallsyms]               [k] do_idle
+   67.86%     0.12%  swapper          [kernel.kallsyms]               [k] cpuidle_idle_call
+   66.49%     0.08%  swapper          [kernel.kallsyms]               [k] cpuidle_enter
+   65.89%     0.78%  swapper          [kernel.kallsyms]               [k] cpuidle_enter_state
+   61.02%     0.00%  swapper          [kernel.kallsyms]               [k] start_secondary
+   53.46%    53.46%  swapper          [kernel.kallsyms]               [k] mwait_idle_with_hints.constprop.0
+    9.95%     0.00%  swapper          [kernel.kallsyms]               [k] x86_64_start_kernel
+    9.95%     0.00%  swapper          [kernel.kallsyms]               [k] x86_64_start_reservations
+    9.95%     0.00%  swapper          [kernel.kallsyms]               [k] start_kernel
+    9.95%     0.00%  swapper          [kernel.kallsyms]               [k] arch_call_rest_init
+    9.95%     0.00%  swapper          [kernel.kallsyms]               [k] rest_init
+    8.95%     0.01%  swapper          [kernel.kallsyms]               [k] asm_common_interrupt
+    8.93%     0.06%  swapper          [kernel.kallsyms]               [k] common_interrupt
+    8.12%     0.05%  zabbix_server    [kernel.kallsyms]               [k] entry_SYSCALL_64_after_hwframe
+    8.02%     0.03%  zabbix_server    [kernel.kallsyms]               [k] do_syscall_64
+    7.39%     0.00%  zabbix_server    [unknown]                       [k] 0x000000000000006c
+    7.39%     0.00%  zabbix_server    libevent-2.1.so.7.0.1           [.] 0x00007fdc2a024600
+    6.71%     0.04%  swapper          [kernel.kallsyms]               [k] __common_interrupt
+    6.64%     0.00%  zabbix_server    [unknown]                       [.] 0x0000561ff32d3280
+    6.62%     0.05%  swapper          [kernel.kallsyms]               [k] handle_edge_irq
+    6.60%     0.09%  zabbix_server    libc.so.6                       [.] epoll_wait
+    6.45%     0.02%  swapper          [kernel.kallsyms]               [k] handle_irq_event
+    6.34%     0.04%  swapper          [kernel.kallsyms]               [k] __handle_irq_event_percpu
+    6.23%     0.04%  swapper          [kernel.kallsyms]               [k] hrtimer_interrupt
+    5.63%     0.06%  zabbix_server    [kernel.kallsyms]               [k] __x64_sys_epoll_wait
+    5.49%     0.05%  zabbix_server    [kernel.kallsyms]               [k] do_epoll_wait
+    5.29%     0.10%  zabbix_server    [kernel.kallsyms]               [k] ep_poll
+    5.22%     0.01%  swapper          [kernel.kallsyms]               [k] hpet_msi_interrupt_handler
+    5.00%     0.02%  zabbix_server    [kernel.kallsyms]               [k] schedule_hrtimeout_range
+    4.97%     0.06%  zabbix_server    [kernel.kallsyms]               [k] schedule_hrtimeout_range_clock
+    4.19%     0.04%  zabbix_server    [kernel.kallsyms]               [k] schedule
+    4.10%     0.12%  zabbix_server    [kernel.kallsyms]               [k] __schedule
+    3.87%     0.00%  mariadbd         libc.so.6                       [.] 0x00007fe8000cdac3
+    3.87%     0.00%  mariadbd         mariadbd                        [.] 0x000055b951d36a26
+    3.87%     0.00%  mariadbd         mariadbd                        [.] handle_one_connection
+    3.87%     0.00%  mariadbd         mariadbd                        [.] do_handle_one_connection
+    3.86%     0.01%  mariadbd         mariadbd                        [.] do_command
+    3.79%     0.03%  swapper          [kernel.kallsyms]               [k] clockevents_program_event
+    3.76%     0.01%  mariadbd         mariadbd                        [.] dispatch_command
+    3.73%     3.73%  swapper          [kernel.kallsyms]               [k] hpet_clkevt_set_next_event
+    3.69%     0.00%  mariadbd         mariadbd                        [.] mysql_parse
+    3.49%     0.01%  swapper          [kernel.kallsyms]               [k] tick_program_event
+    3.46%     0.01%  mariadbd         mariadbd                        [.] mysql_execute_command
+    3.02%     0.00%  mariadbd         mariadbd                        [.] 0x000055b9518c29dc
+    3.02%     0.00%  mariadbd         mariadbd                        [.] handle_select
+    3.01%     0.00%  mariadbd         mariadbd                        [.] mysql_select
+    2.54%     0.00%  mariadbd         mariadbd                        [.] JOIN::exec
+    2.54%     0.00%  mariadbd         mariadbd                        [.] JOIN::exec_inner
+    2.54%     0.13%  swapper          [kernel.kallsyms]               [k] __hrtimer_run_queues
+    2.50%     0.00%  mariadbd         mariadbd                        [.] sub_select

11

1 5 4.svg

Ссылки