3、内核日志分析:dmesg命令、kernel log级别、驱动调试信息、死机分析
内核日志,说白了就是Linux内核的“黑匣子”。系统跑着跑着突然挂了,或者某个驱动死活不干活,第一件事就是翻内核日志。我个人习惯,只要遇到系统异常,二话不说先敲dmesg。这玩意儿比什么调试器都来得快。
3.1 dmesg命令:内核日志的入口
dmesg命令用来读取内核的环形缓冲区(ring buffer)。内核启动时的所有信息、驱动加载的log、硬件报错,全在这里。
基本用法:
# 查看全部内核日志
dmesg
# 实时监控内核日志(类似tail -f)
dmesg -w
# 只看最后20条
dmesg | tail -20
# 清空缓冲区(调试时常用)
dmesg -c
我在项目中遇到过一个问题:某款手机待机一晚后自动重启。查了所有应用层日志都没线索。最后用dmesg一看,发现是某个传感器驱动在深度睡眠时触发了看门狗复位。嗯,这种问题应用层根本看不到。
dmesg -T 可以把时间戳转成人类可读的时间格式。默认是秒数,看着头疼。
3.2 Kernel Log级别:日志的“红绿灯”
内核日志有8个级别,从0到7。数字越小越紧急。你想想看,如果所有日志都打印出来,那屏幕根本刷不完。所以内核用级别来控制哪些日志能出来。
| 级别 | 名称 | 含义 | 典型场景 |
|---|---|---|---|
| 0 | KERN_EMERG | 系统不可用 | 内核崩溃、致命错误 |
| 1 | KERN_ALERT | 必须立即处理 | 严重硬件故障 |
| 2 | KERN_CRIT | 临界条件 | 驱动加载失败 |
| 3 | KERN_ERR | 错误 | I/O错误、内存分配失败 |
| 4 | KERN_WARNING | 警告 | 资源不足、配置异常 |
| 5 | KERN_NOTICE | 正常但重要 | 驱动初始化完成 |
| 6 | KERN_INFO | 信息 | 版本号、硬件信息 |
| 7 | KERN_DEBUG | 调试信息 | 开发阶段使用 |
我建议你在调试驱动时,把printk的级别设为KERN_ERR或KERN_WARNING。别一上来就KERN_DEBUG,否则生产环境里日志刷爆了,用户会骂娘的。
/proc/sys/kernel/printk 控制。默认是 4 4 1 7,分别代表:控制台日志级别、默认消息日志级别、最小控制台日志级别、默认控制台日志级别。改这个文件要小心,我曾经改完后控制台啥日志都不出了,排查了半天才发现是自己手滑。
3.3 驱动调试信息:printk的艺术
驱动开发最常用的调试手段就是printk。别看它简单,用好了能解决大问题。
基本用法:
#include <linux/kernel.h>
#include <linux/printk.h>
printk(KERN_ERR "my_driver: 初始化失败,错误码=%d\n", ret);
printk(KERN_INFO "my_driver: 设备注册成功,主设备号=%d\n", major);
我个人习惯在驱动里加一个调试开关:
#define MY_DRV_DEBUG
#ifdef MY_DRV_DEBUG
#define my_dbg(fmt, ...) \
printk(KERN_DEBUG "my_drv: " fmt, ##__VA_ARGS__)
#else
#define my_dbg(fmt, ...) /* 空 */
#endif
这样调试时打开宏,发布时关掉。干净利落。
我曾经在调试一个USB摄像头驱动时,发现图像数据总是错位。折腾了两天,最后在printk里打印了每个DMA缓冲区的地址和长度,才发现是某个中断处理函数里把buffer指针搞乱了。说白了,printk就是驱动调试的“听诊器”。
3.4 死机分析:从dmesg里找线索
系统死机(kernel panic)是Android开发者的噩梦。但别慌,dmesg里通常有完整的“案发现场”。
典型的死机日志长这样:
[ 123.456789] Kernel panic - not syncing: Fatal exception
[ 123.456790] CPU: 2 PID: 1234 Comm: kworker/u16:5 Tainted: G W
[ 123.456791] Hardware name: Qualcomm Technologies, Inc. MSM8998
[ 123.456792] Call trace:
[ 123.456793] [<ffffff800808c000>] dump_backtrace+0x0/0x1a0
[ 123.456794] [<ffffff800808c1a0>] show_stack+0x20/0x30
[ 123.456795] [<ffffff80082a0000>] dump_stack+0x90/0xb0
[ 123.456796] [<ffffff80080a0000>] panic+0x100/0x280
[ 123.456797] [<ffffff80080b0000>] die+0x50/0x60
[ 123.456798] [<ffffff80080c0000>] do_page_fault+0x200/0x300
[ 123.456799] [<ffffff80080d0000>] do_mem_abort+0x40/0x80
看死机日志,我一般三步走:
- 找panic原因:看第一行
Kernel panic - not syncing后面的描述。常见的有Fatal exception、Out of memory、Unable to handle kernel NULL pointer dereference。 - 看调用栈:从
Call trace开始,从下往上读。最下面的是触发点,最上面的是最终调用的函数。比如上面这个例子,do_mem_abort说明是内存访问异常。 - 查寄存器:如果日志里有
PC(程序计数器)和LR(链接寄存器)的值,用addr2line工具翻译成源码行号。
3.5 知识体系图
下面这张图总结了内核日志分析的核心脉络:
3.6 实战:一次死机排查记录
我记得有一次,某款平板在播放视频时频繁死机。应用层日志啥都没有,但dmesg里留下了关键线索:
[ 456.789012] Unable to handle kernel NULL pointer dereference at virtual address 00000010
[ 456.789013] pgd = ffffffc0a1b00000
[ 456.789014] [00000010] *pgd=0000000000000000
[ 456.789015] Internal error: Oops: 96000004 [#1] PREEMPT SMP
[ 456.789016] CPU: 3 PID: 5678 Comm: mediaserver Tainted: G W
[ 456.789017] PC is at msm_vidc_decoder_release+0x24/0x80 [msm_vidc]
[ 456.789018] LR is at msm_vidc_decoder_release+0x20/0x80 [msm_vidc]
看到NULL pointer dereference和msm_vidc_decoder_release,我立刻意识到是视频解码器在释放资源时访问了空指针。查代码发现,某个条件分支下没有初始化一个结构体指针,但释放函数却直接调用了它。
修复方法很简单:在释放前加个if (ptr)判断。但如果没有dmesg,这种问题可能要排查好几天。
/proc/last_kmsg(部分内核支持)或pstore目录下的文件。这些是上次死机时保存的“遗言”。
好了,内核日志分析就聊到这儿。说白了,dmesg就是内核的“朋友圈”,驱动干了什么、系统出了什么状况,全在上面。学会看它,你就能从系统层面理解很多奇怪的问题。