我至今记得在客户现场盯着一台工控机串口终端的那种无力感主板LED正常闪烁风扇在转但终端里一片寂静。折腾了大半天最后发现机器其实早就活了只是我和它之间缺了一条“看得见的通道”。从那以后我就养成一个习惯拿到任何板子先把Linux内核启动日志的输出链路在脑子里过一遍printk把消息写进内核缓冲区console驱动决定它能不能被看到时间戳告诉你它是哪一刻写的最后kmsg设备负责把它交到用户空间。这个链路听起来简单可真拆开看每一步都藏着坑。“Linux内核启动过程中的日志输出阶段分析”说白了就是回答三个问题日志在哪一刻产生的、存到了哪里、通过什么渠道能被我看到。这篇文章不打算按启动流程一行行罗列代码而是从“日志的生命周期”这个角度把整个启动过程切成几个阶段讲清楚每个阶段里日志的可见性、可追溯性和常见误会。适合正在啃内核源码的同学、做嵌入式BSP的工程师以及被“开机黑屏无从下手”折磨过的运维同事。1. 把启动日志的“生命周期”摊开看从printk到终端要过几道关一段启动日志的真实旅程大致是这样的内核里某个函数调用printkprintk先把消息格式化然后写入一个叫__log_buf的全局缓冲区。这个缓冲区是环形结构写满了就会覆盖最旧的内容。与此同时printk还会顺着一个全局链表console_drivers往下走把消息分发给每一个已注册的控制台驱动由它们负责把字符写到串口、VGA屏幕或者网络控制台上。这里有个容易被忽略的关键点写入缓冲区是必定成功的但输出到控制台则不一定。控制台是否存在、是否完成注册、日志级别是否达标、驱动是否在沉睡都会影响一段日志最终能不能出现在你眼前。从时间线来看Linux内核日志的输出可以分成四个阶段。我在下面整理了一张总览表启动阶段日志产生方式默认可见性典型内容汇编/解压阶段直接操作硬件putstr/串口大部分不可见“Decompressing Linux...”start_kernel早期earlycon / earlyprintk取决于是否配置earlycon参数CPU、内存、时钟初始化console_init之后标准console驱动默认可见受loglevel控制驱动probe、initcall执行用户空间接管通过/dev/kmsg交给systemdjournalctl -k 可见内核与systemd日志看一眼这张表就能发现日志的“存在”和“可见”是两码事。只要printk执行了记录就进了环形缓冲区除非它被后续的日志挤掉。但“可见”则必须满足一个条件存在一个注册成功且使能的控制台驱动。很多排障场景里大家一看串口没有输出就断定内核没跑起来这是最典型的误判后面我会专门用一个实战案例说明这一点。还有一点需要提前铺垫新版内核5.10之后把printk的输出机制改成了可延迟模式加入了更复杂的线程化处理早期也有printk_safe这样的机制用来避免在NMI或中断上下文里锁死。但不管内部怎么变我们做阶段分析时手里握着的核心模型始终是那条链printk - __log_buf - console_drivers。理解这条链上的每个环节比追着某个内核版本的具体实现跑更有价值因为框架是稳定的变的只是细节。2. console还没出生时早期日志到底藏在哪、怎么把它逼出来2.1 汇编阶段是最彻底的“黑箱”从硬件复位到内核C代码入口这段路几乎没有任何标准日志通道。x86上从reset vector到startup_32ARM64上从_head到stext这段代码不仅没有C环境连内核虚拟地址映射都还没建立。如果一个板子死在这个阶段你看到的现象就是“完全没有输出”。但这不代表代码里没有任何调试输出。x86在解压内核时有个putstr辅助函数会往串口或VGA直接写字符“Decompressing Linux... done, booting the kernel.”就是这时候打出来的。如果解压失败可能只有一句“Decompression failed”——就这么点信息够你排查一整天。我自己的习惯是在这个阶段不要指望任何软件手段。要么用JTAG调试器抓PC指针要么在板级支持包里加汇编级的点灯代码GPIO翻转。很多老工程师说“启动早期、看灯判断进度”原理就在这里——汇编阶段根本没有日志系统硬件状态就是唯一的日志。2.2 earlycon和earlyprintk抢在console注册前开一扇窗进入C代码到console_init()被调用之间依然有一段不短的路要走CPU特性探测、内存布局初始化、页表建立这里出问题的概率不小。解决办法就是提前开一扇“临时窗户”——earlycon。earlycon和x86传统的earlyprintk并不完全是一回事。earlyprintk偏x86的历史遗留直接操作VGA显存或指定串口而earlycon是一套更通用、和设备驱动解耦的机制。它不依赖完整的串口驱动直接读UART寄存器用轮询方式把字符发出去不需要中断也不需要等待设备probe完成。配置方式也很直接在bootargs里加参数earlyconuart8250,mmio32,0xfe010000这个例子里uart8250是串口类型mmio32是访问方式最后的地址就是UART控制器的基地址。如果你用的是ARM64平台还可以依赖设备树里chosen节点的stdout-path属性很多Bootloader会自动填充它。一个关键认知是earlycon和console是两条独立的通道earlycon只是临时替代品并不会替代后续的标准console。开了earlycon后你在串口上看到的早期日志和后来console_init之后由标准驱动打出来的日志可能会“重复”一遍——因为后注册的console会把环形缓冲区里的历史记录重新刷出来。这不是bug是机制。2.3 别把earlycon当生产配置留着很多工程师调通了earlycon就一直留在bootargs里这其实有隐患。earlycon的轮询输出会占用CPU而且绕过了驱动的电源管理和时钟管理在低功耗设备上可能导致串口一直处于活跃状态。我的建议是把earlycon当作排障专用钥匙问题定位完毕就删掉需要长期保留调试能力的话再评估具体的板级策略。如果你用的是x86平台还有earlyprintkdbgp这类USB调试端口方案可以选效果类似但需要额外的硬件支持。对于绝大多数场景earlycon加串口就是性价比最高的选择。3. 环形缓冲区与console注册的“迟到补课”启动日志为什么看起来会丢3.1 __log_buf到底是什么尺寸的箱子__log_buf是一个静态分配的全局数组大小由内核编译选项CONFIG_LOG_BUF_SHIFT决定。这个名字的SHIFT表示移位位数实际大小就是1 CONFIG_LOG_BUF_SHIFT字节。默认配置下这个值常见的是17或18对应128KB或256KB大型服务器发行版内核可能会配到20甚至更高。查看当前内核的实际配置很简单zcat /proc/config.gz | grep CONFIG_LOG_BUF_SHIFT如果你想临时扩大缓冲不用重新编译内核启动参数里加一行即可log_buf_len4M注意这个参数有个限制它只能把缓冲区调大不能小于内核编译时的静态默认值。原因也好理解__log_buf是静态数组启动参数解析只能决定使用多大的一段空间超出静态空间的部分需要动态分配往里缩的逻辑没人替你处理。3.2 console注册时的“迟到补课”机制console_init()在start_kernel里被调用之后各个console驱动会陆续通过register_console()挂上链表。这里有一个对排障特别重要的机制每个新console注册时会把环形缓冲区里保存的历史日志从头到尾重新输出一遍。这解释了为什么后注册的串口console能看到非常早期的日志那些日志在console出生前就已经存在缓冲里了新console注册时一次性补刷出来就像学生迟到后补抄笔记一样。所以哪怕只有VT终端、没有任何串口console只要后续挂上一个ttyS0的console你也依然能看到从start_kernel早期以来的全部日志——前提是它们还没有被环形缓冲区挤掉。实操上还有个衍生技巧如果设备有多个串口可以让splash画面在VGA上显示同时把consolettyS0串口作为主console排障时看到的信息量会大得多。3.3 日志被覆盖的真实场景不是没产生是被冲掉了环形缓冲区的覆盖问题在两种场景里最常见。第一种是oops或panic刷屏。系统已经挂了一次但某个CPU可能还在疯狂打印错误信息几百万行的刷屏直接把你最需要的panic日志冲出了缓冲区。等你想回头翻看最早的崩溃现场发现dmesg里已经是扫尾时的状态了。第二种是启动过程过长且printk量大。比如initramfs阶段某个脚本疯狂打印、或者驱动循环报错都会加速覆盖进程。解决思路也不复杂启动参数加log_buf_len4M甚至更大给环形缓冲区扩容如果已经panic加panic10让系统延迟重启留出人工抓取串口日志的时间panic_print参数可以让panic发生时把寄存器、栈、内存摘要等信息一并打入缓冲区养成习惯开完机立刻dmesg /var/log/boot-kernel.log归档别等出问题才想起翻缓冲。一句话总结这节的教训dmesg里缺失的早期日志大概率不是“没打出来”而是“存的那截箱子被冲掉了”。4. loglevel和时间戳控制台看到的不是全貌时间轴也不能全信4.1 console_loglevel的过滤规则内核消息自带级别从0emergency到7debug。内核向控制台输出时会拿消息级别和console_loglevel做比较只有级别数值小于等于console_loglevel的才会真正写到控制台。/proc/sys/kernel/printk这个文件里存着四个数字第一个就是当前console_loglevelcat /proc/sys/kernel/printk # 通常输出4 4 1 7很多发行版为了启动画面干净会通过quiet参数把console_loglevel压到4意味着只有warning级别以上的消息能上控制台。于是你会看到一种常见的“怪相”串口干干净净、仿佛一切正常但dmesg里其实有一大堆驱动报错。quiet并没有阻止日志产生它只是挡住了向控制台的输出通路。如果你不想改内核参数运行中也可以直接调echo 8 /proc/sys/kernel/printk把console_loglevel提高到8所有级别的消息都会打到控制台。还有一个极端参数叫ignore_loglevel加在内核命令行里等于把这个过滤规则彻底废掉适合排查“怀疑有日志被过滤掉”的场景但不建议长期开启否则日志量会让启动时间明显变长。4.2 时间戳为什么启动日志的时间线经常“不长脑子”内核日志默认带时间戳CONFIG_PRINTK_TIME开启也可以用printk.time参数控制显示为[ 12.345678]这样的格式。这个时间戳是自系统启动以来的单调时间uptime不是墙上时钟。听上去很直观但这里埋伏着好几个坑。第一个坑是早期时间源精度差。在clocksource选定之前内核可能只能靠jiffies或者临时计时器时间戳的精度只能到毫秒甚至10毫秒级。你看到的启动前几十条日志时间戳可能全部都是0.000000或者逐条递增得很粗糙这不代表内核卡住了只代表那个阶段没有高精度时钟可用。第二个坑是时钟源切换时的跳变。内核启动早期会先在jiffies这类基础时钟上跑等HPET或者TSC这类高精度定时器初始化完成后切换到新时钟源。切换过程可能造成时间戳的轻微“倒退”或跳跃。如果你发现某个时间点附近相邻两条日志的时间戳不对先别慌着报bug确认一下是不是正好卡在clocksource切换点附近。第三个坑来自SMP。多个CPU同时执行printk时日志的写入顺序由锁竞争决定时间戳靠前的日志可能打印在后面反过来也一样。你在串口上看到的顺序严格来说只是写入缓冲区的顺序不是每个事件实际发生的时间顺序。单看时间戳去判断两个事件谁先谁后在启动早期尤其不可靠。4.3 用时间戳做启动耗时分析的正确姿势想用时间戳做启动性能分析推荐配合initcall_debug参数。它会让内核在执行每个initcall时打印出函数名、返回值、耗时格式大致是initcall xxx_init0x0/0x18 returned 0 after 1234 usecs之后你再配合dmesg按时间戳排序就能看出哪段initcall消耗离谱。用户空间的耗时分析则可以交给systemd-analyze它把内核和systemd两个阶段的耗时都拉出来对比。我一直强调内核日志配合这两个工具基本能覆盖从加电到用户空间就绪的全链路计时问题。5. 接手内核日志的“接力棒”/dev/kmsg、dmesg与systemd-journald5.1 内核把日志暴露给用户空间的三种方式内核日志留在环形缓冲区里用户空间进程要读出来有三个常规入口/dev/kmsg现代推荐接口可读可写支持多个读取者是一个持续输出的字符设备。打开后读取会拿到从当前指针开始的日志后续新日志会持续推送很像tail -f的行为。更关键的是它支持写任何有权限的进程都能往里塞一条“伪内核日志”。/proc/kmsg老接口只能有一个读取者而且读取是阻塞式的需要特权。现在很多场景已经被/dev/kmsg取代。dmesg命令本身老版本通过syslog(2)系统调用读取新版本util-linux默认走/dev/kmsg但最终读到的还是同一个环形缓冲区。实际操作中我强烈建议记住这个写日志的技巧echo custom-marker from script /dev/kmsg多机联调、或者排查脚本时序问题时往内核日志里塞自定义标记非常有用。内核日志和脚本日志通过时间戳对齐能快速定位“脚本哪一步跑慢了、内核在那个时间点干了什么”。5.2 journald接棒之后的常见坑systemd-journald在系统启动顺序里排得并不早但它在启动完成后会把内核缓冲区的日志全部“补拉”到持久化journal里。这正是journalctl -k -b能看到本次启动全部内核日志的原因前提同样是——缓冲区里的日志没被覆盖。实际工作中我踩过一个很典型的坑某设备boot过程因为initramfs脚本故障产生海量打印等系统真正起来后journald去拉内核日志时最早的几百条已经被冲掉了。排障时明明看journalctl -k缺了开头一段还以为是内核bug最后才发现是log_buf_len不够导致的覆盖。另外用户空间本身出问题时比如systemd服务启动崩溃千万别只顾着翻journalctl的用户态日志。先把journalctl -k -b的最后几十行拉出来看确认内核和驱动层面是否健康再往下追应用层。很多服务反复崩溃、重启、再崩溃根因其实是某个驱动在probe阶段没有正确上报资源只是它被用户空间的失败表象掩盖了。5.3 内核日志和用户空间日志的时间线怎么对齐内核日志的时间戳是boottime自启动以来的秒数journald日志有实时时间戳。对齐的方法很简单用journalctl --since或者dmesg -T把时间戳转成可读时间然后看用户空间第一个进程被拉起的时间点。内核日志里“Freeing unused kernel memory”和“Run /init as init process”这两行基本就是内核向用户空间交接的边界线。如果日志停在这两行之前问题大概率在内核、驱动或硬件如果这两行之后还有输出但系统仍然没有起来方向就要转向initramfs、systemd和用户态服务。这条分界线是我做启动排障时划的第一条辅助线。6. 实战复盘一台串口全黑设备的启动日志阶段排查6.1 现场现象与第一判断一块ARM64平台上电后LED停在一个固定状态串口终端完全没输出。第一步不是马上下内核的结论而是分级排查Bootloader比如U-Boot是否有输出如果U-Boot也没有任何打印问题很可能在DDR初始化、时钟配置或者串口硬件层面的配置上这时候应该先用示波器量UART TX脚再去查硬件。如果U-Boot有输出、进内核之后才黑屏那基本可以锁定是内核早期阶段卡死。我这次遇到的场景就是后者U-Boot日志正常显示内存大小、启动参数一行“Starting kernel...”之后串口再也没有任何动静。这是一个非常典型的“console出生前死亡”的现场。6.2 第二板斧把排障参数全部拉满面对这种早期卡死常规的console根本没有机会注册。我的做法是把能开的调试手段一次性开齐避免来回重启浪费时间。组合拳如下earlyconuart8250,mmio32,0xfe010000 consolettyS0,115200n8 ignore_loglevel log_buf_len4M panic10逐个说说为什么这么组合earlycon负责在console机制建立前抢开串口通道console保留标准串口console等console_init后接管输出ignore_loglevel避免消息被级别过滤掉log_buf_len4M扩大环形缓冲区防止日志被覆盖panic10预留10秒延迟给串口足够时间把最后的panic信息吐完。加上这些参数后重新上电串口终于有了动静日志在“Uncompressing Kernel...”之后又输出了一段早期内存初始化信息最后卡在“Memory: ... available”之后的某个节点。从阶段表来判断问题定位在setup_arch内存初始化到页表建立之间的区域紧接着去核对设备树里内存节点的大小和起始地址果然发现内存描述与硬件实际布局不一致导致后续映射出错。6.3 读日志从最后一行开始往回推启动排障有个很实用的原则从最后一行日志往后看。最后一行打到哪里就说明执行流走到了哪里再结合那一行所在模块的代码就能定位卡死点。我整理了常见的几种“最后一行”以及对应的排查方向最后日志的特征大致所处阶段优先排查方向“Kernel Offset: disabled”解压阶段解压失败、内存布局“Memory: ... available”后无输出setup_arch内存初始化、节点映射“Calibrating delay loop...”早期时间初始化timer、clocksource“Freeing unused kernel memory”用户空间前夕init进程、initramfs“Run /init as init process”用户空间systemd、驱动probe这张表不能当定理用但作为起始线索非常有效。我每次拿到一份启动日志都会先定位“最后一行”然后再决定往哪个子系统和驱动深挖。6.4 现场保护与复盘建议最怕的一种情况是设备终于有输出了但就是你眨个眼的功夫全部刷屏过去回头想翻已经来不及。所以现场保护要做在前面。串口终端软件一定要带完整日志文件记录HumbleCRT、minicom、screen都行关键是“从按下电源键的那一刻开始记录”波特率尽量提到115200甚至更高否则几万行panic日志往外吐的时间久到令人绝望如果条件允许把串口日志直接接到一台跑ss或者script的Linux机器上做成自动归档硬件上如果支持再用一个GPIO或LED接在关键初始化点配合日志一起看能判断“日志没打出来是真的没执行到还是通道又断了”。那次排障最后花了半天时间定位真正改动只有设备树里的一行内存参数。但那半天的价值在于我把启动过程从头到尾“看”了一遍再遇到类似的黑屏问题心里就有了牵引线。日志阶段分析这件事与其说是一项技术不如说是一种排查思路的底色。内核启动的每一个阶段能看见什么、能留住什么、靠什么通道传出来都有明确规则。把这些规则刻在脑子里再碰到“看起来完全没有输出”的设备你就知道并不是没有日志而是日志在等你打开正确的窗口。这个体会是我在无数个焦头烂额的排障夜里换来的。