摘要:kernel panic 包含了多种内核异常类型,包括但不限于:空指针/异常指针、HungTask、RCU Stall、softlockup、hardlockup、OOM、BUG_ON。
kernel panic 包含了多种内核异常类型,包括但不限于:空指针/异常指针、HungTask、RCU Stall、softlockup、hardlockup、OOM、BUG_ON。
下图是各种类型 panic 的路径:
kpanic 类异常均为 kernel 软件可感知到的异常, kernel 完成 panic 流程后会由 bl31 完成一次 WarmReset,所以所有 panic 现场我们都是能够拿到 pstore log 的。由于是软件异常,所以 pstore 中都能看到异常调用栈、寄存器等信息,通过这些信息就可以初步分析 70% 的问题。BUG_ON 类是软件主动触发的 panic,所以直接检查代码逻辑即可。对于一些依赖于时序最终产生的 panic 问题,还需要进一步加 log 或 ftrace 进行复现,以跟踪时序(竞争类)引发的异常。 #算法 #自动驾驶 #每天一个知识点对于复杂的 panic 问题,还需要开启 ramdump 功能,抓取 dump 进行分析。此类问题代表内核中访问了一个空指针、未映射、没有权限的地址空间,导致触发 mem abort。
例:[ 1486.084782] CPU: 0 PID: 0 Comm: swapper/0 Tainted: P O 6.1.134-RT51-04836-g0b3e5cbe5431 #13[ 1486.090809] Hardware name: Horizon AI Technologies, Inc. HOBOT Sigi-P Matrix (DT)[ 1486.091730] pstate: 00400009 (nzcv daif +PAN -UAO -TCO BTYPE=--)[ 1486.092492] pc : __memcpy+0x48/0x180[ 1486.092953] lr : kfifo_copy_in+0x68/0x94[ 1486.093456] sp : ffff8000124cbd40[ 1486.093876] pmr_save: 000000e0[ 1486.094265] x29: ffff8000124cbd40 x28: ffff0001950ae200[ 1486.094942] x27: ffff0001765b8800 x26: 0000000000000000[ 1486.095619] x25: 0000000000000340 x24: 0000000000000018[ 1486.096295] x23: 00000000f97f0681 x22: ffff8000124cbe18[ 1486.096970] x21: ffff0001950ae280 x20: 00000000ffff0001[ 1486.097646] x19: 00000000f97f0681 x18: 0000000000000000[ 1486.098321] x17: 0000000000000000 x16: 0000000000000000[ 1486.098997] x15: 000000000000000a x14: 0000000035693bc0[ 1486.099672] x13: ffff800011feecd1 x12: ffffffffffffffff[ 1486.100348] x11: ffffffffffffffff x10: 0000000000000020[ 1486.101024] x9 : ffff800011feecbc x8 : 0000000005f5e100[ 1486.101699] x7 : ffff00027ee2f8b8 x6 : 00000001239ae000[ 1486.102376] x5 : ffff0001950ae280 x4 : 0000000000000008[ 1486.103052] x3 : 0000000100000025 x2 : 00000000f97f0679[ 1486.103728] x1 : ffff8000124cbe20 x0 : 00000001239ae000[ 1486.104405] Call trace:[ 1486.104717] __memcpy+0x48/0x180[ 1486.105133] __kfifo_in+0x3c/0x5c[ 1486.105558] bpu_core_tasklet+0x1b0/0x300 [bpu_cores][ 1486.106214] tasklet_action_common.isra.0+0x90/0xd4[ 1486.106837] tasklet_action+0x28/0x34[ 1486.107306] _stext+0x1e0/0x220[ 1486.107709] __irq_exit_rcu+0x80/0xd0[ 1486.107789] [S1][V0]subdev_balance_lost_next_frame lost_this = 0x1, lost_next = 0x1,[ 1486.107803] [S2][V0]subdev_balance_lost_next_frame lost_this = 0x1, lost_next = 0x1,[ 1486.107813] [S3][V0]subdev_balance_lost_next_frame lost_this = 0x1, lost_next = 0x1,[ 1486.107827] [S0][V0]subdev_balance_lost_next_frame lost_this = 0x0, lost_next = 0x1,[ 1486.107921] [S4][V0]cim_balance_lost_next_frame lost_this = 0x0, lost_next = 0x1,[ 1486.108179] irq_exit+0x10/0x20[ 1486.113403] __handle_domain_irq+0x70/0xa0[ 1486.113928] gic_handle_irq+0x2d0/0x30c[ 1486.114419] el1_irq+0xcc/0x180[ 1486.114822] arch_cpu_idle+0x30/0x38[ 1486.115278] default_idle_call+0x30/0x3c[ 1486.115779] do_idle+0x130/0x258[ 1486.116194] cpu_startup_entry+0x24/0x54[ 1486.116695] rest_init+0xd4/0xe4[ 1486.117108] arch_call_rest_init+0x10/0x1c[ 1486.117631] start_kernel+0x6f0/0x734这类问题,首先我们可以看到 mem abort 的 CPU 调用栈,所以马上就能够定位是哪个函数访问的异常地址,如果这个函数比较简单,也就能够很快定位到是哪个变量的空指针访问。如果函数比较复杂,我们可以使用 gdb,aDDR2line 等工具配合符号表进行汇编分析定位代码位置,通过偏移确认变量。确认异常指针的变量和来源后,有可能是下面的原因导致的错误:检查调用栈代码,从业务/调用逻辑上看是否存在引入错误指针情况。
检查对应变量相关代码逻辑,考虑是否可能存在竞争风险。
如果异常地址没有发现竞争或引入错误的可能,考虑是否是被踩踏,参考 memory correcption 节。
检查设备是否存在随机 crash 的情况,设备是否有单体问题,如果多设备存在随机 crash,也有可能是 DDR 软/硬件配置问题。
khungtaskd 是内核对 D 状态的进程进行扫描的内核线程,当内核某进程/线程长期处于 D 状态,hungtask 就会被触发,在征程 6 的系统中,hungtask 超时时间设置为 120s,且 CONFIG_BOOTPARAM_HUNG_TASK_PANIC_VALUE=1,故当 hungtask 检测到有进程处于 D 状态超过 120s 后就会直接触发 panic。
例:[ 605.147501] INFO: task ipi7_thread:3826 blocked for more than 120 seconds.[ 605.147532] Tainted: P O 6.1.134-rt51-04836-g0b3e5cbe5431 #13[ 605.147538] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.[ 605.147543] task:ipi7_thread state:D stack: 0 pid: 3826 ppid: 2 flags:0x00000028[ 605.147559] Call trace:[ 605.147562] __switch_to+0xf8/0x160[ 605.147583] __schedule+0x268/0x800[ 605.147594] schedule+0x84/0xf8[ 605.147602] cimdma_swap_buffer+0x244/0x338 [hobot_cim_dma][ 605.147631] kthread+0x160/0x188[ 605.147640] ret_from_fork+0x10/0x18[ 605.147649] INFO: task ipi4_thread:3830 blocked for more than 120 seconds.[ 605.147654] Tainted: P O 6.1.134-rt51-04836-g0b3e5cbe5431 #13[ 605.147658] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.[ 605.147661] task:ipi4_thread state:D stack: 0 pid: 3830 ppid: 2 flags:0x00000028[ 605.147669] Call trace:[ 605.147671] __switch_to+0xf8/0x160[ 605.147678] __schedule+0x268/0x800[ 605.147685] schedule+0x84/0xf8[ 605.147692] cimdma_swap_buffer+0x244/0x338 [hobot_cim_dma][ 605.147710] kthread+0x160/0x188[ 605.147716] ret_from_fork+0x10/0x18[ 605.147723] INFO: task ipi6_thread:3831 blocked for more than 120 seconds.[ 605.147728] Tainted: P O 6.1.134-rt51-04836-g0b3e5cbe5431 #13[ 605.147732] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.[ 605.147735] task:ipi6_thread state:D stack: 0 pid: 3831 ppid: 2 flags:0x00000028[ 605.147743] Call trace:[ 605.147745] __switch_to+0xf8/0x160[ 605.147751] __schedule+0x268/0x800[ 605.147758] schedule+0x84/0xf8[ 605.147765] cimdma_swap_buffer+0x244/0x338 [hobot_cim_dma][ 605.147783] kthread+0x160/0x188[ 605.147789] ret_from_fork+0x10/0x18[ 605.147796] INFO: task ipi5_thread:3832 blocked for more than 120 seconds.[ 605.147801] Tainted: P O 6.1.134-rt51-04836-g0b3e5cbe5431 #13[ 605.147805] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.[ 605.147808] task:ipi5_thread state:D stack: 0 pid: 3832 ppid: 2 flags:0x00000028[ 605.147816] Call trace:[ 605.147818] __switch_to+0xf8/0x160[ 605.147824] __schedule+0x268/0x800[ 605.147831] schedule+0x84/0xf8[ 605.147838] cimdma_swap_buffer+0x244/0x338 [hobot_cim_dma][ 605.147856] kthread+0x160/0x188[ 605.147862] ret_from_fork+0x10/0x18这类问题,khungtaskd 进程会在触发 crash 前,将长时间 D 状态的进程栈都输出出来,所以在 pstore 中能够快速定位到对应的调用信息。对于驱动中长时间处于 D 状态,一般是由于在等待的资源无法获取,需要分析业务流程,对于时间不可预期的资源,可以使用_interruable 族、或_timout 族函数进行优化。另一类由于死锁导致的 hungtask,需要代码分析死锁的根源,可以根据 log 中输出的所有 D 状态进程栈和 running 进程栈进行综合分析,对于大量 D 状态进程的复杂死锁问题,只能抓取 ramdump 去分析了。RCU(Read-Copy-Update),顾名思义就是读-拷贝修改,它是基于其原理命名的。对于被 RCU 保护的共享数据结构,读者不需要获得任何锁就可以访问它,但写者在访问它时首先拷贝一个副本,然后对副本进行修改,最后使用一个回调(callback)机制在适当的时机把指向原来数据的指针替换为新的被修改的数据。
释放原来资源的工作由 RCU 软中断和 rcu 线程负责,RCU Stall 在 tick 中断中检查,当负责释放线程一直未执行起来(RCU Stall timeout 时间为 30s),就会出现 RCU Stall panic。
例:[122235.050769] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:[122235.050778] rcu: Tasks blocked on level-0 rcu_node (CPUs 0-5):[122235.050789] (detected by 4, t=7502 jiffies, g=34171837, q=56419)[122235.050796] rcu: All QSes seen, last rcu_preempt kthread activity 1 (4325451296-4325451295), jiffies_till_next_fqs=1, root ->qsmask 0x0[122235.050805] Kernel panic -[122235.050809] RCU Stall [122235.050813] CPU: 4 PID: 0 Comm: swapper/4 Tainted: P O 6.1.134-rt51-04836-g0b3e5cbe5431 #13 [122235.050822] Hardware name: Horizon AI Technologies, Inc. HOBOT Sigi-P Matrix (DT) [122235.050828] Call trace: [122235.050830] dump_backtrace+0x0/0x1cc [122235.050846] show_stack+0x18/0x24 [122235.050853] dump_stack+0xcc/0x12c [122235.050863] panic+0xcc/0x344 [122235.050870] panic_on_rcu_stall+0x24/0x28 [122235.050881] rcu_sched_clock_irq+0x830/0x900 [122235.050889] update_process_times+0x60/0x88 [122235.050898] tick_sched_handle.isra.0+0x50/0x68 [122235.050907] tick_sched_timer+0x4c/0x90 [122235.050914] __hrtimer_run_queues+0x108/0x19c [122235.050922] hrtimer_interrupt+0xb0/0x1b8 [122235.050930] arch_timer_handler_phys+0x2c/0x44 [122235.050940] handle_perCPU_devid_irq+0x5c/0x104 [122235.050951] generic_handle_irq+0x24/0x3c [122235.050958] __handle_domain_irq+0x9c/0xa0 [122235.050965] gic_handle_irq+0x2d0/0x30c [122235.050975] el1_irq+0xcc/0x180 [122235.050982] arch_cpu_idle+0x30/0x38 [122235.050991] default_idle_call+0x30/0x3c [122235.050999] do_idle+0x144/0x270 [122235.051008] cpu_startup_entry+0x24/0x54 [122235.051015] secondary_start_kernel+0x1a4/0x1bc [122236.028018] [S0][V0]pym_subdev_stop [122236.028038] pym_check_stop_state cnt 10 pym->irq_status = 4 [122236.046863] pym_check_exit_state cnt 9 pym->irq_status = 4 [122236.061751] SMP: stopping secondary CPUs [122236.062276] Kernel Offset: disabled [122236.062730] CPU features: 0x0040426,2a00aa38 [122236.063284] Memory Limit: none所以,当出现 RCU Stall 问题一般是出现了调度问题:
长时间关闭硬/软中断、中断风暴,RCU 软中断无法执行。长时间关闭强占。高优先级 RT 进程占用 CPU 导致 rcu 线程无法执行。由于 RT 版本中软中断由 cfs:19 优先级的 ksoftirqd 负责,rcu 软中断的工作可能被各种高优先级强占导致超时。从 RCU Stall 的 log 中能看到发生 Rcu Stall 的核,检查对应 core 上进程,及调度情况定位问题,这种问题最好打开 ftrace,或者至少打开 CONFIG_SCHED_LOGGER 抓取到各核的调度信息才能更快的分析。解决 RCU Stall 问题的方案:
检查是否存在高负载的 RT 进程一直被调用。如果存在,请评估是否降低为非 RT 进程,或者降低优先级。调整 RCU Stall Timeout。修改/sys/module/rcupdate/parameters/rcu_cpu_stall_timeout。检查/proc/interrupts 中所有中断的次数,排除是否是中断风暴导致。如下面的 evt_thread 进程每次调度都会占用 1s 时间:
[122233.054801] [6] : swapper/6(0) -> evt_thread0(26886)[122234.026784] [6] : evt_thread0(26886) -> swapper/6(0)[122234.028451] [6] : swapper/6(0) -> grep(14873)[122234.028515] [6] : grep(14873) -> swapper/6(0)[122234.051471] [6] : swapper/6(0) -> grep(14873)[122234.051541] [6] : grep(14873) -> swapper/6(0)[122234.054793] [6] : swapper/6(0) -> evt_thread0(26886)[122235.030776] [6] : evt_thread0(26886) -> swapper/6(0)来源:墨码行者一点号
