Linux Perf

Linux perf

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

Авторы

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

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

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

TL;DR

• Дело было в том что процессор переходил в режим сохранения энергии слишком активно
• intel_idle.max_cstate=0
• https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=a472ad2bcea479ba068880125d7273fc95c14b70

Введение в 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 опцией intel_idle.max_cstate=0
Для понимания - результат исследования после исправления в третьем столбце.

Заголовок

Ядро 5.4	Ядро 5.15 (проблемное)	Ядро 5.15 (C решенной проблемой)
Файл кликабельный (нужно кликнуть 2 раза что бы добраться до SVG)	Файл кликабельный (нужно кликнуть 2 раза что бы добраться до SVG)	Файл кликабельный (нужно кликнуть 2 раза что бы добраться до SVG)
Ход исследования	Ход исследования	Ход исследования
Тут можно видеть, что используется функция mwait_idle	Тут можно видеть, что используется функция intel_idle	После того, как ядру передан параметр intel_idle.max_cstate=0 можно видеть что снова используется функция mwait_idle

Рубрика "советы бывалых"

• C1 (Halt) - состояние, когда процессор не исполняет инструкции, но готов мгновенно ( с задержкой примерно 10нс) приступить к их исполнению, при этом его энергопотребление составляет примерно 30% от нормы.

• Столкнулся совсем недавно, при nosoftlockup intel_idle.max_cstate=0 processor.max_cstate=1 mce=ignore_ce idle=poll температура на CPU0 E5-2660 и включённом Turbo Boost взлетала до 80-81°C. Убрал idle=poll, стало 70-71°C

Удобные утилиты

• powertop
• i7z

Ещё важно для максимальной производительности, чтобы не было переключения в C-state'ы >1 (для этого нужно делать processor.max_cstate=1 intel_idle.max_cstate=0 idle=poll) но будет есть больше электричества

Изменение CPU Scaling Governor в Linux

На серверах HPE BIOS обязательно нужно включить Collaborative Power Control (CPC) иначе из операционной системы нельзя будет управлять производительностью процессора и не будет этих файлов:

find / -name scaling_governor
find / -name scaling_max_freq

В случае Dell (R710) аналогично - есть пункт в меню

Посмотрим текущее значение всех ядер процессора:

cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor

В моем случае было 4 возможных варианта:

• schedutil
• performance
• ondemand (значение по умолчанию?)
• Отсутвовали файлы, посмотреть нельзя

Посмотрим возможные схемы:

cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_governors

Доступны (там где возможно посмотреть)

• conservative
• ondemand
• userspace
• powersave
• performance
• schedutil

echo performance > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu1/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu2/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu3/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu4/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu5/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu6/cpufreq/scaling_governor
echo performance > /sys/devices/system/cpu/cpu7/cpufreq/scaling_governor

Либо так:

apt install cpufrequtils
for i in 0 1 2 3 4 5 6 7 8 9 10 11; do cpufreq-set -c $i -g performance; done

Проверим:

cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor

egrep '(MHz)' /proc/cpuinfo

Если предыдущие способы не помогли, то для Intel CPU можно также указать «intel_idle.max_cstate» в grub:

nano /etc/default/grub
GRUB_CMDLINE_LINUX_DEFAULT="... intel_idle.max_cstate=1"
update-grub
reboot

dmesg -T | grep intel_idle

Либо можно полностью отключить энергосберегающие функции CPU и PCIe:

intel_idle.max_cstate=0 processor.max_cstate=1 pcie_aspm=off quiet mitigations=off

В крайнем случае с idle=poll:

intel_idle.max_cstate=0 processor.max_cstate=1 pcie_aspm=off quiet mitigations=off idle=poll

Замечу, что если указать idle=poll, то в BIOS или iLo например, может отображаться что CPU используется на 100%, хотя это не так.

Также отключим уже ненужную службу энергосбережения:

systemctl is-enabled ondemand
systemctl disable ondemand

Ссылки

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

• https://www.brendangregg.com/perf.html

• https://docs.kernel.org/admin-guide/pm/cpuidle.html
• https://habr.com/ru/companies/selectel/articles/525542/ (https://metebalci.com/blog/a-minimum-complete-tutorial-of-cpu-power-management-c-states-and-p-states/)
• https://wiki.archlinux.org/title/CPU_frequency_scaling