📚 课程目录第4章内核启动阶段的埋点方法

4、内核启动阶段的埋点方法：dmesg、trace_printk、Ftrace使用，关键内核阶段耗时分析

内核启动阶段是Android系统开机流程中最神秘、也最容易出问题的一段。说白了，从引导加载程序跳转到内核入口，到init进程启动之前，这短短几秒内系统在做大量初始化工作——CPU、中断、内存管理、驱动加载……哪个环节卡壳，开机时间就蹭蹭往上涨。我这些年排查开机慢的问题，至少有一半的根因都藏在内核日志里。

4.1 内核启动的“黑盒”与“探针”

你想想看，这时候用户空间还没起来，普通logcat根本没用。怎么埋点？怎么知道内核到底在干什么？其实就三把刀：dmesg、trace_printk、Ftrace。每把刀的用法、开销、适用场景都不一样，我们一个一个说。

4.2 dmesg：最基础也最容易被忽略的日志宝矿

dmesg 读的是内核环形缓冲区（log_buf）。只要内核启动了，printk打出来的东西都在里面。我有个习惯：接到开机慢的case，第一件事就是用adb shell dmesg > boot_dmesg.txt，然后grep时间戳。

小技巧：内核在早期启动时默认把日志打到串口或Framebuffer上，但Android设备一般不接串口。dmesg是事后取日志的唯一途径。记得在userdebug/eng版本上关闭log_buf的覆盖行为：log_buf_len=4M 加到内核cmdline，防止关键日志被冲掉。

看dmesg我主要关注这几类信息：

时间戳格式：每个printk前面都带 [ 0.123456]，但注意早期时间是相对内核启动的秒数，不是wall clock。启动前期精度比较高，到了后面调度一乱可能会跳好几毫秒。
关键里程碑：比如 Kernel command line:、smp: Bringing up secondary CPUs、Freeing initrd memory、init: ...。这些点之间的delta就是内核各子阶段的耗时。
驱动加载顺序：经常能看到某个驱动init花了100ms以上——我曾经碰上某个MMC驱动在板级初始化时扫描所有分区，硬生生吃了300ms，最后改成异步probe就解决了。

# 从dmesg中抽取时间戳和消息，快速定位耗时大户
adb shell dmesg | awk '
/\[.*\]/ {
    match($0, /\[[0-9.]+\]/);
    ts = substr($0, RSTART+1, RLENGTH-2);
    sub(/^[^]]*\] */, "");
    print ts, $0
}' | sort -t. -k1,1n -k2,2n

不过要注意，dmesg不是万能的。printk本身有开销，而且内核早期有些地方printk还没初始化——那几行代码是直接写串口的，dmesg里根本看不见。我踩过这个坑，后来发现用trace_printk能补上。

4.3 trace_printk：比printk更轻量、更灵活

说白了，trace_printk 就是专门为性能分析设计的printk“小兄弟”。它不写log_buf，而是直接写trace buffer（ftrace框架的一部分），所以对主线时序影响极小。配置方法也不难：

# 内核需要开启
CONFIG_TRACING=y
CONFIG_DYNAMIC_FTRACE=y   # 可选，但推荐

# 代码中直接使用
trace_printk("my_driver init start, gpio=%d\n", gpio_num);
trace_printk("my_driver init done, took %lld us\n", ktime_to_us(ktime_sub(ktime_get(), start)));

  注意：trace_printk只在启用了ftrace并打开了tracing_on的情况下才会记录。早期内核可能还没打开ftrace，所以我很喜欢在start_kernel之后几行就主动打开：tracing_on() 或者通过在cmdline里加 trace_options=overwrite。

我个人的做法是：在几个关键驱动入口（比如 console_init、mm_init、sched_init 之后）加上trace_printk，然后通过 /sys/kernel/tracing/trace 读取。这样就能拿到非常精确的驱动间耗时。我曾经用这个办法发现某个高通平台上的GPU驱动在lpm（低功耗模式）初始化时因为等一个寄存器稳定，白白浪费了150ms。

4.4 Ftrace：函数级“显微镜”

Ftrace是内核自带的追踪框架，功能非常强大。它可以在函数入口和出口自动插入钩子，记录时间戳和调用链。对于启动阶段，我最常用的是 function_graph 模式：

