记录一次WLAN Panic导致的gcore问题分析

记录一次WLAN Panic导致的gcore问题分析

背景

• 高通Q+A架构
• 问题出现在几天前，测试同事大面积报出了开机后直接卡死的问题；经过初步分析，确认是进入了Guest Coredump（gcore）

分析

确认直接原因

解析gcore文件（步骤移步这里），查看kernel log，可以发现是由于WLAN Panic导致：

01-01 00:00:39.520[32.076410]     0     0     0 E [soft_i][0x25ccc6fe][13:42:29.575902] wlan: [0:E:HIF] hif_tasklet_latency: tasklet ce2 latency: from_timer 1, curr_jiffies 4294900315, ce2_tasklet_sched_time 4294898450,ce2_tasklet_exec_time 4294898304, detect_latency_threshold 3900ms detect_latency_timer_timeout 4000ms, cpu_id 1, called: hif_latency_detect_timeout_handler [wlan]
01-01 00:00:39.522[32.077767]     0     0     0 E [soft_i][0x25cd2d04][13:42:29.577262] wlan: [0:E:HIF] hif_credit_latency: credit report latency: from timer 1, curr_jiffies 4294900315, credit_request_time 4294898875,credit_report_time 4294898121, detect_latency_threshold 3900ms, detect_latency_timer_timeout 4000ms, cpu_id 1, called: hif_latency_detect_timeout_handler [wlan]
01-01 00:00:39.523[32.079079]     0     0     0 E [kworke][0x25cd8f96][13:42:29.578576] wlan: [19:E:QDF] cds_trigger_recovery_handler: critical host timeout trigger fw recovery for reason code 24
01-01 00:00:39.523[32.079401]     0     0     0 D cnss    : Start to dump SOC Scratch registers
...
...
...
01-01 00:00:40.222[32.777764]     0     0     0 E WLAN Panic @ cds_trigger_recovery_handler:1995: WLAN recovery is not enabled (via hif_credit_latency:732)
01-01 00:00:40.222[32.777831]     0     0     0 I subsys-restart: subsystem_restart_dev(): Restart sequence requested for wlan_0, restart_level = SYSTEM.
01-01 00:00:40.222[32.777954]     0     0     0 I ------------[ cut here ]------------
01-01 00:00:40.222[32.777956]     0     0     0 D cnss    : PM relax, state: 0xb07, count: 0
01-01 00:00:40.222[32.777958]     0     0     0 F kernel BUG at ../../vendor/qcom/opensource/wlan/qcacld-3.0/.qca6490/cmn/qdf/linux/src/qdf_trace.c:4389!
01-01 00:00:40.222[32.778150]     0     0     0 F Internal error: Oops - BUG: 0 [#1] PREEMPT SMP
01-01 00:00:40.222[32.778219]     0     0     0 I Modules linked in: wlan(O) btpower_new(O) cnss2 pci_msm_drv gvm_spf_machine_dlkm stub_dlkm
01-01 00:00:40.222[32.778336]     0     0     0 I CPU: 1 PID: 19 Comm: kworker/1:0 Tainted: G           O      5.4.219-qgki-debug-g5a2838044f45 #1
01-01 00:00:40.222[32.778468]     0     0     0 I Hardware name: Qualcomm Technologies, Inc. Direwolf Single LA Virtual Machine (DT)
01-01 00:00:40.223[32.778774]     0     0     0 I Workqueue: cds_recovery_workqueue __qdf_defer_func.cfi_jt [wlan]
01-01 00:00:40.223[32.778877]     0     0     0 I pstate  : 60c00005 (nZCv daif +PAN +UAO)
01-01 00:00:40.223[32.779126]     0     0     0 I pc      : __qdf_bug+0x0/0x4 [wlan]
01-01 00:00:40.223[32.779360]     0     0     0 I lr      : cds_trigger_recovery_work+0x4ac/0x4b0 [wlan]
01-01 00:00:40.223[32.779527]     0     0     0 I sp      : ffffffc013d13d00

确定分析方向

看到这里，其实有两个疑问：

1. 为何每次gcore调用栈都是一样的，都指向WLAN Panic，而不是其他线程出现；
2. 开机过程中CPU占用几乎全满，但内核线程通常优先级高于用户线程，不应该抢不赢，且持续4秒之久（阈值设置为3900ms）；

这两个疑问导向两个分析方向：

1. 是否WLAN驱动本身存在逻辑缺陷；
2. 是否存在优先级高于内核线程的用户线程长时间占用CPU资源；

解答

关于第1个疑问

与WLAN BSP同事确认，高通对此回复是：tasklet调度太慢，触发driver的内部检测机制，trigger crash，需要Android侧优化CPU占用

结合简单地追踪代码与调用栈，我认为可以总结成如下几点：

1. crash是WLAN驱动主动触发的；
2. 触发crash的原因从中断请求到tasklet调度，整个耗时太长，触发了WLAN驱动内部检测机制（类似看门狗）；
3. 这是保护机制，不能去掉，所以需要通过优化CPU占用来规避；

那么第一个疑问算是解答了——每次都是WLAN Panic不是因为WLAN驱动有问题，而是WLAN驱动内部有严格的时延检测机制，而其他模块可能没有；

但是同样生成了新的疑问：这个问题到底是中断没触发，还是触发了以后tasklet依旧没有调度到导致的？

关于第1.1个疑问

驱动与内核实际上我不太了解，因此去查阅了一些资料，并向BSP同事请教了一些基本概念，总结如下：

1. 中断会打断内核中进程的正常调度运行，绝大多数情况下不会出现延迟；
   ——在结合此题的现象：

   • 中断如果没有被执行，一般都是因为有线程屏蔽了中断或抢占，这种程度的延时必然会出现Hard/Soft Lockup，不过很遗憾，日志中并没有线索指向这点；
   • 如果WLAN中断未响应，那同样的会出现其他中断未响应的情况，但是日志中也没有线索指向这点；

   综上，不太可能是中断没响应

2. tasklet在下半部执行，运行在中断上下文或者ksoftirqd辅助线程，但无论如何，都是可能被RT线程（设置为SCHED_FIFO或SCHED_RR调度策略的线程）抢占的；

3. WLAN驱动设置了中断亲和力（Affinity），要求在大核运行；

那么关于这个疑问的结论就比较明显了：应该是下半部，也就是此处的tasklet没有执行；

关于第2个疑问

其实，上面也解答了这个疑问，此问题大概率就是tasklet由于被RT线程抢占，导致响应延迟；

验证

首先，为了尝试复现这个现象，我需要创建几个RT线程来抢占CPU资源；
由于此前通过BSP同事的科普，我知道WLAN中断只会在大核处理，那么理论上只需要创建4个RT线程，就可以占满所有大核；

因此首先，我通过如下方式创建了4个线程：

# 创建一个后台线程，执行死循环逻辑，执行4次，即为4个线程
$ while true;do cat /dev/random > /dev/null; done &

此时这4个线程调度策略应该是默认的SCHED_OTHER(SCHED_NORMAL)，于是借助chrt命令依次将其修改为RT线程：

// -r 表示 SCHED_RR
// -p <$tid> 则是指定线程id
// 99 是RT线程可设置的最大优先级
# chrt -r -p <$tid> 99
// 如此执行4次

最后，利用cpuset这个cgroup子系统，我将这4个线程限制在大核运行：

// 创建一个cpuset分组，配置为仅大核运行
# mkdir /dev/cpuset/gold
...
// 本机大核为CPU0/1/2/3
# echo 0-3 > /dev/cpuset/gold/cpus
// 依次将4个线程移至该分组
# echo <$tid> > /dev/cpuset/gold/task

然后，Android侧直接触发gcore了，导出解析后查看kernel log，调用栈与报错日志均与原问题一样；

此时，可以确认：

1. 大核簇上过多RT线程会导致WLAN驱动里的软中断响应延时；

然后，多做一些对比，我在重启机器以后，再次重复上述步骤，唯一不同的是，这次我没有把这4个线程设置为RT线程；

于是，无事发生；

此时，另一条结论可以得出：

2. 即便CPU满载，但只要不是RT线程抢占，软中断是可以及时响应的；

到这里，问题基本已经定位确认了：开机阶段CPU占用高，其中也有不少RT线程，如果此时它们全被调度到了大核上，那么WLAN的软中断就有可能会被大幅推迟，导致触发其内部的延时检测机制，从而引起Panic，生成gcore；

措施

1. 减少应用层的RT线程数量，具体来说，是FIFO线程，因为Android framework中，AMS（ActivityManagerService）有一个属性sys.use_fifo_ui被打开了，这会导致前台应用的渲染线程被设置为FIFO调度，而且前台进程的大部分线程对大核调度是有亲和性的，这势必会加剧这个问题出现的概率；
2. 通过限制、调整RT线程可执行的最长时间片（RT Throttle），来确保其不会把CPU资源耗尽；
3. 通过cpuclt等机制，限制上层应用能占用的最大CPU比例，从而保留一定余量给到内核；

措施1实施后，问题就已经不再复现了，因此措施2与3没有实施，而是成为后续持续优化的备选方案；

思考

这个问题涉及到了我很多知识盲区，表面上是WLAN的问题，但实际上牵扯到了Linux内核调度、WLAN驱动，甚至system_server的策略；

整体来说是一个综合性的问题，虽然没有抓到出现问题瞬间的trace（几乎不可能）来直接证明这个结论，但是通过上面梳理，以及措施实施后的效果来看，其正确性是可以被印证的；

当问题解决时，内心还是有那么一点点成就感，感觉自己又进步了一点点。