前言

我手里有两台一加 8250 平台的机子,一台小 8 ,一台 8T 。照理说这两台机子的硬件上的区别应该不大,但是这台 8T 从出厂系统开始,我就没有成功获得过一次 pstore ,warm reset 之后开机看 pmic 的日志还是 cold boot,非常的诡异。相反,这台小 8 的 pstore 则一直工作正常。我甚至非常怀疑这台 8T 的 pmic 固件是不是有什么猫病。

无奈,小 8 是主力机,没法天天拿来调试。于是糊了个在 panic 时转储日志到本地文件 / 指定分区的方案,也算是对 pstore 的一个小替代吧。

源码

https://github.com/libxzr/kernel-playground/commits/playground/logstore

是基于高通 4.19 平台的,别的平台可能需要移植一下。

细节

单纯转储日志还是很简单的,利用 kmsg_dump 相关的 api 把日志从 buffer 里拿出来,再转储到文件里即可。这里的关键点是在于,该在何时转储日志。
panic 的流程大概可以概括为以下几个阶段:

  • 进入 panic() 函数。
  • 在本 CPU 上禁用中断与抢占。
  • 打印 panic 信息与(本 CPU 的)调用栈。
  • 关闭其它 CPU。
  • 调用各个模块注册的 panic notifier。
  • 调用各个模块注册的 kmsg dumper。
  • 准备重启 / halt 住。

在越是后面的阶段转储日志,得到的日志越是详细。比如在回调各个模块的 panic notifier 和 kmsg dumper 时,它们就很有可能往日志中增加额外的内容。我们所熟悉的 pstore 就是注册在 kmsg dumper 中的。

但是,这一套流程中有一个对转储影响巨大的因素,那就是“关闭其它 CPU”(smp_send_stop())。这里的关闭可不是温柔的 cpu_down(),而是直接发送 IPI 强行下线其它的处理器(ARM64)。要知道,对于正常的热插拔流程,在关闭 CPU 之前至少要把运行在它上面的任务迁移走,还要通知中断控制器不再给这个 CPU 分发中断。但是,panic 时真的是什么都没做就把 CPU 强行下线了,所有上面没有来得及迁移的东西都直接被毁灭了。这一操作其实是导致 panic 时设备直接 freeze 住的直接原因——别的 CPU 啥也不能执行,当前 CPU 被独占只能执行 panic 代码,自然而然设备看起来就像死机了一样。

对于 pstore ,这一操作影响不大,反正它只需要写入指定的内存区域罢了。但是,对于我们这种正儿八经的日志转储,这种操作可能就是毁灭性的。就不说 vfs 了,光光是最底层的存储器驱动就可能依赖于一堆中断和 kthread / queue_work ,这些原本可能跑在别的 CPU 上的东西都被摧毁了,它该怎么转储日志?

所以呐,想要和 pstore 在同一阶段转储日志已经变得非常不靠谱。对于我们这种非常复杂的转储方式来说,最好的选择就是在 down 掉别的 CPU 之前。此时我们虽然不能得到完整的 panic 日志(比如别的 CPU 的调用栈),但是对于得到 panic 的原因以及本 CPU 的调用栈已经非常足够了。

此时我们得到的一个典型日志是长这样的:

[   19.122168] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000000
[   19.122175] Mem abort info:
[   19.122177]   ESR = 0x96000046
[   19.122179]   Exception class = DABT (current EL), IL = 32 bits
[   19.122181]   SET = 0, FnV = 0
[   19.122182]   EA = 0, S1PTW = 0
[   19.122183] Data abort info:
[   19.122185]   ISV = 0, ISS = 0x00000046
[   19.122187]   CM = 0, WnR = 1
[   19.122189] user pgtable: 4k pages, 39-bit VAs, pgdp = 000000003746e1fd
[   19.122191] [0000000000000000] pgd=000000015722b003, pud=000000015722b003, pmd=0000000000000000
[   19.122195] Internal error: Oops: 96000046 [#1] PREEMPT SMP
[   19.122198] Process ScreenDecoratio (pid: 4483, stack limit = 0x00000000b107786d)
[   19.122202] CPU: 4 PID: 4483 Comm: ScreenDecoratio Tainted: G S      W         4.19.157-Horizon-03261204 #3
[   19.122204] Hardware name: Qualcomm Technologies, Inc. kona MTP 19805 (DT)
[   19.122206] pstate: 40400005 (nZcv daif +PAN -UAO)
[   19.122214] pc : hwui_inject1_handler+0x10/0x24
[   19.122219] lr : uprobe_notify_resume+0x530/0xca4
[   19.122220] pc : ffffffa33a4b42b8
[   19.122221] lr : ffffffa339212e3c
[   19.122223] sp : ffffff801e6dbc50
[   19.122224] x29: ffffff801e6dbcb0 x28: 0000000000000080 
[   19.122227] x27: 00000000004000c0 x26: ffffffa33c2b52a8 
[   19.122229] x25: 0000000000000001 x24: 0000000000000000 
[   19.122231] x23: ffffffd3d5f00d18 x22: ffffffd3d5f00d00 
[   19.122233] x21: ffffffd3d5f00dc0 x20: ffffffd40d5b0000 
[   19.122234] x19: ffffff801e6dbec0 x18: 0000000000000000 
[   19.122236] x17: 0000000000000000 x16: 0000000000000000 
[   19.122238] x15: 0000000000000000 x14: 0000003103bac000 
[   19.122240] x13: ffffffa33bf6b9a0 x12: 16157c9af96779a3 
[   19.122242] x11: e9895543204eefdc x10: e9ea834ef4b11023 
[   19.122244] x9 : ffffffa33a4b42a8 x8 : 0000000000000000 
[   19.122246] x7 : 0000000000000000 x6 : 000000000000003f 
[   19.122247] x5 : 0000000000000040 x4 : 0000000000000000 
[   19.122249] x3 : 0000000000000004 x2 : 0000000000000000 
[   19.122251] x1 : ffffff801e6dbec0 x0 : 0000000000000000 
[   19.122253] Call trace:
[   19.122256]  hwui_inject1_handler+0x10/0x24
[   19.122260]  do_notify_resume+0xe0/0x23cc
[   19.122262]  work_pending+0x8/0x10
[   19.122264] Code: aa1f03e8 90000009 910aa129 2a1f03e0 (f9000109) 
[   19.122267] ---[ end trace cb552490e52b4757 ]---
[   19.126648] binder: context.name[binder] tr.size:152 service:qti.radio.extphone
[   19.126649] bt_configure_gpios: BTON:Turn Bt Off bt-reset-gpio(1121) value(0)
[   19.126710] Kernel panic - not syncing: Fatal exception
[   19.126735] save_dump_reason_to_smem: info : Fatal exception
[   19.126739] 
save_dump_reason_to_smem: dump_reason : Fatal exception reason_len=15 function caused panic :die name_len=3 
[   19.126770] bt_configure_gpios: BTON:Turn Bt Off
[   19.126777] bt_configure_gpios: bt-sw-ctrl-gpio(1224) value(1)
[   19.126780] bt_enable_bt_reset_gpios_safely: bt_enable_bt_reset_gpios_safely: BTON: Asserting BT_EN
[   19.138935] oplus_binder_stats binder_stats_driver_ioctl: unknown ioctl cmd:120
[   19.139622] oplus_binder_stats binder_stats_driver_ioctl: unknown ioctl cmd:120

其实还不错。
这种转储方式有一个非常重要的前提假设是:panic 既不是 vfs 相关东西导致的,也不是存储驱动导致的。不然真就直接升天了。
而且这种转储方式并不适用于启动早期造成的 panic ,此时相关的文件系统可能根本就还没挂载好,想要转储日志也是无稽之谈。

还有一个点,也许我们真的需要区分一下什么才是 panic 。我所认为的 panic 必然是需要调用到 panic() 函数的,就比如上面的空指针异常,是由缺页中断的相关处理函数经过一系列判断后主动调用的 panic() ,这整个调用过程都是稳定可控的,全程代码并没有“跑飞”,也没有发生死锁。

但是还有一种情况,那就是代码“跑飞”或死锁了,系统整个死掉了,panic() 函数并没有被调用。此时展现出的状况也是死机重启,但是这时的重启往往是由 watchdog 触发的,而非在 panic() 函数中调用的重启方法。这种情况下,很显然日志是不会转储的,甚至 pstore 也大概率不会生效。

有一种测试代码是否“跑飞”的方法是把 CONFIG_PANIC_TIMEOUT 设为 0 。此时系统如果 panic ,那么将会一直 freeze 住不会重启(因为 panic 函数会主动喂狗),而如果是代码“跑飞”了,那么 watchdog 照样会按时触发系统重启。

为了方便测试,有一种触发典型 panic 的方法是 echo c > /proc/sysrq-trigger ,它依赖于 CONFIG_MAGIC_SYSRQ

就到这里吧 88。