Linux Perf

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%.

Выглядит это примерно так (и тут можно четко видеть что сервер большую часть времени ничего не делает (swapper --> mwait_idle_with_hints.constprop.0) но иногда что-то делает zabbix_server и mariadbd

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

FlameGraph

Визуально можно представить данные с помощью FlameGraph
Установить:

git clone https://github.com/brendangregg/FlameGraph

Запустить:

perf script --input ./perf.data  | /root/FlameGraph/stackcollapse-perf.pl | /root/FlameGraph/flamegraph.pl > file.svg

• perf script --input ./perf.data - преобразует данне в вид, который может понять stackcollapse-perf.pl
• --input ./perf.data - это путь по-умолчанию, и указан для того что бы было понятнее откуда взяты данные для анализа.

Заголовок

Flame Chart

Пояснения

Файл кликабельный (нужно кликнуть 2 раза что бы добраться до SVG)

Читать этот график следует так Нижняя линия (красная, без подписи) это 100% времени Вторая снизу - распределение времени по функциям, больше всего времени в функции swapper Почти все время в функции swapper проводит в secondary_startup_64_no_verify И так далее смотреть вверх по функциям Пробелы в верхней части графика означают что время проведено собственно в функции, а не вызывалась какая-то другая функция

Сравнение производительности разных ядер на реальном тесте

Заголовок

Ядро 5.4	Ядро 5.15 (проблемное)	Ядро 5.15 (C решенной проблемой)
Файл кликабельный (нужно кликнуть 2 раза что бы добраться до SVG)

Ссылки

• https://habr.com/ru/companies/yandex/articles/700918/
• https://habr.com/ru/companies/oleg-bunin/articles/659789/