驱动压测中报错watchdog: BUG: soft lockup - CPU#5 stuck for 22s

        在某国产兆芯CPU硬件平台项目的驱动调测过程中曾经碰到的一个异常问题：watchdog: BUG: soft lockup - CPU#5 stuck for 22s。

1 问题现象

        在该项目中，密码卡驱动的输入报文流主要来自两个方向：

1. 本地密码服务API调用：本地各应用服务的密码请求报文通过应用API发送报文到密码卡驱动。
2. 内核网络旁路方向：通过netfilter框架hook点拦截来自网卡驱动的网络请求报文并发送到密码卡驱动。

        前期的系统压测都只是构造单个方向的业务请求报文分别压测，系统都工作正常；后来改为同时发送两个方向的报文压测，结果系统出现了异常，在串口上通过dmesg获取的系统异常信息如下：

[  457.039936] watchdog: BUG: soft lockup - CPU#5 stuck for 22s! [busihandle:4664]

... ... ... ...(省略无关信息)

[  457.048018] Call Trace:

[  457.048019]  <IRQ>

[  457.048021]  ? show_regs.cold+0x1a/0x1f

[  457.048024]  ? watchdog_timer_fn.cold+0x47/0xa0

[  457.048026]  ? __hrtimer_run_queues+0xfb/0x280

[  457.048028]  ? softlockup_fn+0x50/0x50

[  457.048031]  ? hrtimer_interrupt+0x109/0x220

[  457.048033]  ? smp_apic_timer_interrupt+0x71/0x140

[  457.048035]  ? apic_timer_interrupt+0xf/0x20

[  457.048037]  ? apic_timer_interrupt+0xa/0x20

[  457.048039]  ? native_queued_spin_lock_slowpath+0x60/0x1d0

[  457.048043]  ? sprintf+0x56/0x70

[  457.048044]  _raw_spin_lock+0x1e/0x30

[  457.048052]  tsr_rxMsgProc+0x7d/0x370 [djtdl]

[  457.048061]  djup_rxhook+0x2ee/0x490 [djtdl]

... ... ... ...(省略无关信息)

[  457.048096]  net_rx_action+0x13a/0x380

[  457.048098]  __do_softirq+0xe1/0x2d6

[  457.048102]  irq_exit+0xae/0xb0

[  457.048104]  do_IRQ+0x5a/0xf0

[  457.048106]  common_interrupt+0xf/0xf

[  457.048107]  </IRQ>

[  457.048108] RIP: 0010:_raw_spin_lock+0x10/0x30

[  457.048110] Code: ff 01 00 00 75 07 4c 89 e0 41 5c 5d c3 e8 28 ef 60 ff 4c 89 e0 41 5c 5d c3 90 66 66 66 66 90 31 c0 ba 01 00 00 00 f0 0f b1 17 <75> 01 c3 55 89 c6 48 89 e5 e8 72 d5 60 ff 66 90 5d c3 66 66 2e 0f

[  457.048111] RSP: 0018:ffffb768c292be30 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffd3

[  457.048112] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000006

[  457.048113] RDX: 0000000000000001 RSI: 0000000000000002 RDI: ffff982cb8a1c358

[  457.048114] RBP: ffffb768c292be68 R08: 0000001000000010 R09: 0000000000000060

[  457.048115] R10: ffff982cdcc07480 R11: 0000000040000000 R12: ffff982cb8a1c358

[  457.048116] R13: ffff982cb8a18000 R14: 0000000000000000 R15: 0000000000000000

[  457.048125]  ? tsr_apiMsgProc+0xb6/0x590 [djtdl]

[  457.048133]  tsr_dev_write+0x88/0xb0 [djtdl]

[  457.048135]  __vfs_write+0x1b/0x40

[  457.048137]  vfs_write+0xb9/0x1a0

[  457.048139]  ksys_write+0x67/0xe0

[  457.048141]  __x64_sys_write+0x1a/0x20

[  457.048143]  do_syscall_64+0x57/0x190

[  457.048145]  entry_SYSCALL_64_after_hwframe+0x5c/0xc1

... ... ... ...(省略无关信息)

2 原因分析

从上述系统异常日志可以分析到：

1. 系统时间457.048秒左右，应用层调用API（通过系统文件写命令__x64_sys_write）=》驱动层tsr_dev_write=》 tsr_apiMsgProc=》_raw_spin_lock，进入原子锁时此应用线程被系统调度中断挂起（此调用过程对应前述“本地密码服务API调用”）；
2. 系统中断do_IRQ=》djup_rxhook（驱动层钩子函数）=》tsr_rxMsgProc=》_raw_spin_lock再次进入原子锁（此调用过程对应前述“内核网络旁路方向”）；

        由于上述两次原子锁调用是同一把锁（用锁保护同一个消息队列），导致了系统死锁，系统watchdog在死锁超时（这里是20s）后发出系统告警“watchdog: BUG: soft lockup - CPU#5 stuck for 22s”，同时死锁也会导致被锁"CPU#5 stuck"，最终系统异常。

3 解决方案

        分析清楚原因之后，对应的解决办法至少有两种：

        1）方案1：问题原因之一是驱动中使用的spin_lock原子锁函数在系统硬中断是可以被打断的，改为使用支持禁用本地硬中断功能的spin_lock_irq原子锁函数，确保在临界区内不会被硬中断打断（spin_lock_irq由于禁用了硬中断，性能开销更大）。

        2）方案2：将来自两个方向的请求报文分别保存到两个不同的驱动工作队列分别处理，每个队列对应一把独立的原子锁，避免前述系统日志中出现的单个原子锁因系统中断导致的重入死锁问题。

        最后考虑到系统性能开销成本（该原子锁的调用比较频繁），项目组采样了方案2。