Howto Профилирование Linux

Начать с:

yum --enablerepo='base-debuginfo' install kernel-debuginfo-`uname -r` kernel-devel perf oprofile gdb kexec-tools crash

если по быстрому

если всерьез

  • oprofile
  • sysrq
  • ftrace + debugfs
  1. Привести машину в максимально дефалтное состояние. Проверить и устранить аномалии и вредные настройки, например штормы прерываний, постоянный лог ошибок в dmesg и прочее. Убрать все оптимизации, если они были наугад включены.
  2. Добиться нагрузки на ядро не менее 15-25% процентов
  3. Провести профилирование oprofile
  4. Провести профилирование через sysrq
  5. Найти и подтвердить по коду, что проблема есть
  6. Проверить, что в новых версиях не сделана оптимизация этих функций и подсистем(обычно нет)
  7. Попробовать решить задачу оптимизацией настроек и оборудования и правил и тп workaround
  8. Если невозможно решить оптимизацией настроек, пробуем оптимизировать код, убрать локи добавить хеши усилить параллельность итп.

Перед профилированием попробовать решить типовые проблемы, а именно:

  1. Убедиться, что нет шторма прерываний(особенно usb и прочее левое оборудование).
  2. Проверить, что dmesg чистый.
  3. Поднять буферы сетевок rx tx на максимум, выключаем pause_rx и tx ethtool -A
  4. Проверяем и меняем кабеля, коммутаторы, сетевки, смотрим нагрузку роутеров
  5. Проверяем tcpdump tcp retrain если много то? tx путь
  6. Проверяем сеть ping -f -l 30 IPклиента и роутера, для 1Гбит ping -f -l 300 IPклиента и роутера. Потерь должно быть не более 3-10%. При этом роутер может отвечать с потерями, а роутить без потерь.
  7. Проверить, что правил iptables не более 50 и стоят верхние ACCEPT –state ESTABLISHED и прочие обязательные оптимизации.
  8. Проверить, что в tc filter используются только hash фильтры на основе маркировок.
  9. Проверить, что используются только fifo или fast_fifo очереди на сетевках, на qdisc, на imq, тк все остальные хитрые очереди гарантированно дают лишнюю нагрузку и никакой пользы не дают на современных скоростях.
  10. Проверить что connlimit либо патченый c hash? либо не используется тк дефалтный очень плохой и тормозной.
  11. Проверить колво маршрутов в ip route show и ip route show cache, бывает, что там 1млн маршрутов и это будет тормозить, однако если в FORWARD поставить первым ACCEPT или DROP(для зеркальных firewall) и нагрузка упадет в разы значит кеш маршрутов не причем. Оттюнить бакеты и прочее в rt_cache в proc sys
  12. Проверить колво контраков, если запредельно, то будет тормозить. Оттюнить колво бакеты и прочее в в proc sy
  13. Для carbon_xge проверить, что используется ядро carbon_master с правильными оптимизированными OSV патчами IMQ.
  14. Для carbon_xge проверить, что включены все оптимизаци для arp и для route подсистем.
  15. Убедитьтся, что потери все равно есть или cpu usage большой или нагрузка большая
  16. Проверить улучшится ли ситуация если поставить везде ACCEPT первым правилом кроме nat postrouting. todo Добавить сюда готовый пример со sleep 5
  17. Проверить улучшится ли ситуация если запретить маршрутизацию и поставить iptables -I FORWARD -j DROP; sleep 5; iptables -D FORWARD -j DROP
  18. Проверить насколько упадет нагрузка если поставить DROP в raw, кроме ssh 22
  19. Перенести RSS на CPU0
  20. Включить и настроить RPS на NUMA0 на все процессоры кроме CPU0
  21. Убедиться, что нагрузка на CPU0 и CPU1 не менее 10% если CPU1 менее 10% уменшить колво процов на RPS или даже весь rps повешать на CPU1
  22. Далее проводить профилирование по Общему алгоритму

В каждом современном процессоре есть внутренние счетчики, которые при прокрутке могу вызвать процессору прерывание 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 -с не всегда помогает тк калбек по факту не сохраняется, а моделируется.

В 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

Если профилируем ванильное ядро 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
# собрали стату, стопнули, чтоб не грузить.

Отчет стандартный

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~~