📚 课程目录第3章操作系统日志

操作系统日志：系统日志、dmesg、内核日志

接口超时，有时候不是应用层代码的问题。
是底层操作系统在「捣乱」。

我遇到过好几次这样的场景：
接口偶尔超时，抓包看TCP重传，查应用日志又看不出异常。
折腾半天，最后发现是系统日志里一条「Out of memory: killed process」给了解答。
嗯，从那以后，我排查超时问题时，一定会先扫一眼操作系统日志。

这一章，我们就聊聊三种必须掌握的日志：
syslog、dmesg、内核日志。

为什么必须从系统日志入手？

应用层日志只告诉你「超时了」。
系统日志则告诉你「为什么超时」。

比如：

内存不足，杀掉了你的进程（OOM Killer）
磁盘I/O卡住，导致线程挂起
网络驱动报错，丢包率飙升
文件句柄用尽，新连接无法建立

这些情况，应用层日志可能只留下一句「connection timeout」。
但操作系统日志会给出根因。

核心思路：
先看系统日志 -> 定位是否是OS层面的问题 -> 再回查应用层。这个顺序能省下一半的排查时间。

1. 系统日志（syslog）

syslog 是操作系统的「记事本」。
几乎所有内核模块、服务、守护进程都会往这里写日志。

常见路径：

/var/log/messages（大部分Linux发行版）
/var/log/syslog（Ubuntu、Debian）
/var/log/secure（认证相关，SSH、sudo等）

查看技巧：

# 查看最后50条系统日志
tail -50 /var/log/messages

# 实时监控日志输出
tail -f /var/log/messages

# 按关键词过滤
grep -i "timeout\|oom\|error\|killed" /var/log/messages

超时相关关键词：

watchdog timeout
hung_task_timeout
blocked for more than 120 seconds
oom-killer
soft lockup
hard lockup

我的个人习惯：
每次部署新服务后，我都会先挂一个 tail -f /var/log/messages 在另一个终端。运行几天，基本就能摸清这个服务器的「脾气」。哪些时段有定时任务、哪些服务会写大量日志、磁盘I/O峰值在哪——心里有数，排查超时就快了。

2. dmesg（内核环形缓冲区）

dmesg 是内核的「急诊室记录」。
它存放的是内核启动以来的所有环形缓冲区消息。

主要用途：

查看硬件相关错误（网卡、磁盘、内存）
查看设备驱动加载/卸载
查看OOM Killer的击杀记录
查看磁盘I/O错误

常用命令：

# 查看所有dmesg消息
dmesg

# 查看最后20条
dmesg | tail -20

# 实时监控dmesg（相当于 klogd）
dmesg -w

# 按时间过滤（需要配合 journalctl）
journalctl -k -n 50

# 只看OOM相关
dmesg | grep -i oom

一个实战案例：

我记得有一次，接口每隔30分钟就会超时一次。
应用层日志、网络抓包、数据库日志都查了，没找到规律。
最后我用 dmesg -w 跑了半天，发现每到整点，系统就会打印一坨 EDAC PCI 错误，然后紧接着几条 Out of memory。
原来是服务器的硬件内存出现了ECC纠错失败，触发了内存刷写，导致短时间内内存压力暴增。
嗯，那台机器后来换了内存条，问题彻底解决。

注意：

dmesg 环形缓冲区大小是固定的。如果日志太多，旧消息会被覆盖。
生产环境建议开启 rsyslog 或 journald 持久化dmesg内容，不然重启后就没了。
klogd 服务可以自动将 dmesg 写入 /var/log/dmesg，但很多容器化环境默认不开启。

3. 内核日志（Kernel Logging）

内核日志比 syslog 更底层。
它直接由内核的 printk 函数产生，级别从高到低分为8级：

级别	名称	含义
0	KERN_EMERG	紧急，系统不可用
1	KERN_ALERT	警报，需立即处理
2	KERN_CRIT	严重，可能系统崩溃
3	KERN_ERR	错误
4	KERN_WARNING	警告
5	KERN_NOTICE	通知
6	KERN_INFO	信息
7	KERN_DEBUG	调试

与超时相关的内核日志场景：

锁超时： BUG: soft lockup - CPU#X stuck for 22s!
表示某个CPU被一个不可抢占的代码路径卡住了22秒以上。进程死锁或中断风暴，都会导致这种日志。
任务挂起： INFO: task xxx blocked for more than 120 seconds.
进程等待某个资源（如锁、I/O）超过120秒，内核会打印这个警告。接口超时如果伴随这个日志，多半是线程在等死锁。
内存耗尽： oom-killer: gfp_mask=0x...
系统内存不足，内核开始杀进程。如果被杀的正好是业务进程，接口必然超时。

# 查看内核日志（级别3及以上的错误）
dmesg --level=err,crit,alert,emerg

# 查看锁定相关的内核日志
dmesg | grep -E "soft lockup|hung_task|blocked"

一个典型排查链路（我经常用）：

接口超时 → 看应用日志，确认是哪个环节超了
看 syslog，搜 timeout|oom|killed
看 dmesg，搜 lockup|blocked|oom
如果发现 soft lockup，查看对应CPU的进程列表，排查进程调度问题
如果发现 blocked，用 cat /proc/xxxx/stack 看线程堆栈，定位死锁

这个链路，能覆盖80%的系统级超时问题。

三类日志的关系

你以为它们是独立的？
其实，dmesg 是源头，syslog 是管道，内核日志是内容。

dmesg： 内核的环形缓冲区，原始数据。重启就丢。
syslog： 通过 klogd 读取 dmesg，再写入文件。持久化，但可能有延迟。
内核日志： 就是 dmesg 里的内容，只是我们按级别过滤出来的子集。

所以，当你用 tail -f /var/log/messages 时，看到的其实是经过 syslog 处理后的 dmesg 消息。

实操建议：收集阶段的关键一步

最佳实践：

所有生产服务器，开启 rsyslog 并配置远程日志服务器
（万一机器挂了，本地日志也会丢）
定时轮转日志，不要让 /var/log/messages 撑爆磁盘
给日志加时间戳：ulimit -c unlimited 配合 pstack

一个常见的坑：

我曾经排查过一个接口「随机超时」的问题。
翻遍了所有应用日志、网络包、数据库慢查询，毫无头绪。
最后习惯性 dmesg -T 看了一眼，发现有一条 INFO: task mysqld blocked for more than 120 seconds，时间戳正好和接口超时吻合。
原来 MySQL 在做 ALTER TABLE 时锁住了表，应用层的连接池全部卡死。
嗯，早看 dmesg，半小时就能定位到。

小结

系统日志、dmesg、内核日志，三者其实是同一个故事的不同讲述方式。
内核模块产生消息 → dmesg 暂存 → syslog 持久化 → 我们按需查看。
遇到接口超时，别光盯着应用层。
敲一句 dmesg | grep -iE "blocked|lockup|oom"，也许答案就在那里。