===== Отладка panic ===== * ставим kdump и kernel-debuginfo (нужен vmlinux Не linuz) * ловим панику * Запускаем утилиту crash /usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/vmlinux /var/crash/vmcore * http://people.redhat.com/anderson/crash_whitepaper/#HELP * https://www.kernel.org/doc/Documentation/kdump/kdump.txt * https://www.dedoimedo.com/computers/crash-book.html * http://people.redhat.com/anderson/crash_whitepaper/ * Удобный листинг dis -rl 0xffffffffb1fe2fe5 * Если это обычная паника по памяти и тп, то она обычно на то ядре где и поймали. * Помним что локап мог быть на 4ом ядре, а виновато могло быть 1 ядро. Локап надо сверять по всем ядрам и смотреть те которые значительно по стеку отличаются от других. * Помним что стек может быть лоскутным из-за прерываний и случайного попадания переменных колбек функций в стек. * Видим KERNEL: /usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/vmlinux DUMPFILE: /var/crash/127.0.0.1-2018-09-24-15:07:40/vmcore [PARTIAL DUMP] CPUS: 8 DATE: Mon Sep 24 15:21:45 2018 UPTIME: 76 days, 03:30:21 LOAD AVERAGE: 40.84, 23.29, 11.60 TASKS: 298 NODENAME: host22 RELEASE: 2.6.32-642.el6.x86_64 VERSION: #1 SMP Tue May 10 17:27:01 UTC 2016 MACHINE: x86_64 (3702 Mhz) MEMORY: 32 GB PANIC: "Kernel panic - not syncing: softlockup: hung tasks" PID: 5487 COMMAND: "sshd" TASK: ffff880834017520 [THREAD_INFO: ffff8807708e4000] CPU: 6 STATE: TASK_RUNNING (PANIC) * Причина паники PANIC: "Kernel panic - not syncing: softlockup: hung tasks" * LOAD AVERAGE: 40.84 - довольно большой, возможно паника была не мгновенной, а вначале подвисло, значит в стеке мусора может быть много. * COMMAND: "sshd" - Обычно это просто текущее приложение которое было активно во время паники и если от него нет прямых сисколов в паникующу функцию, то оно не причем. * Команды crash * начнем с crash>log лог здесь может быть полней чем в messages тк messages * список процессов crash>ps ===== Локализация проблемы локапа ===== * Делаем bt -c 0 далее bt -c 1 и тд по всем процессорам * Находим стеки отличающиеся от других и просто подозрительные * Завариваем кофе, выливаем, гадаем * Обычно локап бывает при повторном попадании на свой же спинлок или свой врайтлок поверх ридлок при сменах контекста в широком смысле, часто из-за незапрещеных/случайноразрешенных BH или CLI. То есть висит себе ядро в блокироке, его прерывали и послали обрабатывать по другому стеку и пришло оно к той же блокировке и вот вам локап. * Часто если функция и локеры написаны для ядра, а вызываются из юспейс и наоборот * Часто конфликты юспейс и ядра * Часто перекрестная блокировка deadlock 2x2 две блокировки два ядра крест накрет ===== Пример ===== **crash>bt -c 0** PID: 6836 TASK: ffff88082d8e3520 CPU: 2 COMMAND: "sshd" #0 [ffff880028286e90] crash_nmi_callback at ffffffff810366e6 #1 [ffff880028286ea0] notifier_call_chain at ffffffff8154dc85 #2 [ffff880028286ee0] atomic_notifier_call_chain at ffffffff8154dcea #3 [ffff880028286ef0] notify_die at ffffffff810aceae #4 [ffff880028286f20] do_nmi at ffffffff8154b903 #5 [ffff880028286f50] nmi at ffffffff8154b1c3 [exception RIP: __write_lock_failed+9] RIP: ffffffff812a6f29 RSP: ffff880028283950 RFLAGS: 00000287 RAX: ffff88078b0fbfd8 RBX: ffff88075efe27e0 RCX: 0000000000000002 RDX: 0000000000000036 RSI: ffff8807905a35c0 RDI: ffff88075efe27e0 RBP: ffff880028283968 R8: 0000000000000006 R9: ffff880028283937 R10: ffffc90019613300 R11: 0000000000000000 R12: 0000000000000002 R13: 0000000000000002 R14: ffff8807905a35c0 R15: ffff88075efe27e0 ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018 --- --- #6 [ffff880028283950] __write_lock_failed at ffffffff812a6f29 #7 [ffff880028283950] _write_lock_bh at ffffffff8154aa87 #8 [ffff880028283970] ip_set_add at ffffffffa0726841 [ip_set] #9 [ffff8800282839c0] set_target at ffffffffa074d464 [xt_set] #10 [ffff8800282839f0] ipt_do_table at ffffffffa06d920b [ip_tables] #11 [ffff880028283b80] ipt_hook at ffffffffa071d0f3 [iptable_filter] #12 [ffff880028283b90] nf_iterate at ffffffff814a8c89 #13 [ffff880028283be0] nf_hook_slow at ffffffff814a8e46 #14 [ffff880028283c60] ip_forward at ffffffff814b5523 #15 [ffff880028283ca0] ip_rcv_finish at ffffffff814b34ad #16 [ffff880028283ce0] ip_rcv at ffffffff814b3a35 #17 [ffff880028283d20] __netif_receive_skb at ffffffff81478401 Далее **crash> bt -c 1** PID: 5752 TASK: ffff88077fa8aab0 CPU: 1 COMMAND: "modules_ctl" #0 [ffff880028246e90] crash_nmi_callback at ffffffff810366e6 #1 [ffff880028246ea0] notifier_call_chain at ffffffff8154dc85 #2 [ffff880028246ee0] atomic_notifier_call_chain at ffffffff8154dcea #3 [ffff880028246ef0] notify_die at ffffffff810aceae #4 [ffff880028246f20] do_nmi at ffffffff8154b903 #5 [ffff880028246f50] nmi at ffffffff8154b1c3 [exception RIP: __write_lock_failed+15] RIP: ffffffff812a6f2f RSP: ffff8800282438e8 RFLAGS: 00000287 RAX: ffff880769db3fd8 RBX: ffff88075efe27e0 RCX: 0000000000000002 RDX: 0000000000000036 RSI: ffff8807ceee3880 RDI: ffff88075efe27e0 RBP: ffff880028243900 R8: 0000000000000006 R9: ffff8800282438cf R10: ffffc9001960b300 R11: 0000000000000001 R12: 0000000000000002 R13: 0000000000000002 R14: ffff8807ceee3880 R15: ffff88075efe27e0 ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0000 --- --- #6 [ffff8800282438e8] __write_lock_failed at ffffffff812a6f2f #7 [ffff8800282438e8] _write_lock_bh at ffffffff8154aa87 #8 [ffff880028243908] ip_set_add at ffffffffa0726841 [ip_set] #9 [ffff880028243958] set_target at ffffffffa074d464 [xt_set] #10 [ffff880028243988] ipt_do_table at ffffffffa06d920b [ip_tables] #11 [ffff880028243b18] ipt_hook at ffffffffa071d0f3 [iptable_filter] #12 [ffff880028243b28] nf_iterate at ffffffff814a8c89 #13 [ffff880028243b78] nf_hook_slow at ffffffff814a8e46 #14 [ffff880028243bf8] ip_forward at ffffffff814b5523 #15 [ffff880028243c38] ip_rcv_finish at ffffffff814b34ad #16 [ffff880028243c78] ip_rcv at ffffffff814b3a35 #17 [ffff880028243cb8] __netif_receive_skb at ffffffff81478401 Далее **crash> bt -c 0 1 2 3 4 5 6 ** - имеют примерно одинаковый вывод с залочиванием на функции **ip_set_add** на **_write_lock_bh**\\ А вот далее уже интересней на 8 ом ядре\\ **crash> bt -c 7 ** crash> bt -c 7 PID: 33 TASK: ffff8808340da040 CPU: 7 COMMAND: "ksoftirqd/7" #0 [ffff8800283c6e90] crash_nmi_callback at ffffffff810366e6 PID: 33 TASK: ffff8808340da040 CPU: 7 COMMAND: "ksoftirqd/7" #0 [ffff8800283c6e90] crash_nmi_callback at ffffffff810366e6 #1 [ffff8800283c6ea0] notifier_call_chain at ffffffff8154dc85 #2 [ffff8800283c6ee0] atomic_notifier_call_chain at ffffffff8154dcea #3 [ffff8800283c6ef0] notify_die at ffffffff810aceae #4 [ffff8800283c6f20] do_nmi at ffffffff8154b903 #5 [ffff8800283c6f50] nmi at ffffffff8154b1c3 [exception RIP: hash_netport4_expire+91] RIP: ffffffffa00c608b RSP: ffff8800283c3878 RFLAGS: 00000246 RAX: 0000000000000000 RBX: 00000000000e08c0 RCX: 0000000000000010 RDX: 00000002881f522f RSI: ffff8800283c3928 RDI: 0000000000000004 RBP: ffff8800283c38b8 R8: ffff8800283c392c R9: ffff8800283c392e R10: 0000000000000001 R11: 0000000000000001 R12: 0000000000000000 R13: ffff88080f400000 R14: 00000000000e08d0 R15: ffff88082e4cd400 ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018 --- --- #6 [ffff8800283c3878] hash_netport4_expire at ffffffffa00c608b [ip_set_hash_netport] #7 [ffff8800283c38c0] hash_netport4_tadd at ffffffffa00ca2a0 [ip_set_hash_netport] #8 [ffff8800283c3910] hash_netport4_kadt at ffffffffa00c5b2a [ip_set_hash_netport] #9 [ffff8800283c3970] ip_set_add at ffffffffa0726860 [ip_set] #10 [ffff8800283c39c0] set_target at ffffffffa074d464 [xt_set] #11 [ffff8800283c39f0] ipt_do_table at ffffffffa06d920b [ip_tables] #12 [ffff8800283c3b80] ipt_hook at ffffffffa071d0f3 [iptable_filter] #13 [ffff8800283c3b90] nf_iterate at ffffffff814a8c89 #14 [ffff8800283c3be0] nf_hook_slow at ffffffff814a8e46 #15 [ffff8800283c3c60] ip_forward at ffffffff814b5523 #16 [ffff8800283c3ca0] ip_rcv_finish at ffffffff814b34ad #17 [ffff8800283c3ce0] ip_rcv at ffffffff814b3a35 #18 [ffff8800283c3d20] __netif_receive_skb at ffffffff81478401 * На 8 ом процессоре явно ситуация отличная от других, здесь ip_set_add прошел через _write_lock и застрял где-то в #6 [ffff8800283c3878] hash_netport4_expire at ffffffffa00c608b [ip_set_hash_netport].\\ * at 0xffffffffa00c608b - это нужный нам абсолютный адрес для дебага * [ip_set_hash_netport] - это имя модуля * Делаем dis -l hash_netport4_expiredis и смотрим 0xffffffffa00c608b 0xffffffffa00c607f : shl $0x4,%r14 0xffffffffa00c6083 : cmpb $0x0,0x11(%r14,%r13,1) 0xffffffffa00c6089 : jne 0xffffffffa00c60a3 НАША АДРЕС: 0xffffffffa00c608b : jmpq 0xffffffffa00c614d 0xffffffffa00c6090 : movzbl 0x11(%r14,%r13,1),%eax 0xffffffffa00c6096 : add $0x1,%r12d 0xffffffffa00c609a : cmp %r12d,%eax * Наш адрес = hash_netport4_expire+91 * Далее выходим из crash и запускаем gdb на на модуль * gdb /lib/modules/2.6.32-642.el6.x86_64/kernel/net/netfilter/ipset/ip_set_hash_netport.ko * Ура подгрузилось с дебагом: Reading symbols from /usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/kernel/net/netfilter/ipset/ip_set_hash_netport.ko.debug...done. * disass hash_netport4_expire 0x00000000000010b3 <+83>: cmpb $0x0,0x11(%r14,%r13,1) 0x00000000000010b9 <+89>: jne 0x10d3 НАШ АДРЕС +91 0x00000000000010bb <+91>: jmpq 0x117d 0x00000000000010c0 <+96>: movzbl 0x11(%r14,%r13,1),%eax 0x00000000000010c6 <+102>: add $0x1,%r12d * Видим нашу строку 0x00000000000010bb <+91>: jmpq 0x117d * Делаем листинг * (gdb) list *hash_netport4_expire+91 * 0x10bb is in hash_netport4_expire (include/linux/netfilter/ipset/ip_set_ahash.h:**701**). 0x10bb is in hash_netport4_expire (include/linux/netfilter/ipset/ip_set_ahash.h:701). 696 u32 i; 697 int j; 698 699 for (i = 0; i < jhash_size(t->htable_bits); i++) { 700 n = hbucket(t, i); Наша строка 701 for (j = 0; j < n->pos; j++) { 702 data = ahash_tdata(n, j); 703 if (type_pf_data_expired(data)) { 704 pr_debug("expired %u/%u\n", i, j); 705 #ifdef IP_SET_HASH_WITH_NETS * Итого мы нашли подозрительную функцию и конкретную строчку ===== Прогуляемся в исходники ядра ===== * grep hash_netport4_expire - ничего не находим, такое часто если функции сделаны через макросы и надо искать префикс или постфикс * grep -r _expire /usr/src/linux/include/linux/netfilter/ipset - а вот и нашли #define type_pf_expire TOKEN(TYPE, PF, _expire * Имя функции генерируется макросом через макропеременную TYPE который объявлен в ip_set_hash_netport.c * #define TYPE hash_netport * Далее смотрим откуда она вызывается grep type_pf_expire * Находим аналогично через предыдущую функцию hash_netport4_tadd ее макроопределение type_pf_tadd и там if (h->elements >= h->maxelem) /* FIXME: when set is full, we slow down here */ type_pf_expire(h); * В функции type_pf_expire мы видим два вложенных цикла, но в теории они не очень большие, а локап срабатывает при 60 сек. * Возможно что то приводит к частому вызову type_pf_expire либо она сильно тормозит. * В любом случае проблема при переполнении ip_set h->elements >= h->maxelem * Что делаем далее, далее пауза и пробуем повторить синтетик тестом, если не вышло то ждем повтора на продакшене * Если удалось повторить, начинаем разбираться подробней с дебагами и тд ~~OWNERAPPROVE~~ /*Не удаляйте эту строку и ниже!*/ {(rater>id=1|name=Прочитал_howto:howto_kernel:отладка_kernel_panic|type=vote|trace=user|tracedetails=1)}