# 开启function_graph，只追踪特定函数（避免爆量）
echo function_graph > /sys/kernel/tracing/current_tracer
echo my_driver_init > /sys/kernel/tracing/set_graph_function
echo 1 > /sys/kernel/tracing/tracing_on
# 等驱动跑完...
echo 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace | head -200

输出像这样：

 1)               |  my_driver_init() {
 1)  0.100 us    |    mutex_lock();
 1)  0.050 us    |    clk_prepare();
 1) 45.200 us    |    regulator_enable();  // 你瞧，这里就45微秒
 1)  2.300 us    |    gpio_direction_output();
 1)  0.080 us    |    mutex_unlock();
 1)  3.100 us    |    devm_kzalloc();
 1) 55.000 us    |  }  // 整个函数耗时55微秒

踩坑警告：function_graph开销比较大，如果一下子追踪所有函数，环形buffer秒满。我之前在生产调试机上不小心开了全函数追踪，结果手机直接重启——buffer溢出了，反而没法分析。正确做法是先缩小范围，只追踪怀疑的函数，或者用set_ftrace_filter过滤模块名的通配符。

除了function_graph，Ftrace还支持静态tracepoint（比如 sched_switch、irq_handler_entry）和kprobe动态插桩。对于启动阶段，我特别关注sched_waking和irq_handler_entry，用来分析CPU调度延迟和中断回应时间。比如有次发现某个外设的中断响应时间偶尔飙到10ms，最后查到是因为中断被别的核心上的高优先级任务屏蔽了。

工具	开销	使用时机	适合分析
dmesg	极低（printk本身有少量锁开销）	任何阶段（开箱即用）	阶段耗时概览、异常日志定位
trace_printk	低（写入trace buffer，无锁竞争）	内核早期（ftrace初始化后即可）	驱动函数级耗时精确测量
Ftrace function_graph	中（每个函数都有钩子）	ftrace完全初始化后	函数调用链、子函数耗时分解
Ftrace tracepoint	低	任意阶段	调度、中断、工作队列等事件分析

4.5 关键内核阶段的耗时分析方法

有了上面三种埋点方式，接下来就是怎么把数据变成可操作的结论。我个人喜欢用三步法：

确定里程碑点：从start_kernel到kernel_init_freeable再到init进程启动，通常找这几个点——setup_arch结束、mm_init结束、sched_init结束、do_basic_setup开始/结束、init_post。通过dmesg先拿到粗略时间。
精细拆解耗时：对每个里程碑内的驱动初始化，用trace_printk打点。比如某个总线枚举阶段花了500ms，再进一步追踪是哪个子设备占大头。
验证优化效果：改完代码后，重跑同样的埋点，对比delta。我通常会写个自动脚本，从dmesg或trace文件中parse出所有带trace_printk标签的时间戳，输出成CSV，方便Excel透视。

# 示例：从trace文件中提取自定义tag的耗时
grep "my_tag" /sys/kernel/tracing/trace | \
  awk '{print $4}' | \
  awk -F: '{print $1*60+$2}'  # 把时间戳转成秒

避坑指南：我曾经在一台手机上用dmesg检查启动时间，发现从smp: Bringing up secondary CPUs到Freeing initrd memory之间出现了凭空多出的300毫秒。后来用trace_printk逐行打点时才发现——不是内核慢，而是dmesg的时间戳在SMP初始化之后因为CPU时钟不同步产生了跳跃。解决办法是用ktime_get()打本地时间，而不是依赖printk的全局时间戳。

另外，别忘了用Bootchart/Perfetto做整体校验。内核埋点的数据最终要和用户空间的启动曲线对上。比如你测出内核在某个驱动上花了200ms，结果Perfetto上对应的init.powerctl阶段也恰好卡了200ms，那就对上了。如果对不上，通常是时间基准不一致——内核用jiffies或clocksource，用户空间用trace clock，需要统一用同一个时钟源（比如 monotonic_raw）。

嗯，关于内核启动阶段的埋点，核心方法就这些。记住：不要迷信单一工具，dmesg、trace_printk、Ftrace各有各的长处和盲区。我在实际项目中往往三者混合使用——先用dmesg快速定位异常区间，再用trace_printk精确定位函数，最后用Ftrace深挖调用链。下一层功夫都下在“如何把时间戳解读成清晰的瓶颈分析”上，这比单纯打点重要得多。