在某车载项目上，因为其中多域使用了can总线通信，系统使用麒麟，在大负载的情况下，低概率会触发死机问题。死机伴随着rcu stall信息。很明显，这是一个典型的死核的问题，本文主要总结和分享此问题。

复现问题

根据描述的现象，首先就是需要针对现场问题寻找复现办法，可以了解到问题是can通信导致的rcu，所以可以简单通过脚本测试，如下


while true
do
cansend can0 1f602001#00000000D0570068
done

日志

根据上面的测试脚本，内核跑一段时间就出来rcu stall了，其日志如下


[ 815.850352] rcu: INFO: rcu_sched self-detected stall on CPU
[ 815.855942] rcu: 0-....: (17844 ticks this GP) idle=d1a/1/0x4000000000000004 softirq=29552/29558 fqs=6000
[ 815.865680] (t=18000 jiffies g=51353 q=2202)
[ 815.870039] Task dump for CPU 0:
[ 815.873269] task:kworker/0:0 state:R running task stack: 0 pid: 1131 ppid: 2 flags:0x0000000a
[ 815.883192] Workqueue: events_freezable input_dev_poller_work
[ 815.888937] Call trace:
[ 815.891389] dump_backtrace+0x0/0x1a8
[ 815.895052] show_stack+0x2c/0x38
[ 815.898370] sched_show_task+0x12c/0x148
[ 815.902299] dump_cpu_task+0x48/0x54
[ 815.905879] rcu_dump_cpu_stacks+0xec/0xf8
[ 815.909977] rcu_sched_clock_irq+0x274/0x6c8
[ 815.914254] update_process_times+0x68/0x90
[ 815.918437] tick_sched_handle.isra.16+0x50/0x64
[ 815.923050] tick_sched_timer+0x50/0x90
[ 815.926893] __hrtimer_run_queues+0x170/0x23c
[ 815.931254] hrtimer_interrupt+0xb4/0x1b8
[ 815.935267] arch_timer_handler_phys+0x38/0x50
[ 815.939713] handle_percpu_devid_irq+0x6c/0x124
[ 815.944243] generic_handle_irq_desc+0x10/0x18
[ 815.948688] __handle_domain_irq+0xbc/0xc4
[ 815.952785] gic_handle_irq+0x2c0/0x30c
[ 815.956627] el1_irq+0xcc/0x180
[ 815.959775] slab_free_freelist_hook+0x0/0xf0
[ 815.964136] skb_free_head+0x38/0x3c
[ 815.967716] skb_release_data+0x64/0xb4
[ 815.971558] skb_release_all+0x30/0x3c
[ 815.975306] __kfree_skb+0x20/0x34
[ 815.978705] consume_skb+0x38/0x44
[ 815.982117] can_receive+0x90/0xf8
[ 815.985526] can_rcv+0xac/0xbc
[ 815.988589] __netif_receive_skb_one_core+0x6c/0x94
[ 815.993466] __netif_receive_skb+0x78/0x80
[ 815.997562] process_backlog+0xac/0x15c
[ 816.001405] net_rx_action+0x148/0x328
[ 816.005152] __do_softirq+0x228/0x2d4
[ 816.008816] __irq_exit_rcu+0x48/0x94
[ 816.012479] irq_exit+0x14/0x20
[ 816.015626] __handle_domain_irq+0xc0/0xc4
[ 816.019721] gic_handle_irq+0x2c0/0x30c
[ 816.023563] el1_irq+0xcc/0x180
[ 816.026710] __schedule+0x40c/0x5d0
[ 816.030204] preempt_schedule_common+0x10/0x24
[ 816.034648] _cond_resched+0x20/0x38
[ 816.038227] mutex_lock+0x1c/0x44
[ 816.041544] iio_read_channel_processed+0x2c/0xd0
[ 816.046253] adc_keys_poll+0x40/0x130
[ 816.049917] input_dev_poller_work+0x28/0x3c
[ 816.054194] process_one_work+0x1d4/0x28c
[ 816.058205] worker_thread+0x1d0/0x260
[ 816.061954] kthread+0xf0/0x100
[ 816.065101] ret_from_fork+0x10/0x18
[ 900.973670] rcu: INFO: rcu_sched self-detected stall on CPU
[ 900.979258] rcu: 0-....: (17996 ticks this GP) idle=d1a/1/0x4000000000000004 softirq=29563/29765 fqs=6000
[ 900.988996] (t=18000 jiffies g=51361 q=715)
[ 900.993271] Task dump for CPU 0:
[ 900.996500] task:kworker/0:0H state:R running task stack: 0 pid: 6 ppid: 2 flags:0x0000000a
[ 901.006426] Workqueue: 0x0 (mmc_complete)
[ 901.010528] Call trace:
[ 901.012980] dump_backtrace+0x0/0x1a8
[ 901.016644] show_stack+0x2c/0x38
[ 901.019961] sched_show_task+0x12c/0x148
[ 901.023889] dump_cpu_task+0x48/0x54
[ 901.027468] rcu_dump_cpu_stacks+0xec/0xf8
[ 901.031565] rcu_sched_clock_irq+0x274/0x6c8
[ 901.035842] update_process_times+0x68/0x90
[ 901.040023] tick_sched_handle.isra.16+0x50/0x64
[ 901.044637] tick_sched_timer+0x50/0x90
[ 901.048480] __hrtimer_run_queues+0x170/0x23c
[ 901.052841] hrtimer_interrupt+0xb4/0x1b8
[ 901.056854] arch_timer_handler_phys+0x38/0x50
[ 901.061299] handle_percpu_devid_irq+0x6c/0x124
[ 901.065830] generic_handle_irq_desc+0x10/0x18
[ 901.070275] __handle_domain_irq+0xbc/0xc4
[ 901.074370] gic_handle_irq+0x2c0/0x30c
[ 901.078212] el1_irq+0xcc/0x180
[ 901.081359] trace_consume_skb+0x10/0x7c
[ 901.085286] consume_skb+0x30/0x44
[ 901.088687] can_receive+0x90/0xf8
[ 901.092086] can_rcv+0xac/0xbc
[ 901.095148] __netif_receive_skb_one_core+0x6c/0x94
[ 901.100025] __netif_receive_skb+0x78/0x80
[ 901.104122] process_backlog+0xac/0x15c
[ 901.107964] net_rx_action+0x148/0x328
[ 901.111712] __do_softirq+0x228/0x2d4
[ 901.115376] __irq_exit_rcu+0x48/0x94
[ 901.119039] irq_exit+0x14/0x20
[ 901.122186] __handle_domain_irq+0xc0/0xc4
[ 901.126281] gic_handle_irq+0x2c0/0x30c
[ 901.130123] el1_irq+0xcc/0x180
[ 901.133269] _cond_resched+0x10/0x38
[ 901.136848] mutex_lock+0x1c/0x44
[ 901.140163] set_pf_worker+0x24/0x5c
[ 901.143743] worker_thread+0x6c/0x260
[ 901.147406] kthread+0xf0/0x100
[ 901.150552] ret_from_fork+0x10/0x18
[ 1056.446969] rcu: INFO: rcu_sched self-detected stall on CPU
[ 1056.452557] rcu: 0-....: (17835 ticks this GP) idle=d1a/1/0x4000000000000004 softirq=29774/29878 fqs=6000
[ 1056.462294] (t=18003 jiffies g=51369 q=1254)
[ 1056.466655] Task dump for CPU 0:
[ 1056.469884] task:kworker/0:0H state:R running task stack: 0 pid: 6 ppid: 2 flags:0x0000000a
[ 1056.479806] Workqueue: 0x0 (mmc_complete)
[ 1056.483908] Call trace:
[ 1056.486360] dump_backtrace+0x0/0x1a8
[ 1056.490024] show_stack+0x2c/0x38
[ 1056.493342] sched_show_task+0x12c/0x148
[ 1056.497269] dump_cpu_task+0x48/0x54
[ 1056.500848] rcu_dump_cpu_stacks+0xec/0xf8
[ 1056.504945] rcu_sched_clock_irq+0x274/0x6c8
[ 1056.509222] update_process_times+0x68/0x90
[ 1056.513404] tick_sched_handle.isra.16+0x50/0x64
[ 1056.518017] tick_sched_timer+0x50/0x90
[ 1056.521860] __hrtimer_run_queues+0x170/0x23c
[ 1056.526221] hrtimer_interrupt+0xb4/0x1b8
[ 1056.530233] arch_timer_handler_phys+0x38/0x50
[ 1056.534679] handle_percpu_devid_irq+0x6c/0x124
[ 1056.539209] generic_handle_irq_desc+0x10/0x18
[ 1056.543654] __handle_domain_irq+0xbc/0xc4
[ 1056.547750] gic_handle_irq+0x2c0/0x30c
[ 1056.551592] el1_irq+0xcc/0x180
[ 1056.554740] __slab_free+0x124/0x2a0
[ 1056.558319] kfree+0x218/0x238
[ 1056.561380] skb_free_head+0x38/0x3c
[ 1056.564960] skb_release_data+0x64/0xb4
[ 1056.568803] skb_release_all+0x30/0x3c
[ 1056.572550] __kfree_skb+0x20/0x34
[ 1056.575949] consume_skb+0x38/0x44
[ 1056.579349] can_receive+0x90/0xf8
[ 1056.582759] can_rcv+0xac/0xbc
[ 1056.585821] __netif_receive_skb_one_core+0x6c/0x94
[ 1056.590698] __netif_receive_skb+0x78/0x80
[ 1056.594795] process_backlog+0xac/0x15c
[ 1056.598637] net_rx_action+0x148/0x328
[ 1056.602384] __do_softirq+0x228/0x2d4
[ 1056.606049] __irq_exit_rcu+0x48/0x94
[ 1056.609712] irq_exit+0x14/0x20
[ 1056.612858] __handle_domain_irq+0xc0/0xc4
[ 1056.616954] gic_handle_irq+0x2c0/0x30c
[ 1056.620796] el1_irq+0xcc/0x180
[ 1056.623942] __schedule+0x108/0x5d0
[ 1056.627436] preempt_schedule_common+0x10/0x24
[ 1056.631880] _cond_resched+0x20/0x38
[ 1056.635459] mutex_lock+0x1c/0x44
[ 1056.638774] set_pf_worker+0x24/0x5c
[ 1056.642353] worker_thread+0x6c/0x260
[ 1056.646016] kthread+0xf0/0x100
[ 1056.649162] ret_from_fork+0x10/0x18

