2. 启动时间测量方法：使用 printk 时间戳、initcall_debug、bootgraph 工具、ftrace 进行启动时间分析
精确测量是优化的前提。Linux 内核提供了多种内置和外置工具来捕获启动各阶段的耗时。本章将逐一介绍 printk 时间戳、initcall_debug、bootgraph 以及 ftrace 的使用方法，帮助您建立从粗粒度到细粒度的测量能力。
2.1 printk 时间戳：最基础的启动计时器
printk 时间戳是内核在每条 printk 消息前自动添加的时间前缀，精度通常为微秒级。它是启动时间分析的“第一把尺子”。
启用方法
在 kernel cmdline 中添加 printk.time=y 或 time 参数：
# 在 U-Boot 或 bootloader 的 bootargs 中添加
console=ttyS0,115200 printk.time=y输出示例
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000123] Initializing cgroup subsys cpu
[ 1.456789] Freeing unused kernel memory: 1024K
[ 2.345678] Run /init as init process方括号内的数字即为自启动以来的秒数（含小数）。通过对比关键节点的时间戳差值，可快速定位耗时异常的阶段。
earlyprintk 或 earlycon，以捕获最早期的内核消息。
关键时间戳节点对照表
| 时间戳节点 | 含义 | 典型耗时（嵌入式） |
|---|---|---|
[0.000000] |
内核解压完成，开始启动 | 0 ms |
kernel_init() 开始 |
内核初始化入口 | ~50 ms |
Freeing unused kernel memory |
内核核心初始化完成 | ~500 ms |
Run /init as init process |
切换到用户空间 init | ~800 ms |
2.2 initcall_debug：逐级展开内核初始化调用
printk 时间戳只能看到“大阶段”，而 initcall_debug 可以打印出内核中每一个初始化函数（initcall）的调用顺序和耗时。
启用方法
# 在 kernel cmdline 中添加
initcall_debug输出示例
[ 0.123456] initcall do_initcalls+0x0/0x100 returned 0 after 12345 usecs
[ 0.234567] initcall populate_rootfs+0x0/0x200 returned 0 after 23456 usecs
[ 0.345678] initcall populate_rootfs+0x0/0x200 returned 0 after 34567 usecs每一行都包含：函数名、返回值、执行耗时（微秒）。通过排序这些耗时，可以快速找出“拖后腿”的 initcall。
initcall_debug 会增加大量串口输出，可能影响启动时间本身（串口瓶颈）。建议在调试阶段使用，或配合 quiet 参数将输出重定向到内存缓冲区。
分析流程
- 收集完整的启动日志。
- 使用
grep "initcall.*returned"提取所有 initcall 行。 - 按耗时降序排列，定位 Top N 耗时函数。
- 针对耗时函数对应的驱动或子系统进行优化。
2.3 bootgraph：可视化启动时序
bootgraph 是内核源码 scripts/bootgraph.pl 提供的 Perl 脚本，它将 initcall_debug 的日志转换为 SVG 时序图，直观展示各 initcall 的起止时间和依赖关系。
使用方法
# 1. 收集带 initcall_debug 的启动日志
dmesg > boot.log
# 2. 使用 bootgraph.pl 生成 SVG
perl scripts/bootgraph.pl boot.log > bootgraph.svg生成的 SVG 图示例
通过 bootgraph 生成的 SVG，可以一目了然地看到哪些初始化函数占用了最长的“时间条”，从而确定优化优先级。
2.4 ftrace：函数级启动时间追踪
当需要深入分析某个特定 initcall 或驱动内部的函数调用链时，ftrace 是内核最强大的追踪工具。它可以在几乎零开销的情况下记录函数调用、耗时和上下文切换。
常用配置步骤
# 挂载 tracefs
mount -t tracefs tracefs /sys/kernel/tracing
# 选择追踪器为 function_graph
echo function_graph > /sys/kernel/tracing/current_tracer
# 设置要追踪的函数（例如 mmc_init）
echo mmc_init > /sys/kernel/tracing/set_graph_function
# 设置追踪深度（可选）
echo 10 > /sys/kernel/tracing/max_graph_depth
# 开始追踪
echo 1 > /sys/kernel/tracing/tracing_on
# 执行需要分析的操作（如重新加载驱动）
modprobe -r mmc_block; modprobe mmc_block
# 停止追踪
echo 0 > /sys/kernel/tracing/tracing_on
# 查看追踪结果
cat /sys/kernel/tracing/trace输出示例
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) 0.123 us | mmc_init();
0) 1.456 us | mmc_alloc_host();
0) 23.456 us | mmc_add_host();
0) 0.789 us | mmc_claim_host();
0) 45.678 us | mmc_rescan();
0) 0.001 us | mmc_release_host();DURATION 列显示了每个函数的执行时间，可以精确到微秒级。通过分析子函数的耗时，可以定位到具体的代码行或硬件操作。
2.5 四种测量方法对比
| 方法 | 粒度 | 开销 | 适用场景 |
|---|---|---|---|
| printk 时间戳 | 粗（消息级） | 极低 | 快速定位大阶段耗时 |
| initcall_debug | 中（函数级） | 低 | 定位耗时驱动/子系统 |
| bootgraph | 中（可视化） | 低（基于日志） | 团队汇报、趋势分析 |
| ftrace | 细（指令级） | 中 | 深入分析特定函数内部 |
2.6 综合测量流程
建议按照“先粗后细”的原则：先用 printk 时间戳和 initcall_debug 做全局扫描，再用 bootgraph 可视化确认热点，最后用 ftrace 对热点函数进行深入追踪。