AG35-CEN休眠模式，异常唤醒。问题分析及分享

背景

这几天一直在救火的路上，这不，刚解决了遗留问题数据库操作，触发系统 OOM 机制，客户又报出了一个低功耗情况下，系统被异常唤醒的现象。说实话，当任务分给我时，我内心忐忑的，因为对于所谓的休眠、唤醒概念，我并没有接触过。但是硬着头皮上，最终在一天多的时间内，从了解功能、问题复现、分析现象、定位问题。本文向大家分享我是应对相关问题的方式。

类别	参数
模组型号	AG35_CEN
CPU 型号	armv7l
软件版本	AG35CENFNR07A02M4G_OCPU
内核版本	3.18.44

低功耗模式

对于完全不熟悉的功能，建议先了解其功能、应用场景以及实现原理。

于是，我向模组供应商要了相关文档，了解其功能定义。大致了解到，其低功耗的实现原理是在 linux 系统中定义了两个属性：

1. autosleep。通过 autosleep，模块可达到 Opportunistic suspend 的效果，即系统不持有任何 wakelock 时，可自动进入低功耗模式。
2. wakelock,即唤醒锁机制。autosleep 开启后，只要系统所有的唤醒锁均被释放，则模块可进入低功耗模式；若任一唤醒锁未被释放，则无法进入低功耗模式。

linux 侧休眠的逻辑大致如下：

由该流程可知，休眠异常可能存在两种情况：

1. 设备无法进入休眠模式。其原因有两种：

• 未使能 autosleep
• 持有唤醒锁

2. 休眠模式被异常唤醒。其原因就是触发唤醒源，常见的唤醒源有：

• 语音数据
• 数据
• 短信
• 定时器
• 特定 GPIO 中断

因此正常的软件流程就是：

1. 上电之后，启动软件程序，使能 autosleep。
2. 申请唤醒锁并持有不释放。这样系统就不会进入休眠。
3. 等待休眠通知。
4. 释放唤醒锁。linux 系统进入休眠模式，挂起软件程序。
5. 等待唤醒源，linux 系统唤醒，唤醒软件程序。
   1. 若软件程序需要运行，则继续持有唤醒锁，并不释放。重复步骤二。
   2. 若软件程序不需要运行，则不做任何动作。等待系统再次进入休眠。

其中的休眠通知，在 TBOX 中，一般都是由 ACC OFF 事件触发。大致流程如下：

休眠流程：

1. 当系统正常运行时，MCU 会一直监听 CAN 总线上的数据。
2. 当收到 ACC OFF 信号时，MCU 会通过 UART 串口发送 sleep 消息给模组的应用程序，并拉低 GPIO。
3. 应用程序收到请求后，并判断 GPIO 是否是低电平，且做一系列动作。比如使能 autosleep、释放唤醒锁等。
4. 当 linux kernel，识别到 autosleep 使能，并且没有唤醒锁持有，就会将模组挂起，进入休眠状态。

唤醒流程：

1. MCU 发送 sleep 消息给模组后，也会进入低功耗模式，但是此模式下依旧可以监听 CAN 通道信号。
2. 当 MCU 收到 ACC ON 信号时，MCU 会通过拉高 GPIO，唤醒模组。（因为此时模组已经将程序挂起，无法处理事件通知）
3. linux kernel 收到 GPIO 唤醒源（特定 GPIO 唤醒源）响应。就会将系统拉起，应用程序就会运行。
4. 应用程序此时发现 GPIO 是高电平状态，则说明此时需要 wakeup。因此会再次持有唤醒锁，避免系统休眠。

问题复现

当基本有了分析思路后，就是问题复现了。于是我在测试同事的指导下，进行问题复现。

操作步骤：

1. 程序正常运行时，断开 ACC（模拟 ACC OFF 的场景）。
2. 等待一会，查看系统是否进入休眠模式。

现象一:偶现无法进入休眠。（仅出现一次）

现象二:休眠之后大约 5min 被唤醒，持续 10 多秒后再次进入休眠；之后再过 3min 被唤醒，过了 20 多秒，再次进入休眠。如此反复。