rcu_sched

这里借助内核的文档可以理解 * https://www.kernel.org/doc/html/v5.10/RCU/stallwarn.html

简单理解就是：内核在每个cpu上的任务，没有任何的机会调用schedule切出，一定时间后，抛出日志以及每个cpu上监听rcu的结构体的值。

那么所有的点都可以围绕到没有办法schedule的代码语义中，这种代码语义有如下场景：

禁用中断
禁用buttom half
禁用抢占
禁用timer
中断风暴

当然，文中还提到一下corner cases，其中有一个如下

一些rt程序的优先级被强制设置，它会干扰了rcu stall的检测线程，从而导致问题出现

本文的问题在于中断风暴。

分析

根据日志，初步判断堆栈可以知道如下

每次都是在netrx过程的堆栈
softirq的计数会变
cpu核心不变
宽限期gp序号g会变

可以知道，这并不是完全在cpu0上停滞了，而是不断的有softirq在处理，并且softirq的数量特别多，也就意味着很可能有中断风暴。结合日志，中断风暴来自can驱动。

结合现象

初步定位到是中断风暴，那么简单确认系统现象可以知道复现问题的时候，can的硬件中断异常升高，百万级到千万级，ksoftirq 100% kworker 100%。所以可以直接分析can驱动的中断判断问题了。

