一、问题现象

死机

二、问题分析

2.1 初步定位问题类型

查看dmesg_TZ.txt

[161726.646617][    C0] gh-watchdog hypervisor:qcom,gh-watchdog: QCOM Apps Watchdog bark! Now = 161726.646605
[161726.646652][    C0] gh-watchdog hypervisor:qcom,gh-watchdog: QCOM Apps Watchdog last pet at 161706.646098
[161726.646663][    C0] gh-watchdog hypervisor:qcom,gh-watchdog: cpu alive mask from last pet ff

从离线解析的dump日志中,我们可以轻松定位出发生了watchdog 死机。

last pet : 161706s

bark time: 161726s

20s时间内都没有喂狗

2.2 查看watchdog

----------begin Watchdog----------
Non-secure Watchdog data
Pet time: 15.0s
Bark time: 20.0s
Watchdog last pet: 161706.000
Watchdog pet timer not expired
Current jiffies crossed pet_timer expires jiffies
CPU online bits: 11111111
CPU runqueue online bits: 11111111
CPU isolated bits: 00000000
CPU dying bits: 00000000
pet_timer_flags: 0x26800003
pet_timer_expires: 4335322726
Current jiffies  : 4335324028
Timestamp of last timer interrupt(last_jiffies_update): 161726.924
tick_do_timer_cpu: 3
CPU logical map: [0, 1, 2, 3, 4, 5, 6, 7]
tick_broadcast_oneshot_mask: 00000000
tick_broadcast_pending_mask: 00000000
tick_broadcast_force_mask: 00000000
tick_broadcast_device cpumask: 11111111
tick_broadcast_device next_event: 9223372036.854776
CPU0 tick_device next_event: 161726.720000
CPU1 tick_device next_event: 161726.928000
CPU2 tick_device next_event: 161726.928000
CPU3 tick_device next_event: 161726.928000
CPU4 tick_device next_event: 161726.940000
CPU5 tick_device next_event: 161726.940000
CPU6 tick_device next_event: 161726.940000
CPU7 tick_device next_event: 161726.940000
CPU#0 : ping_start: 161706.646000 : ping_end: 161706.646013
CPU#1 : ping_start: 161706.646013 : ping_end: 161706.646044
CPU#2 : ping_start: 161706.646044 : ping_end: 161706.646053
CPU#3 : ping_start: 161706.646053 : ping_end: 161706.646053
CPU#4 : ping_start: 161706.646054 : ping_end: 161706.646063
CPU#5 : ping_start: 161706.646064 : ping_end: 161706.646070
CPU#6 : ping_start: 161706.646071 : ping_end: 161706.646080
CPU#7 : ping_start: 161706.646080 : ping_end: 161706.646088
timer_fired : 161706.645948
thread_start : 161706.645999
------------end Watchdog----------
  • Pet time = 15 s
    系统每隔 15 秒要触发一次“喂狗”操作(schedule pet_timer)。

  • Bark time = 20 s
    如果 20 秒内仍未再次“喂狗”,则 Watchdog 会“bark”并最终“bite”。

  • last pet = 161706.000
    最后一次真实的喂狗动作记录在内核时间戳 161706.000 s。

  • jiffies & expires

    • pet_timer_expires = 4335322726:以 jiffies 为单位,下一次计划触发喂狗动作的时刻。

    • Current jiffies = 4335324028:当前系统 jiffies。

    • 由于 4335324028 > 4335322726,说明本该在此时触发的 pet_timer 已经“错过”

  • ping_start

CPU#0 : ping_start: 161706.646000 → ping_end: 161706.646013
CPU#1 : ping_start: 161706.646013 → ping_end: 161706.646044
…
CPU#7 : ping_start: 161706.646080 → ping_end: 161706.646088

所有cpu的ping_start都是161706s的那次喂狗的时间点触发的记录。
这里我们要解释一下第四点和第五点
pet_timer 是以定时器(hrtimer 或 jiffies_timer)的方式注册在内核定时器链表上。上述“expires < current”说明定时器回调本应在 jiffies=4335322726 时触发,但在当前 jiffies 已到 4335324028 仍未执行。

这种情况常见于:

  • 全局中断被长时间禁止(local_irq_disable/uninterruptible section)。

  • 内核处于某些 critical section,例如大批量的自旋锁持有或软中断/任务let 被无限阻塞。

每次 pet_timer(喂狗定时器)到期时,Watchdog 会在各个 CPU 上发起一次 ping,记录下 ping_start 和 ping_end。

  • 因此,这两个时间戳反映的是上一次定时器回调成功执行的时刻。

从前面的 dump 可以看到,pet_timer 应该在 jiffies=4335322726 时触发,但由于定时器链路被阻塞(tick 漏调度、全局中断被屏蔽或 nohz 模式问题),它一直没跑,所以也就没机会重新发 ping,也就没有新的 ping_start 时间戳。

此处内容已隐藏,「评论可见」