分析：

一、 通过了解休眠流程后，对于无法进入休眠的场景。无非只有两种情况：

• autosleep 未使能。
• 某一应用持有唤醒锁，导致 linux kernel 无法进入休眠模式。

分别确认即可：

确认 autosleep 是否使能,执行下述命令。若结果为mem则说明使能。

~ # cat /sys/power/autosleep
mem

确认系统持有的唤醒锁，执行如下命令。

~ # awk '$6 != 0 {print $1" "$6}' /sys/kernel/debug/wakeup_sources
name active_since
bam_dmux_wakelock 2635015

其中bam_dmux_wakelock就是唤醒锁名称，后续查看该锁被哪一个应用申请即可确认，以及为何没有被释放。因为bam_dmux_wakelock该唤醒锁不是我们申请的，于是通过与模组商沟通，了解到，网口上有数据时，则会持有该锁，当数据停止时，则会释放锁。因此，当时应该是有业务进行下载或上传操作。因为仅出现过一次，也就没有深入研究了。

二、进入休眠之后，再次被唤醒。那么肯定就是唤醒源导致的。无非就是语音数据、网络数据、短信、定时器、特定 GPIO 中断。于是打开相关日志打印，进行分析即可。在串口上，执行以下命令，打开日志开关：

echo 1 > /sys/module/printk/parameters/perf_mode_console
echo 1 > /sys/module/msm_show_resume_irq/parameters/debug_mask
echo 0x2 > /sys/module/ipc_router_core/parameters/debug_mask

此时串口日志的打印会增加很多，我们不需要关注的。待进入休眠之后，窗口打印就会停止，并且设备电流功耗稳定在 4mA 以下（进入低功耗模式的判断方式）。大约 5min 后，串口会继续打印，并在短时间后，又进入休眠。日志输入大致如下：

[  320.755569] [ql_lpm][quectel_low_consume_suspend]: output low
[  320.764404] PM: suspend of devices complete after 28.566 msecs
[  320.765979] PM: late suspend of devices complete after 1.531 msecs
[  320.767204] msm_hs_pm_sys_suspend_noirq:Fail Suspend.clk_cnt:0,clnt_count:0
[  320.771962] PM: noirq suspend of devices complete after 5.942 msecs
[  320.772015] suspend ns:     320771998321     suspend cycles:      13635050280
[  320.771998] CPU0:msm_cpu_pm_enter_sleep mode:3 during suspend
[  320.771998] gic_show_resume_irq: 57 triggered qcom,smd-modem
[  320.771998] gic_show_resume_irq: 200 triggered qcom,smd-rpm
[  320.771998] resume cycles:      17124471324
[  320.773413] [IPCRTR]  CLI RX Len:0x37 T:0x1 CF:0x0 SVC:<0xb:0x1> SRC:<0x3:0x1c> DST:<0x1:0x5a> DATA: 3   000204 10003000
[  320.773422] PM: noirq resume of devices complete after 0.679 msecs
[  320.774337] PM: early resume of devices complete after 0.579 msecs
[  320.783943] msm_serial_hs 78b1000.uart: resule from sleep, msm_uport->obs: 0
[  320.793980] [IPCRTR]  CLI RX Len:0x37 T:0x1 CF:0x0 SVC:<0xb:0x1> SRC:<0x3:0x1c> DST:<0x1:0x5a> DATA: 32000304 10003000
[  320.793985] msm_otg 78d9000.usb: phy_reset:

......

[  326.015811] PM: Syncing filesystems ... done.
[  326.092659] Freezing user space processes ...
[  326.098407] Error: returning -512 value
[  326.104360] mbim_read: Waiting failed
[  326.110197] (elapsed 0.013 seconds) done.
[  326.113180] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done.
[  326.121884] Suspending console(s) (use no_console_suspend to debug)

从日志开始中可以看到：

中断唤醒号为 57，200。模组商的定义是 QMI 唤醒。

