Howto Профилирование Linux
Различия
Здесь показаны различия между двумя версиями данной страницы.
howto:howto_kernel:howto_профилирование_linux [08.10.2018 16:12] admin Approved(admin 2018/10/08 16:12) |
howto:howto_kernel:howto_профилирование_linux [20.05.2019 15:18] |
||
---|---|---|---|
Строка 1: | Строка 1: | ||
- | ===== Введение ===== | ||
- | **если по быстрому** | ||
- | * perf top | ||
- | * https://perf.wiki.kernel.org/index.php/Tutorial#Sampling_with_perf_record | ||
- | * perf top -d 5 -U | ||
- | * perf top -d 5 -g -U | ||
- | * **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.\\ | ||
- | <code> | ||
- | # включаем sysrq эмулятор | ||
- | echo 1 > /proc/sys/kernel/sysrq | ||
- | # посылаем L чтобы распечатать стеки CPU\\ | ||
- | echo l >/proc/sysrq-trigger | ||
- | </code> | ||
- | При записи в proc происходит выставление переменной тригера, которая отлавливается в nmi_enter() и печать стека происходит уже там через случайный промежуток времени, тк на ходу это делать нет смысла, ибо мы поймаем только сами себя.\\ | ||
- | p.s. Из минусов сервер может повиснуть, поэтому делать надо с паузами и синками, чтоб файл успел записаться.\\ | ||
- | Пример скрипта:\\ | ||
- | <code bash> | ||
- | 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 | ||
- | </code> | ||
- | <code> | ||
- | [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 | ||
- | |||
- | </code> | ||
- | Полученный файл можно грепать по первому и второму процу, и потом по конкретным вызовам и подвызовам, подподвызовам, чтоб понять проблему.\\ | ||
- | <code bash> | ||
- | Простейший отчет | ||
- | cat /tmp/cpu_report | grep 'RIP: ' | sort -k 5,5 | uniq -c -f 4 | sort -k 1,1n | ||
- | потом смотрим кто в топе и его колтрейс | ||
- | </code> | ||
- | ===== Другие способы профилирования===== | ||
- | Callgrind | ||
- | gprof | ||
- | crxprof | ||
- | systemtap | ||
- | <code> | ||
- | Самый простой способ без установки тулз: | ||
- | strace -c -p 14308 | ||
- | Далее зажимаем enter | ||
- | По колво пустого места между строк видно какой сискол тупил | ||
- | </code> | ||
- | |||
- | ===== Как найти строчку кода ===== | ||
- | <code> | ||
- | Можно узнать конкретные команды и строчки через | ||
- | gdb vmlinux | ||
- | > disass *0xfffffffff82324523 | ||
- | видим что это net_rx+121 | ||
- | > list *0xfffffffff82324523 | ||
- | > list net_rx+121 | ||
- | </code> | ||
- | Часто узнавать приходится через смещение тк требуется перекомпиляция модуля или подсистемы ядра с -g debug. | ||
- | Часто gdb глючит если весь vmlinux с дебагом и тогда компилим конкретные net.o с дебагом и потом находим через смещение. | ||
- | <code> | ||
- | gdb net.o | ||
- | list net_rx+121 | ||
- | </code> | ||
- | |||
- | ===== Установка и использование oprofile ===== | ||
- | [[http://geoe.mu.edu.tr/sharedoc/oprofile-0.9.7/oprofile.html#controlling-daemon|http://geoe.mu.edu.tr/sharedoc/oprofile-0.9.7/oprofile.html#controlling-daemon]]\\ | ||
- | <code bash> | ||
- | yum install oprofile | ||
- | </code> | ||
- | ==== Если профилируем ванильное ядро CentOS ==== | ||
- | Включаем репозиторий | ||
- | <code bash> | ||
- | /etc/yum.repos.d/CentOS-Debuginfo | ||
- | enabled=1 | ||
- | </code> | ||
- | |||
- | Найти название пакета с нужной версией можно с помощью: | ||
- | <code> | ||
- | yum --showduplicates list kernel-debuginfo | ||
- | </code> | ||
- | |||
- | <code bash> | ||
- | yum -y install kernel-debuginfo | ||
- | </code> | ||
- | качаться будет долго, можно попить чаёк или сделать мелкую таску. | ||
- | Не знаю почему пишется centos.plus но оно нам не нужно, так что: | ||
- | <code bash> | ||
- | 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/ | ||
- | </code> | ||
- | тогда можем указывать параметр vmlinux динамически: | ||
- | <code bash> | ||
- | /usr/lib/debug/lib/modules/`uname -r`/vmlinux | ||
- | </code> | ||
- | ==== Если кастомное ядро ==== | ||
- | Копируем кастомный или хотя бы близкий к нему vmlinu**<color #ed1c24>x</color>** например в /boot/.\\ | ||
- | Если есть только близкий vmlinu**<color #ed1c24>x</color>**, то точную функцию сможем найти по адресу в /proc/kallsyms (и почему oprofile сам его не использует?)\\ | ||
- | |||
- | ====== Использование ====== | ||
- | <code bash> | ||
- | 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 | ||
- | # собрали стату, стопнули, чтоб не грузить. | ||
- | </code> | ||
- | ===== Отчеты 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 **/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~~ | ||