代码

分析到这，直接从代码找答案即可。关键函数在netif_receive_skb，其代码路径如下


devm_request_irq(rockchip_can_interrupt)
    rockchip_can_err
        netif_receive_skb

这些就比较明朗了，问题来自can总线发送了大量的中断，中断指向了can的错误帧，接下来解析错误帧内容即可。比较重点的寄存器如下


#define BUS_ERR_INT     BIT(6)
#define TX_LOSTARB_INT      BIT(5)
err_code = rockchip_canfd_read(rcan, CAN_ERR_CODE);

这里一个值是0x20，一个是0x40。

对于TX_LOSTARB_INT其原因是总线竞争失败错误，会重新竞争。这个不是问题的原因，只能代表当前总线上负载太高了。
对于 BUS_ERR_INT 是rx接收crc校验错误，然后发送的bus err中断，这个中断特别多，问题出现在这。

根本问题

通过查阅寄存器手册，和不断的打印can的state寄存器，发现芯片存在如下现象：

这个can的ip在发送扩展帧时候，内部寄存器状态值在特定组合条件下，触发load失败，从而最后按标准帧而非扩展帧的格式来发送id和dlc段。
这个can的ip概率性出现CRC校验错误和ID段填充位错误，导致接收方会往总线发送错误帧，由发送方进行重发。