上图部分字段说明如下：
CLI RX：表示 QMI 客户端已收到消息，可能是响应（response）或指示（indication），需通过DATA 字段区分；
SVC:<0x3,0x1>：0x3 代表 QMI 的服务类型 NAS。常见的 SVC 唤醒如下：
0x3 NAS 唤醒
0x2a DSD 唤醒
0x5 短信唤醒
0x9 电话唤醒

从这个描述的过程中，我们可以知道因为 moderm 收到了消息，通过 qmi 机制唤醒了 AP 侧。但是至于具体什么原因唤醒的，还不能确认。初步怀疑是网络的报文唤醒的。

验证一

于是我尝试将部分应用关闭（断开和平台的交互），仅保留休眠处理服务，操作如下：

1. 关闭部分应用程序
2. 断开ACC连接。

现象：

1. 在进入休眠模式。
2. 但是在 8min 时也会被唤醒。

串口日志大致如下：

[  584.728895] [ql_lpm][quectel_low_consume_suspend]: output low
[  584.736647] PM: suspend of devices complete after 23.807 msecs
[  584.737923] PM: late suspend of devices complete after 1.239 msecs
[  584.738986] msm_hs_pm_sys_suspend_noirq:Fail Suspend.clk_cnt:0,clnt_count:0
[  584.743111] PM: noirq suspend of devices complete after 5.151 msecs
[  584.743156] suspend ns:     584743141469	suspend cycles:      30407779503
[  584.743141] CPU0:msm_cpu_pm_enter_sleep mode:3 during suspend
[  584.743141] __qpnpint_handle_irq: 38 triggered [0x0, 0x61,0x1] qpnp_rtc_alarm
[  584.743141] gic_show_resume_irq: 200 triggered qcom,smd-rpm
[  584.743141] gic_show_resume_irq: 203 triggered 601d0.qcom,mpm
[  584.743141] gic_show_resume_irq: 222 triggered 200f000.qcom,spmi
[  584.743141] resume cycles:      39620290908
[  584.744821] PM: noirq resume of devices complete after 1.075 msecs
[  584.746599] PM: early resume of devices complete after 0.811 msecs
[  584.757317] msm_serial_hs 78b1000.uart: resule from sleep, msm_uport->obs: 0
[  584.769174] msm_otg 78d9000.usb: phy_reset:

......

[  598.912350] [IPCRTR] CTL MSG: RX cmd:0x7 ADDR: <0x3:0x12>[IPCRTR]  CLI RX Len:0x17 T:0x1 CF:0x0 SVC:<0x3:0x1> SRC:<0x3:0x12> DST:<0x1:0x57> DATA: 4f052f02 02001000
[  598.929141] [IPCRTR] mcm_ril_service SRV TX Len:0x1b T:0x1 CF:0x0 SVC:<0x401:0x1> SRC:<0x1:0x72> DST:<0x1:0x9b> DATA: 07051f02 01001405[  601.208962] PM: suspend entry 2024-03-25 12:27:19.944378300 UTC
[  601.214075] PM: Syncing filesystems ... done.
[  601.250776] Freezing user space processes ...
[  601.256437] Error: returning -512 value
[  601.262692] mbim_read: Waiting failed
[  601.268613] (elapsed 0.014 seconds) done.
[  601.271599] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done.
[  601.280340] Suspending console(s) (use no_console_suspend to debug)

从日志的唤醒源可以知道：

中断唤醒号为 38，且从qpnp_rtc_alarm关键字中可以看出是 RTC 定时器唤起的。

分析现象，进行思考：

1. 通过关闭部分服务，不再触发中断唤醒源 57。说明网络唤醒大概率是外部平台下发的。
2. rtc 唤醒源，基本是由程序进行设置的。需要走读代码。

通过走读代码，发现在进入休眠时，的确有设置定时器的操作（480 秒）。再与同事沟通后，了解到这是业务需求：每隔 8min 唤醒，使stTsp服务向平台发送心跳，避免平台将其踢下线（属于预期）。

验证二：

