记录一次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
确定分析方向
看到这里,其实有两个疑问:
- 为何每次gcore调用栈都是一样的,都指向WLAN Panic,而不是其他线程出现;
- 开机过程中CPU占用几乎全满,但内核线程通常优先级高于用户线程,不应该抢不赢,且持续4秒之久(阈值设置为3900ms);
这两个疑问导向两个分析方向:
- 是否WLAN驱动本身存在逻辑缺陷;
- 是否存在优先级高于内核线程的用户线程长时间占用CPU资源;
解答
关于第1个疑问
与WLAN BSP同事确认,高通对此回复是:tasklet调度太慢,触发driver的内部检测机制,trigger crash,需要Android侧优化CPU占用
结合简单地追踪代码与调用栈,我认为可以总结成如下几点:
- crash是WLAN驱动主动触发的;
- 触发crash的原因从中断请求到tasklet调度,整个耗时太长,触发了WLAN驱动内部检测机制(类似看门狗);
- 这是保护机制,不能去掉,所以需要通过优化CPU占用来规避;
那么第一个疑问算是解答了——每次都是WLAN Panic不是因为WLAN驱动有问题,而是WLAN驱动内部有严格的时延检测机制,而其他模块可能没有;
但是同样生成了新的疑问:这个问题到底是中断没触发,还是触发了以后tasklet依旧没有调度到导致的?
关于第1.1个疑问
驱动与内核实际上我不太了解,因此去查阅了一些资料,并向BSP同事请教了一些基本概念,总结如下:
-
中断会打断内核中进程的正常调度运行,绝大多数情况下不会出现延迟;
——在结合此题的现象:- 中断如果没有被执行,一般都是因为有线程屏蔽了中断或抢占,这种程度的延时必然会出现Hard/Soft Lockup,不过很遗憾,日志中并没有线索指向这点;
- 如果WLAN中断未响应,那同样的会出现其他中断未响应的情况,但是日志中也没有线索指向这点;
综上,不太可能是中断没响应
-
tasklet在下半部执行,运行在中断上下文或者
ksoftirqd
辅助线程,但无论如何,都是可能被RT线程(设置为SCHED_FIFO
或SCHED_RR
调度策略的线程)抢占的; -
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,调用栈与报错日志均与原问题一样;
此时,可以确认:
- 大核簇上过多RT线程会导致WLAN驱动里的软中断响应延时;
然后,多做一些对比,我在重启机器以后,再次重复上述步骤,唯一不同的是,这次我没有把这4个线程设置为RT线程;
于是,无事发生;
此时,另一条结论可以得出:
- 即便CPU满载,但只要不是RT线程抢占,软中断是可以及时响应的;
到这里,问题基本已经定位确认了:开机阶段CPU占用高,其中也有不少RT线程,如果此时它们全被调度到了大核上,那么WLAN的软中断就有可能会被大幅推迟,导致触发其内部的延时检测机制,从而引起Panic,生成gcore;
措施
- 减少应用层的RT线程数量,具体来说,是FIFO线程,因为Android framework中,AMS(ActivityManagerService)有一个属性
sys.use_fifo_ui
被打开了,这会导致前台应用的渲染线程被设置为FIFO调度,而且前台进程的大部分线程对大核调度是有亲和性的,这势必会加剧这个问题出现的概率; - 通过限制、调整RT线程可执行的最长时间片(RT Throttle),来确保其不会把CPU资源耗尽;
- 通过cpuclt等机制,限制上层应用能占用的最大CPU比例,从而保留一定余量给到内核;
措施1实施后,问题就已经不再复现了,因此措施2与3没有实施,而是成为后续持续优化的备选方案;
思考
这个问题涉及到了我很多知识盲区,表面上是WLAN的问题,但实际上牵扯到了Linux内核调度、WLAN驱动,甚至system_server的策略;
整体来说是一个综合性的问题,虽然没有抓到出现问题瞬间的trace(几乎不可能)来直接证明这个结论,但是通过上面梳理,以及措施实施后的效果来看,其正确性是可以被印证的;
当问题解决时,内心还是有那么一点点成就感,感觉自己又进步了一点点。