上面两个条件一组合，并且还是在车载多域融合的情况下使用的can通信，那么整个can的通信环境就会出现大量的错误帧，设备接受到错误帧，由控制器主动发送中断，驱动获取中断状态，进而产生中断风暴。

解决办法

到这里，已经知道问题的根本点在于can的控制器在特定情况下触发的中断风暴，所以解决也很简单，芯片问题，驱动只能workaround，也就是屏蔽，操作如下


rockchip_canfd_write(rcan, CAN_INT_MASK, BUS_ERR_INT);

当恢复到正常传输时，再打开 BUS_ERR_INT 中断，这样能够有效的解决此问题，代码如下


val &= ~BUS_ERR_INT;
rockchip_canfd_write(rcan, CAN_INT_MASK, val);

原厂方案

因为芯片已经量产了，这种问题只能规避。如果需要简单有效的办法，建议可以按照上面我的操作，针对此情况屏蔽BUS_ERR_INT中断，恢复后再开启BUS_ERR_INT中断。

反馈原厂后，原厂最后解决办法是禁用软件实现的can_bus_off，通过配置寄存器的方式，重新开关can控制器，这种方法默认代码已经同步了。代码如下


    if (rcan->can.state >= CAN_STATE_BUS_OFF ||
        ((sta_reg & CAN_BUSOFF_FLAG) == CAN_BUSOFF_FLAG)) {
        cancel_delayed_work(&rcan->tx_err_work);
        netif_stop_queue(ndev);
        rockchip_canfd_stop(ndev);
        can_free_echo_skb(ndev, 0);
        rockchip_canfd_start(ndev);
        netif_start_queue(ndev);
    }

无论哪种办法，都能解决问题。

总结

本文通过分享了一个中断风暴带来的rcu stall日志的具体问题，最后的原因还是芯片内部的已知缺陷，通过修改寄存器屏蔽中断或者重新开关can控制器都能解决问题。

通过这个问题的实战，也可以知道，如果一个驱动/硬件可能有缺陷，根据我个人的建议最好还是想办法绑定到其他核心上，如果问题出现在cpu0，那么带来的是系统死机，而问题出现在非cpu0，一切还有挽救的机会。


irq_set_affinity_hint(irq, get_cpu_mask(num_online_cpus() - 1));

目录