Howto Профилирование Linux
Введение
Начать с:
yum --enablerepo='base-debuginfo' install kernel-debuginfo-`uname -r` kernel-devel perf oprofile gdb kexec-tools crash
если по быстрому
- perf top - не точно показывает адрес топ фукнции
- perf top -d 5 -U
- perf top -d 5 -g -U
- perf stat -e task-clock,cycles,instructions,cache-references,cache-misses sleep 5
- perf record -a sleep 5 и потом perf report
- powertop
если всерьез
- oprofile
- sysrq
- ftrace + debugfs
Общий алгоритм
- Привести машину в максимально дефалтное состояние. Проверить и устранить аномалии и вредные настройки, например штормы прерываний, постоянный лог ошибок в dmesg и прочее. Убрать все оптимизации, если они были наугад включены.
- Добиться нагрузки на ядро не менее 15-25% процентов
- Провести профилирование oprofile
- Провести профилирование через sysrq
- Найти и подтвердить по коду, что проблема есть
- Проверить, что в новых версиях не сделана оптимизация этих функций и подсистем(обычно нет)
- Попробовать решить задачу оптимизацией настроек и оборудования и правил и тп workaround
- Если невозможно решить оптимизацией настроек, пробуем оптимизировать код, убрать локи добавить хеши усилить параллельность итп.
Рекомендации профилированию сетевого стека ядра для маршрутизаторов и firewall
Перед профилированием попробовать решить типовые проблемы, а именно:
- Убедиться, что нет шторма прерываний(особенно usb и прочее левое оборудование).
- Проверить, что dmesg чистый.
- Поднять буферы сетевок rx tx на максимум, выключаем pause_rx и tx ethtool -A
- Проверяем и меняем кабеля, коммутаторы, сетевки, смотрим нагрузку роутеров
- Проверяем tcpdump tcp retrain если много то? tx путь
- Проверяем сеть ping -f -l 30 IPклиента и роутера, для 1Гбит ping -f -l 300 IPклиента и роутера. Потерь должно быть не более 3-10%. При этом роутер может отвечать с потерями, а роутить без потерь.
- Проверить, что правил iptables не более 50 и стоят верхние ACCEPT –state ESTABLISHED и прочие обязательные оптимизации.
- Проверить, что в tc filter используются только hash фильтры на основе маркировок.
- Проверить, что используются только fifo или fast_fifo очереди на сетевках, на qdisc, на imq, тк все остальные хитрые очереди гарантированно дают лишнюю нагрузку и никакой пользы не дают на современных скоростях.
- Проверить что connlimit либо патченый c hash? либо не используется тк дефалтный очень плохой и тормозной.
- Проверить колво маршрутов в ip route show и ip route show cache, бывает, что там 1млн маршрутов и это будет тормозить, однако если в FORWARD поставить первым ACCEPT или DROP(для зеркальных firewall) и нагрузка упадет в разы значит кеш маршрутов не причем. Оттюнить бакеты и прочее в rt_cache в proc sys
- Проверить колво контраков, если запредельно, то будет тормозить. Оттюнить колво бакеты и прочее в в proc sy
- Для carbon_xge проверить, что используется ядро carbon_master с правильными оптимизированными OSV патчами IMQ.
- Для carbon_xge проверить, что включены все оптимизаци для arp и для route подсистем.
- Убедитьтся, что потери все равно есть или cpu usage большой или нагрузка большая
- Проверить улучшится ли ситуация если поставить везде ACCEPT первым правилом кроме nat postrouting. todo Добавить сюда готовый пример со sleep 5
- Проверить улучшится ли ситуация если запретить маршрутизацию и поставить iptables -I FORWARD -j DROP; sleep 5; iptables -D FORWARD -j DROP
- Проверить насколько упадет нагрузка если поставить DROP в raw, кроме ssh 22
- Перенести RSS на CPU0
- Включить и настроить RPS на NUMA0 на все процессоры кроме CPU0
- Убедиться, что нагрузка на CPU0 и CPU1 не менее 10% если CPU1 менее 10% уменшить колво процов на RPS или даже весь rps повешать на CPU1
- Далее проводить профилирование по Общему алгоритму
Как работает профилирование oprofile
В каждом современном процессоре есть внутренние счетчики, которые при прокрутке могу вызвать процессору прерывание nmi - оно немаскируемое через asm cli.
Внутренние прерывания процессора это lapic и обычно профилируем через него.(также можно использовать внешние тактуемые apic-nmi или другие генераторы, но не рекомендуется)
Профилировщик также как и nmi_watchog устанавливает счетчик на event CPU_CLK_UNHALTED. Поэтому нужно выключить nmi_watchog
CPU_CLK_UNHALTED - это счетчик всех инструкций, кроме HLT(=idle) инструкций. И когда сработает скажем 100, то вызовется nmi→nmi_profile(), инфа кладется в буфер ядра.
Потом демон профилировщика забирает эту инфу из буфера ядра и сохраняет в файл.
На основе этого файла можно строить разные отчеты.
Таким образом, мы можем узнать где чаще всего находится процессор.
p.s. Из минусов, очень редко можно получить нормальный стек вызова и есть подозрения на неполную достоверность, возможно из-за корреляций с демоном.
opreport -с не всегда помогает тк калбек по факту не сохраняется, а моделируется.
Как работает профилирование osv через sysrq
В sysrq есть возможность печати текущего стека CPU.
# включаем sysrq эмулятор echo 1 > /proc/sys/kernel/sysrq # посылаем L чтобы распечатать стеки CPU\\ echo l >/proc/sysrq-trigger
При записи в proc происходит выставление переменной тригера, которая отлавливается в nmi_enter() и печать стека происходит уже там через случайный промежуток времени, тк на ходу это делать нет смысла, ибо мы поймаем только сами себя.
p.s. Из минусов сервер может повиснуть, поэтому делать надо с паузами и синками, чтоб файл успел записаться.
Пример скрипта:
echo 1 > /proc/sys/kernel/sysrq dmesg -c>/tmp/d1 echo > /tmp/cpu_report for ((i=0;i<100;i++)); do sync; sleep 1; sync; for ((k=0;k<10;k++)); do echo $i $k echo l > /proc/sysrq-trigger sleep 1 dmesg -c >>/tmp/cpu_report done done
[3002759.740760] NMI backtrace for cpu 5 [3002759.740915] CPU 5 <d>Modules linked in: xt_conntrack vhost_net macvtap macvlan kvm_intel kvm vzethdev vznetdev pio_kaio pio_nfs pio_direct pfmt_raw pfmt_ploop1 ploop simfs vzrst vzcpt nfs lockd fscache auth_rpcgss nfs_acl sunrpc vziolimit vzmon ip6table_mangle xt_length xt_hl xt_multiport xt_limit xt_dscp ip_set_list_set(F)(U) ip_set_hash_netportnet(F)(U) ip_set_hash_netport(F)(U) ip_set_hash_netnet(F)(U) ip_set_hash_net(F)(U) ip_set_hash_netiface(F)(U) ip_set_hash_mac(F)(U) ip_set_hash_ipportnet(F)(U) ip_set_hash_ipport(F)(U) ip_set_hash_ipportip(F)(U) ip_set_hash_ipmark(F)(U) ip_set_hash_ipmac(F)(U) ip_set_hash_ip(F)(U) ip_set_bitmap_port(F)(U) ip_set_bitmap_ipmac(F)(U) ip_set_bitmap_ip(F)(U) xt_set(F)(U) ip_set(F)(U) flashcache(F)(U) ipip tunnel4 nf_conntrack_netlink zram(C) lzo_decompress lzo_compress vxlan nfnetlink ebtable_nat ebtables ipt_MASQUERADE iptable_nat xt_CHECKSUM tun bridge stp llc nf_nat vzdquota xt_tcpmss xt_TCPMSS iptable_mangle vzevent vzdev ipt_REJECT nf_conntrack_ipv4 nf_defrag_ipv4 iptable_filter [3002759.742871] Pid: 0, comm: swapper veid: 0 Tainted: GF C -- ------------ 2.6.32-042stab123.8 #3 042stab123_8<c> Supermicro Super Server<c>/X11SSL-F<c> [3002759.743306] RIP: 0010:[<ffffffff8130ed31>] [<ffffffff8130ed31>] intel_idle+0xd1/0x1b0 [3002759.743594] RSP: 0018:ffff8810694dbe48 EFLAGS: 00000046 [3002759.743742] RAX: 0000000000000020 RBX: 0000000000000008 RCX: 0000000000000001 [3002759.744036] RDX: 0000000000000000 RSI: ffff8810694dbfd8 RDI: ffffffff81a989c0 [3002759.744321] RBP: ffff8810694dbed8 R08: 00000000000001e2 R09: 00000000000000fd [3002759.744606] R10: 0000000000000002 R11: 0000000000000000 R12: 0000000000000004 [3002759.744900] R13: ffff880028366280 R14: 0000000000000020 R15: 150cb8aef998319c [3002759.745401] FS: 0000000000000000(0000) GS:ffff880028340000(0000) knlGS:0000000000000000 [3002759.745689] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b [3002759.745847] CR2: 00000000006d4740 CR3: 0000000001a8d000 CR4: 00000000001427e0 [3002759.746132] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [3002759.746419] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [3002759.746705] Process swapper (pid: 0, veid: 0, threadinfo ffff8810694d8000, task ffff8810694ce3c0) [3002759.747003] Stack: [3002759.747144] ffff8810694dbe58 ffffffff810152a9 ffff8810694dbe78 ffffffff810b860d [3002759.747430] ffff880000000002 0000000000000005 ffff8810694dbe88 ffffffff810b86e1 [3002759.747716] ffff8810694dbed8 ffffffff81455004 0000000000000000 0000000500075d13 [3002759.748011] Call Trace: [3002759.748153] [<ffffffff810152a9>] ? sched_clock+0x9/0x10 [3002759.748302] [<ffffffff810b860d>] ? sched_clock_cpu+0xcd/0x110 [3002759.748451] [<ffffffff810b86e1>] ? sched_clock_idle_sleep_event+0x11/0x20 [3002759.748602] [<ffffffff81455004>] ? menu_select+0x174/0x350 [3002759.748751] [<ffffffff81453efa>] cpuidle_idle_call+0x7a/0xe0 [3002759.748909] [<ffffffff8100a046>] cpu_idle+0xb6/0x110 [3002759.749056] [<ffffffff8154f403>] start_secondary+0x2c0/0x316 [3002759.749206] Code: ff ff a8 08 75 25 31 d2 48 8d 86 38 c0 ff ff 48 89 d1 0f 01 c8 0f ae f0 48 8b 86 38 c0 ff ff a8 08 75 08 b1 01 4c 89 f0 0f 01 c9 <e8> 0a d1 da ff 4c 29 f8 48 89 c7 e8 8f c3 d7 ff 49 89 c6 49 89 [3002759.749650] Call Trace: [3002759.749792] <NMI> <<EOE>> [<ffffffff810152a9>] ? sched_clock+0x9/0x10 [3002759.749948] [<ffffffff810b860d>] ? sched_clock_cpu+0xcd/0x110 [3002759.750098] [<ffffffff810b86e1>] ? sched_clock_idle_sleep_event+0x11/0x20 [3002759.750249] [<ffffffff81455004>] ? menu_select+0x174/0x350 [3002759.750398] [<ffffffff81453efa>] cpuidle_idle_call+0x7a/0xe0 [3002759.750548] [<ffffffff8100a046>] cpu_idle+0xb6/0x110 [3002759.750695] [<ffffffff8154f403>] start_secondary+0x2c0/0x316 [3002759.750854] Pid: 0, comm: swapper veid: 0 Tainted: GF C -- ------------ 2.6.32-042stab123.8 #3 [3002759.751144] Call Trace: [3002759.751286] <NMI> [<ffffffff81009c77>] ? show_regs+0x27/0x50 [3002759.751435] [<ffffffff8155b6b9>] ? arch_trigger_all_cpu_backtrace_handler+0x99/0xc0 [3002759.751722] [<ffffffff8155cf55>] ? notifier_call_chain+0x55/0x80 [3002759.751881] [<ffffffff8155cfba>] ? atomic_notifier_call_chain+0x1a/0x20 [3002759.759870] [<ffffffff810b739e>] ? notify_die+0x2e/0x30 [3002759.750018] [<ffffffff8155a92b>] ? do_nmi+0xdb/0x370 [3002759.750166] [<ffffffff8155a433>] ? nmi+0x83/0x90 [3002759.750314] [<ffffffff8130ed31>] ? intel_idle+0xd1/0x1b0 [3002759.750462] <<EOE>> [<ffffffff810b5c38>] ? hrtimer_start+0x18/0x20
Полученный файл можно грепать по первому и второму процу, и потом по конкретным вызовам и подвызовам, подподвызовам, чтоб понять проблему.
Простейший отчет cat /tmp/cpu_report | grep 'RIP: ' | sort -k 5,5 | uniq -c -f 4 | sort -k 1,1n потом смотрим кто в топе и его колтрейс
Другие способы профилирования
Callgrind gprof crxprof systemtap
Самый простой способ без установки тулз: strace -c -p 14308 Далее зажимаем enter По колво пустого места между строк видно какой сискол тупил
Как найти строчку кода
Можно узнать конкретные команды и строчки через gdb vmlinux > disass *0xfffffffff82324523 видим что это net_rx+121 > list *0xfffffffff82324523 > list net_rx+121
Часто узнавать приходится через смещение тк требуется перекомпиляция модуля или подсистемы ядра с -g debug. Часто gdb глючит если весь vmlinux с дебагом и тогда компилим конкретные net.o с дебагом и потом находим через смещение.
gdb net.o list net_rx+121
Установка и использование oprofile
http://geoe.mu.edu.tr/sharedoc/oprofile-0.9.7/oprofile.html#controlling-daemon
yum install oprofile
Если профилируем ванильное ядро CentOS
Включаем репозиторий
/etc/yum.repos.d/CentOS-Debuginfo enabled=1
Найти название пакета с нужной версией можно с помощью:
yum --showduplicates list kernel-debuginfo
yum -y install kernel-debuginfo
качаться будет долго, можно попить чаёк или сделать мелкую таску. Не знаю почему пишется centos.plus но оно нам не нужно, так что:
mv /usr/lib/debug/lib/modules/2.6.32-642.1.1.el6.centos.plus.x86_64/ /usr/lib/debug/lib/modules/2.6.32-642.1.1.el6.x86_64/
тогда можем указывать параметр vmlinux динамически:
/usr/lib/debug/lib/modules/`uname -r`/vmlinux
Если кастомное ядро
Копируем кастомный или хотя бы близкий к нему vmlinux например в /boot/.
Если есть только близкий vmlinux, то точную функцию сможем найти по адресу в /proc/kallsyms (и почему oprofile сам его не использует?)
Использование
echo 0 > /proc/sys/kernel/nmi_watchdog opcontrol --deinit opcontrol --init opcontrol --reset opcontrol --start --vmlinux=/usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/vmlinux # но иногда можно и --no-vmlinux если нам не важно про ядро, а только про юспейс # если баг Failed to open profile device: Device or resource busy, то стопаем все виртуалки KVM, одна из них залочила nmi sleep 10 # ждем сбора статистики opcontrol --stop # включаем watchdog обратно echo 1 > /proc/sys/kernel/nmi_watchdog # собрали стату, стопнули, чтоб не грузить.
Отчеты oprofile
Отчет стандартный
opreport
CPU_CLK_UNHALT…|
samples| %|
——————
105284 56.8974 vmlinux
54308 29.3490 kvm_intel
13697 7.4021 kvm
3512 1.8979 qemu-kvm
CPU_CLK_UNHALT…|
samples| %|
3157 89.8918 qemu-kvm
2739 1.4802 oprofile
1127 0.6091 libc-2.12.so
отчет по функциям
opreport -l
samples % image name app name symbol name
54308 29.3501 kvm_intel kvm_intel /kvm_intel
14571 7.8747 vmlinux vmlinux intel_idle
13697 7.4024 kvm kvm /kvm
6923 3.7415 vmlinux vmlinux ksm_scan_thread
4437 2.3979 vmlinux vmlinux follow_page
4017 2.1709 vmlinux vmlinux memcmp_pages
отчет по адресам. в тч inline и lock
opreport -d -l
0000000000000000 54308 29.3501 kvm_intel kvm_intel /kvm_intel
0000000000000050 23 0.0424
0000000000000051 10 0.0184
0000000000000058 1 0.0018
000000000000005c 3 0.0055
0000000000000060 2 0.0037
Отчета о кастомном модуле
opreport -l -w -p /lib/modules/2.6.32-642.el6.x86_64/kernel/drivers/net/i40e/
opreport -l -w -p /node/bin 2>&1| head -n 100 | grep flas
0000000000007d30 5385 1.3249 flashcache.ko flashcache flashcache_hash_lookup
0000000000003400 3255 0.8008 flashcache.ko flashcache hash_block
00000000000037b0 1792 0.4409 flashcache.ko flashcache flashcache_setlocks_multiget
~~OWNERAPPROVE~~