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

Здесь показаны различия между двумя версиями данной страницы.

--- howto:howto_kernel:howto_профилирование_linux [08.10.2018 13:45]
admin Approved(admin 2018/10/08 13:45)
+++ 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
-  * 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=/boot/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| %|\\
-——————\\
-56.8974 vmlinux\\
-29.3490 kvm_intel\\
-7.4021 kvm\\
-1.8979 qemu-kvm\\
-CPU_CLK_UNHALT…|\\
-samples| %|\\
-89.8918 qemu-kvm\\
-1.4802 oprofile\\
-0.6091 libc-2.12.so\\
-==== отчет по функциям ====
-opreport -l\\
-samples % image name app name symbol name\\
-29.3501 kvm_intel kvm_intel /kvm_intel\\
-7.8747 vmlinux vmlinux intel_idle\\
-7.4024 kvm kvm /kvm\\
-3.7415 vmlinux vmlinux ksm_scan_thread\\
-2.3979 vmlinux vmlinux follow_page\\
-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~~

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

Различия