ARTICLE DETAIL

资讯详情

深耕郑州网站建设与运营推广的一线实战洞察。

Linux内核启动日志全解:printk到dmesg的故障排查指南

Linux内核启动日志全解:printk到dmesg的故障排查指南 搞 Linux 内核启动问题最怕的其实不是看不懂代码而是连“系统到底走到哪一步才挂的”都不知道。启动过程中的日志输出是我们唯一能盯着内核从零到一跑完整个初始化流程的窗口。这里说的启动日志既包括你接上串口线看到的那一排排以[ 0.000000]开头的内容也包括进了系统之后用dmesg翻出来的内核环形缓冲区记录。如果你正被开机黑屏、启动到一半卡死、某个驱动加载慢或者内核 panic 折腾得焦头烂额这篇内容就是为这个场景准备的。内核初学者可以用它建立启动过程的整体时间线运维和嵌入式工程师可以用它定位真实的启动故障普通 Linux 用户也能借此理解自己的系统开机时都发生了什么。1. 启动日志到底在记录什么先给整个启动过程画条时间线1.1 一次 Linux 启动日志输出要经历哪几个阶段很多人以为开机后屏幕上滚动的字符就是“Linux 启动日志”其实那只是内核通过某个 console 设备输出的一个子集。完整的日志链路远长于你能看到的画面。按时间顺序一次启动的日志输出大致经历四个阶段。第一阶段是固件阶段。BIOS 或 UEFI 在自检时也会打印自己的信息这些内容和内核没有直接关系但它们决定了 CPU、内存、串口、显卡等设备最早是什么状态。你在启动时按 Del 或 F2 看到的 POST 界面就属于这个阶段。如果固件里启用了串口重定向那么 POST 输出也会被重定向到串口这对接下来的内核日志抓取非常重要。第二阶段是引导加载程序阶段。GRUB 或 U-Boot 会加载内核镜像此时屏幕上出现的菜单和Loading Linux...字样来自引导程序自身。真正影响后续日志行为的是引导程序向内核传递的内核参数比如consolettyS0,115200、loglevel8。我们经常要解决“内核日志没输出”的问题追到根上往往就是这一段参数没配对。第三阶段是内核早期阶段。从引导程序跳转到内核入口到start_kernel()完成基本初始化这期间 printk 能工作但很多子系统还没准备好。串口驱动和内存管理往往也未就绪。这一段的日志能不能抓到取决于有没有提前打开earlycon或earlyprintk。很多系统在“黑屏挂死”时日志其实已经产生了只是没有 console 能打出来结果所有人都抓瞎。第四阶段是内核实初始化与用户态接管。start_kernel()之后内存管理、调度器、中断、定时器、initcall 机制依次启动所有驱动的初始化回调都在这个阶段执行日志量非常密集。最后内核启动第一个用户态进程通常是 systemd。从这一秒开始屏幕输出逐渐被用户态服务日志接管但内核自己的 printk 依然会继续往 console 和 ring buffer 里写直到关机。这四个阶段里的日志机制完全不同。固件和引导程序的输出我们控制不了多少但内核早期和初始化阶段的输出几乎完全可以通过内核参数和内核配置来掌控。所以后面讲的实操都是围绕后两个阶段展开的。1.2 为什么早期日志最能看出问题却也最难拿到启动早期是整个系统最脆弱的一段时间。内存分配器还没工作锁机制才刚初始化CPU 可能还停在实模式或某个不太稳定的状态。内核在这个阶段打日志不能依赖常规的 console 驱动因为驱动本身可能还没 probe。于是内核引入了对最基础输出设备的支持串口8250、PL011 等、VGA 文本模式、甚至一个极简的 framebuffer。我在实际排查中遇到过一个典型场景某块 ARM 板卡在 “Starting kernel ...” 之后完全没有任何输出看起来像死机。用earlycon打开串口输出后日志显示是解压内核后随即访问了一个未映射的物理地址机器在__bug_on处直接停止。没有早期输出这个问题只能靠猜有了早期输出一眼就能定位到具体位置。可以说早期日志是内核启动排障中价值密度最高的一部分。但早期日志有个天然的矛盾console 设备没有初始化完输出通道很少而问题恰恰发生在这个窗口。所以我们要么在引导程序阶段就提前把一个可靠的 console 设备告诉内核也就是earlycon参数要么干脆让内核把早期日志先全部缓存到内存等到 console 可用后再一次性回放。理解了这一点再看后面的earlyprintk和log_buf_len就不会糊了。2. 内核日志输出机制拆解printk、日志级别与内核缓冲2.1 printk 到底怎么工作每条日志都是怎么送到你面前的整个启动日志系统的核心只有一个函数printk()。它和用户在 C 语言里熟悉的printf长得很像但语义完全不同。printf只负责把字符串写到用户态的文件描述符而printk要把格式化好的内容同时做两件事存进内核的环形缓冲区以及输出到所有已经注册的 console 设备。先看环形缓冲区。从 5.10 开始内核用了一套新的 printk ringbuffer 实现支持无锁访问和更灵活的内存分配。历史版本则是固定大小的__log_buf。这块缓冲区本质上是一段内存内核每打一条日志就按[时间戳] 级别 内容的格式往里写。dmesg命令读取的就是这个缓冲区而不是某个日志文件。所以dmesg能看到的内容本质上就是内核自己保存的启动记录无论它是否在屏幕上出现过。再看 console 输出。printk 在写完环形缓冲区后会遍历当前注册的 console 驱动列表把日志逐个送往每个 console。启动早期这个列表可能只有 earlycon 提供的极简串口驱动等到 serial、tty、vt 这些子系统初始化完成后真正的 console 驱动才注册进来。注册时内核会做一次“回放”把缓冲区里已经存在但没被该 console 输出过的日志一次性补齐到屏幕上。这里有一个关键细节console 驱动在注册的时候会从哪条日志开始回放内核记录了一个next_seq指针跟踪每个 console 已经消费到的位置。如果某个 console 一直没注册它开始回放的位置就非常早你会看到屏幕突然刷出一大段内核日志然后才回到正常输出。这种“日志突然补发”的行为在串口调试时尤其常见。2.2 日志级别不是摆设理解 KERN_DEBUG 到 KERN_EMERGprintk 打出的每条日志都带一个级别对应内核源码里最常见的pr_info、pr_warn、pr_err、pr_debug等宏。级别数字越小越紧急KERN_EMERG是 0KERN_ALERT是 1KERN_CRIT是 2KERN_ERR是 3KERN_WARNING是 4KERN_NOTICE是 5KERN_INFO是 6KERN_DEBUG是 7。这些级别决定了日志是否能出现在 console 上。内核有一个控制台日志级别也就是你经常在include/linux/printk.h里看到的console_loglevel。只有级别数值小于等于console_loglevel的日志才会被真正打印到 console。比如默认console_loglevel是 4那么pr_info级别 6就不会显示在屏幕上但依然会写进环形缓冲区这就是为什么有些启动信息你看不到却能用dmesg看到。这里很容易踩坑。内核参数quiet会把console_loglevel降到 4 以下只显示比较严重的错误适合 UEFI 启动时想尽量干净的场景。但如果你在调试驱动的pr_debug只加quiet是不会看到任何 debug 输出的因为pr_debug在未开CONFIG_DYNAMIC_DEBUG时可能直接被编译为空就算开了日志级别也根本不满足输出条件。正确做法是使用debug或loglevel8并配合动态调试的控制文件。总之理解级别机制是看懂启动日志的第一步不然你会在“为什么少了一堆日志”的问题上浪费很久。2.3 用/proc/sys/kernel/printk控制输出门以及参数优先级进系统之后我们可以通过cat /proc/sys/kernel/printk看到四个数字。它们依次代表当前 console 的日志级别、默认消息日志级别、最小 console 日志级别、默认控制台日志级别。在绝大多数发行版上你会看到4 4 1 7这样的组合。第一个 4 表示 info 以下的信息一般不上屏第二个 4 表示没有显式指定级别的 printk 按 KERN_WARNING 处理实际是 4所以叫默认消息级别第三个 1 表示 console 日志级别最小只能被降到 1第四个 7 是default_console_loglevel在ignore_loglevel这类参数存在时会被行覆盖。我排查启动问题时经常在引导参数里加ignore_loglevel。这个参数会强制让所有日志不考虑 console 级别直接输出。它像个“日志开关的开关”适合早期想看到所有内容的时候。生产环境不建议开着因为日志量太大串口会成为瓶颈反过来拖慢启动。如果久经沙场你会发现loglevel8和ignore_loglevel有细微差别。loglevel是设置一个很高的阈值让级别小于等于 8 的日志能上 console但某些路径里的 printk 仍然会受其他机制影响ignore_loglevel则直接绕过级别判断。在排障早期我更倾向用ignore_loglevel一次把所有内容都逼出来然后再逐步收紧。3. 完整复现一次启动过程日志抓取3.1 准备一个可重复的内核实验环境纸上谈兵没有意义真要分析启动日志最好有一个能随意重启、随便加内核参数的实验环境。生产机器不敢折腾虚拟机是性价比最高的选择。我用的是 QEMU 最小 initramfs 的组合。准备bzImage和一个能用的 initramfs前者来自发行版内核包或自己编译的内核后者可以用 Buildroot 生成或者干脆用现成发行版的 initramfs。如果你不想编译内核也可以拿发行版自带的内核直接做实验。关键在于启动参数要自定义QEMU 的-append可以满足。下面是一个最常用的起机命令qemu-system-x86_64 \ -m 2G \ -kernel /boot/vmlinuz-$(uname -r) \ -initrd /boot/initramfs-$(uname -r).img \ -append consolettyS0 earlyconuart8250,io,0x3f8 loglevel8 ignore_loglevel \ -nographicconsolettyS0是告诉内核把常用 console 放到串口earlyconuart8250,io,0x3f8是让内核在初始化串口驱动之前直接用最底层的 8250 驱动往 0x3f8 的 I/O 端口写日志。这样从第一行内核输出开始就能抓到。配合-nographic所有日志会直接打到当前终端观察起来很直观。3.2 配置 earlycon 与 loglevel让每一行日志都留在串口earlycon是早期日志输出的关键。格式一般为earlycon设备名,地址或earlycon设备名,io,地址具体取决于平台。x86 上最常见的 8250 串口可以写成earlyconuart8250,io,0x3f8ARM 板子则可能写成earlyconamba,pl011,0xfe201000。只要地址正确内核从setup_arch()之前就能打日志。设置之后启动过程中你会看到类似这样的一行行输出[ 0.000000] Linux version 6.6.10 (userhost) (gcc ...) #1 SMP ... [ 0.000000] Command line: consolettyS0 earlyconuart8250,io,0x3f8 loglevel8 ignore_loglevel [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable第一行的时间戳是从 boot 开始计时的相对秒数0.000000说明这是最早期。随后你会看到内存映射、CPU 拓扑、时间源、中断控制器等一系列初始化信息。因为ignore_loglevel打开pr_debug暂时还不会全部输出它还要看编译开关但正常情况下你已经能看到比默认多出好几倍的内容。这里要提醒一句用完ignore_loglevel之后记得关掉否则每次启动屏幕信息量太大反而淹没什么重要错误。尤其是在控制台输出速度很慢的嵌入式板子上大量日志打印会让启动时间从几秒钟拖到几分钟。3.3 对照 dmesg 的时间戳还原启动顺序启动结束后登录系统执行dmesg你可以拿到和 console 输出相同的日志但不一定完全一样因为 console 可能丢掉一些行而 ring buffer 里是完整的。用dmesg -T可以把单调时间戳转换成墙上时钟时间这对和系统日志、应用程序日志关联很有用。不过要注意启动早期的时间戳并不完全是精确的单调时间。在时钟源、定时器初始化之前printk 时间戳可能用的是节拍计数jiffies或者极简的本地时钟数值不一定连续。你看[ 0.000000]后面突然变成[ 0.004000]并不是内核停顿了 4 毫秒而是它换了一个更精确的时钟源。理解这一点就不会被时间戳的跳变误导。分析启动顺序时我一般会按日志内容分类。先看内存和 CPU 初始化再看pinctrl、clk等基础一级驱动的 probe然后跟踪文件系统相关的initcall最后看 systemd 启动用户态服务的阶段。内核源码里用initcall_debug参数会额外打印每个 initcall 函数名和耗时这比纯看时间戳更直接。加上它之后日志里会出现下面的片段[ 0.980123] initcall irqsoff_init0x0/0x10 returned 0 after 0 usecs [ 1.031543] initcall populate_rootfs0x0/0x20 returned 0 after 0 usecs看到某个initcall后面的 usecs 值异常大基本就能锁定是哪个驱动初始化拖慢了启动。3.4 用日志定位一次典型的启动变慢问题我拿这个环境做过一次真实演练启动过程中有一段明显的十几秒静默期串口没有任何输出屏幕也不滚动。系统最终能启动但体感非常慢。先看dmesg最后一条输出是[ 3.204560] r8169 0000:00:03.0 eth0: link is up然后直接跳到[ 16.892345] systemd[1]: Starting Journal Service...中间缺了十几秒。这种“gap”通常发生在 console 设备暂时停止工作或者某个服务在无输出等待超时。换一个思路用initcall_debug重启之后发现缺失时间集中在async_run_initcall的某个网络驱动固件加载环节实际上是网卡在等待固件校验。不是死锁只是那个环节默认有超时等待。这种排查过程恰恰说明启动日志分析的核心不是背命令而是会看“时间戳跳跃”和“日志断层”。你可以把每个阶段预期的日志主题整理成清单内存初始化应该在哪里、中断控制器应该在哪里、根文件系统挂载应该在哪里。一旦日志中断在不在清单里的位置问题就一目了然。4. 启动日志排查的常见坑与技巧4.1 日志被环形缓冲区冲掉怎么办默认的 printk 环形缓冲区其实不大很多发行版配置在 128KB 到 1MB 之间。启动时驱动日志量很大早期日志会被后续日志覆盖最后dmesg只保留系统运行起来之后的内容。我刚学内核时就遇到过用dmesg却看不见早期日志的烦恼。解决办法有两个方向。第一是加大缓冲区在启动参数里加log_buf_len4M或者更大的值。注意这个参数必须在早期生效它会在内存配置阶段重新分配日志缓冲区。第二是使用持久化存储把启动日志在写往 console 的同时记录到 pstore / ramoops 区域。对于发生过 panic 的系统pstore 里保留的最后一段日志往往是破案的关键。这个思路在生产服务器上特别有用。4.2 控制台没有输出或乱码启动时屏幕黑屏是最常见的问题。原因往往不是内核没输出而是输出去了别的地方。比如服务器主板固件默认把 console 重定向到了串口但系统里没配置串口参数日志自然不会出现在 VGA。还有一种情况是 GPU 驱动初始化后接管了显示设备各 framebuffer console 因为显示时序不同而短暂黑屏。处理思路是先确定目标 console 设备。物理服务器使用串口调试时必须保证固件的串口重定向设置、引导程序的console参数、内核驱动的串口配置三者一致。波特率不匹配就会出现满屏乱码。出现乱码时先检查 bootloader 和内核两侧的 baudrate不要急着怀疑内核代码。ARM 嵌入式板上还要确认串口分频和时钟如果时钟配置错了即使波特率参数一致也会乱码。4.3 printk 在启动早期卡死递归、锁与额外输出很多人不知道printk 内部有一把锁虽然新版内核已经尽力减少持锁时间但在启动早期如果 console 驱动本身的输出路径又调用了 printk就可能形成递归输出甚至因递归打印刷爆栈空间。这种情况在串口 console 驱动刚注册时偶尔会出现。另一个容易忽视的点是中断上下文。在中断处理函数或 NMI 回调里直接调用printk可能导致死锁因为锁状态不可预估。内核为此提供了printk_deferred这样的延迟输出机制。启动早期遇到“卡死在 printk 附近”的问题不要立刻怀疑锁先把earlycon拆掉换consoleNULL试试看是否是 console 输出路径本身的问题。4.4 实战速查表我把自己这些年碰过的问题整理成一张表方便你在遇到类似现场的时候快速对照。现象可能原因首选排查动作启动日志在早期中断earlycon 未配置添加earlyconuart8250,io,0x3f8等参数dmesg 看不到早期日志环形缓冲区被覆盖加大log_buf_len或使用 pstore串口输出乱码波特率不匹配核对固件、bootloader、内核三侧波特率启动时间出现大段空档某设备驱动等待超时启用initcall_debug定位耗时 initcall内核 panic 后没有日志console 未注册或已损坏尽快启用 pstore / crashkernel保留现场屏幕上级别为 info 的日志不显示console_loglevel 过低使用loglevel8或ignore_loglevel有日志但找不到某行内容用户态工具过滤使用dmesg -l err,warn或原始dmesg仔细对照这张表不能替代完整分析但能帮你压缩大量排查时间。遇到启动问题顺序永远是先拿日志再定阶段再查机制最后改配置。5. 剩下的代码和细节几个值得动手验证的点如果你已经把上面的实验环境跑起来我建议顺手做两个小实验。第一个是去掉ignore_loglevel只保留loglevel4对比 console 输出和dmesg结果的差别。你会看到屏幕上安静了很多但dmesg里依然有完整的 info 级别日志。这个现象能让你对“console 级别”和“缓冲区完整度”产生直观印象。第二个是看dmesg中Kernel command line这一行。它记录了实际传给内核的启动参数很多隐蔽问题都源于参数拼错。我遇到过同事把consolettyS0,115200错写成consolettyS0 115200空格代替逗号结果串口完全无输出调试了一下午才反应过来。启动参数格式非常严格差一个字符结果可能完全不一样。根据我的个人经验分析内核启动日志最能锻炼你对系统的整体认识。不要只看自己关注的驱动试着把启动日志完整读一遍从内存、CPU、时钟到驱动、文件系统、init你会慢慢建立起“系统不是一瞬间出现的而是一个组件一个组件搭起来的”这种感觉。工作里遇到任何启动阶段的异常都能沿着这条主线快速定位。希望这篇文章能让你在处理下一个“开机慢、起不来、莫名 panic”时不再是盯着黑屏发呆而是从容地拿日志、分阶段、找根因。
返回列表