为了避免 RTC 定时唤醒的影响，于是关闭了 RTC 定时唤醒功能，但其它业务线程保留。操作：

1. 关闭 rtc 定时唤醒。
2. 断开 ACC 连接。

现象：

1. 5min被唤醒，但是仅唤醒一次。

串口输出如下：

[  741.389868] [ql_lpm][quectel_low_consume_suspend]: output low
[  741.397374] PM: suspend of devices complete after 22.864 msecs
[  741.398831] PM: late suspend of devices complete after 1.414 msecs
[  741.399929] msm_hs_pm_sys_suspend_noirq:Fail Suspend.clk_cnt:0,clnt_count:0
[  741.403935] PM: noirq suspend of devices complete after 5.067 msecs
[  741.403984] suspend ns:     741403967935	suspend cycles:      73403410240
[  741.403967] CPU0:msm_cpu_pm_enter_sleep mode:3 during suspend
[  741.403967] gic_show_resume_irq: 200 triggered qcom,smd-rpm
[  741.403967] resume cycles:      75812793361
[  741.405067] PM: noirq resume of devices complete after 0.704 msecs
[  741.406003] PM: early resume of devices complete after 0.592 msecs
[  741.415506] msm_serial_hs 78b1000.uart: resule from sleep, msm_uport->obs: 0
[  741.423718] msm_otg 78d9000.usb: phy_reset: success
[  741.426396] Resume: sysfs_notify wakeup_in
[  741.471100] PM: resume of devices complete after 65.054 msecs
[  741.548343] msm_otg 78d9000.usb: msm_otg_reset motg->inputs=1, motg->id_state=1

其实唤醒是我预期的，因为应用程序可能会存在应用报文唤醒；但是后续不再被唤醒，是我意料之外的。

经过头脑风暴，我有了一个大胆的想法，该报文会不会是 TCP 的 keep alive 报文，用于平台确认 client 是否存活的心跳探包。

1. 5min 时，服务端下发心跳探包。通过 moderm 唤醒 AP 侧，串口进行打印。
2. AP 没有对心跳探包响应（为什么没有响应，还不清楚）。
3. 服务端认为客户端断开连接，释放资源。因此后续不再发送心跳探包。

验证三

为了更进一步确认是否因为平台 TCP 连接导致的问题，于是我就讲stTsp进程中与平台连接的部分代码屏蔽，进行进一步定位。

操作流程：

1. 屏蔽stTsp中关于网络连接的代码。
2. 屏蔽 RTC 定时器。
3. 断开 ACC 连接。

现象：

1. 持续一个多小时，都没有被唤醒。

结论：基本断定是被平台的报文唤醒。需要咨询平台人员。

经过沟通，平台开发人员确定 keep alive 间隔设定的是 300s，与实际情况符合。

最终测试的功耗图也能解释清楚了。

分析：

1. 0 秒时，MPU 设定 8min 的定时器，并进入休眠状态。
2. 300 秒时，因为平台心跳探包下发，导致功耗出现波峰，但很快又进入到休眠。（没有唤醒源持有）
3. 500 秒左右时，RTC 定时器触发，此时和平台发送业务心跳（这个过程应该是：发现连接断开、重新建立连接、发送心跳）。之后也进入到休眠。
4. 800 秒左右，又触发了平台心跳包下发。（800-500=300）
5. 1000 秒左右，则是第二次 RTC 定时器唤醒。

完结，撒花 🎉🎉🎉。

总结

本主要介绍如何分析 AG35-CEN 模组休眠模式被异常唤醒的分析思路。通过一点点排查，分析。最终定位到是 TCP 协议中 keep alive 机制导致的。

令我收获比较大的就是了解到车辆低功耗的整个实现方案，以及遇到相关问题是的大致方向。希望能帮到有需要的朋友。

若我的内容对您有所帮助，还请关注我的公众号。不定期分享干活,剖析案例，也可以一起讨论分享。
我的宗旨：
踩完您工作中的所有坑并分享给您，让你的工作无bug，人生尽是坦途。