前言
我手里有两台一加 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。
佬您好,请教一下
手头有一台红米k50u,这台机子有个问题就是无论如何都无法抓到pstore,我把logstore的更改加到gki刷进去在系统触发panic,但是依然没有任何抓到log,是因为LOG_FILE_PATH不能在sdcard下还是什么别的原因
以及这种方法不适合early init的话,卡第一屏应该用什么方法抓取log
谢谢
不能确定原因是不是这个。总之是放在越简单的文件系统里越好,像 sdcard 这种中间叠加了一层 fuse 的,可能还没来得及回写就结束了。卡第一屏很难有什么通用的方法,如果确定内核能起来,是因为系统的原因卡第一屏的话,可以用这个方法 https://blog.xzr.moe/archives/112/ 。但是如果内核都没起来,那最好直接用工程机上 UART 了。
好的,十分感谢
大佬好,我在尝试给魅族20抓取pstore,现在在pstore下可以抓到console-ramoops-0文件,但是这个文件打开后里面的log介于乱码和明文之间,能看出来是log但是其实都是乱码,就像下面这样,谢谢大佬
[ ð.186080]S308pw`@0er0] $hci_`cd2
[ 0.186 84][7*1*ssapper/0\ Ahci-0Ca:
[
这种情况一般是文件损坏了,没有直接的解决方案,以前我偶尔也会遇到,但出现概率不是很高,就当成偶发的硬件错误了。
如果这种情况会一直稳定出现的话,可以考虑把 pstore 的内存区域换个位置,可能是启动早期阶段这块内存被 bootloader 使用了,导致数据被部分覆盖
https://github.com/libxzr/android_kernel_oneplus_sm8250/blob/5d32bedab386e5fc8b2736f52d22d07b078b2058/arch/arm64/boot/dts/vendor/qcom/kona-oem.dtsi#L568