3. 启动时间测量：硬件示波器测量法、printk 时间戳法、initcall_debug 内核参数、bootgraph 与 bootchart 工具

做启动优化，第一件事不是动手改代码，而是先搞清楚时间花在哪了。我见过不少工程师上来就砍驱动、改 init 脚本，结果折腾半天，启动时间反而更长了。说白了，没有数据支撑的优化就是瞎蒙。

这一章，我带你过一遍 Tina Linux 上最常用的四种测量手段。每种方法都有它的适用场景，也有它的坑。咱们一个一个来。

3.1 硬件示波器测量法：最原始，也最可靠

你可能会问：都什么年代了，还用示波器？嗯，我刚开始做嵌入式的时候也这么想。直到有一次，软件时间戳显示启动只要 3 秒，但客户拿秒表一掐，足足 5 秒。问题出在哪？软件计时本身就有开销，而且内核打印还会阻塞。

硬件示波器测量法，说白了就是拿 GPIO 引脚打点。在关键节点拉高或拉低电平，示波器一看，时间差清清楚楚。

操作步骤

1. 选一个空闲 GPIO，比如 PE12。确保它不会被其他驱动占用。
2. 在 bootloader 里打点。以 U-Boot 为例，在 start.S 或 board_init 里加上 GPIO 操作。
3. 在内核里打点。在 start_kernel 入口、init 进程启动、根文件系统挂载等位置加入 gpio_direction_output 和 gpio_set_value。
4. 接上示波器，测量各段电平宽度。

// 内核中打点示例
#include <linux/gpio.h>

#define MEASURE_GPIO 112  // PE12

static int __init measure_init(void)
{
    gpio_request(MEASURE_GPIO, "measure");
    gpio_direction_output(MEASURE_GPIO, 0);
    gpio_set_value(MEASURE_GPIO, 1);  // 开始计时
    return 0;
}
early_initcall(measure_init);

我个人习惯在三个关键位置打点：U-Boot 启动完成、内核解压完成、init 进程启动。这样就能把整个启动过程切成三段，哪段慢了一目了然。

3.2 printk 时间戳法：零成本，随手可用

如果你手头没有示波器，或者不想改硬件，printk 时间戳是最快的办法。内核默认就支持，你只需要在启动参数里加一个选项。

原理很简单：内核每打印一条消息，都会在前面加上一个时间戳。这个时间戳是从系统启动开始到现在的微秒数。

开启方法

在 kernel cmdline 里加上 printk.time=y。如果你用的是 Tina Linux，可以在 board.dts 或 env.cfg 里配置：

bootargs=console=ttyS0,115200 printk.time=y

启动后，dmesg 输出会变成这样：

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000456] Machine model: Allwinner sun8i Family
[    1.234567] mmc0: new high speed SD card at address 1234
[    2.345678] VFS: Mounted root (squashfs filesystem) on device 31:0

看到没？方括号里的数字就是时间戳，单位是秒。从 0 开始，到根文件系统挂载用了 2.34 秒。

不过要注意，printk 时间戳的精度受内核 tick 频率影响。如果内核配置了 CONFIG_HZ=100，那时间戳精度只有 10 毫秒。想提高精度，可以改成 CONFIG_HZ=1000，代价是 CPU 开销会大一点。

3.3 initcall_debug 内核参数：把内核初始化扒个精光

printk 时间戳只能看到大概，但内核初始化阶段到底哪个驱动慢？哪个模块卡住了？这时候就需要 initcall_debug 了。

这个参数一开，内核会把每个 initcall 的入口和出口都打印出来，包括函数名、返回值、执行耗时。说白了，就是给内核初始化过程加了个性能分析器。

使用方法

同样在 kernel cmdline 里加上：

bootargs=console=ttyS0,115200 initcall_debug

启动后你会看到类似这样的输出：

[    0.123456] initcall sunxi_mmc_init+0x0/0x40 returned 0 after 12345 usecs
[    0.234567] initcall sunxi_i2c_init+0x0/0x30 returned 0 after 5678 usecs
[    1.234567] initcall sunxi_lcd_init+0x0/0x60 returned 0 after 345678 usecs

看到最后那个 LCD 驱动了吗？花了 345 毫秒！这就是优化的重点对象。

你可以把 dmesg 输出重定向到文件，然后用脚本分析。比如按耗时排序：

dmesg | grep "initcall" | sed 's/.*after //' | sort -rn | head -20

这样就能快速找出最耗时的前 20 个 initcall。

3.4 bootgraph 与 bootchart：可视化分析，一目了然

如果你觉得看日志太累，那就上可视化工具。bootgraph 和 bootchart 能把启动过程画成时序图，哪个进程在跑、哪个在等，一眼就能看出来。

3.4.1 bootgraph：内核初始化时序图

bootgraph 是内核自带的一个脚本，位置在 scripts/bootgraph.pl。它解析 dmesg 输出，生成 SVG 格式的时序图。

使用方法：

# 先获取带 initcall_debug 的 dmesg
dmesg > dmesg.log

# 生成 bootgraph
perl scripts/bootgraph.pl dmesg.log > bootgraph.svg

生成的 SVG 图里，横轴是时间，纵轴是各个 initcall 函数。每个函数用一条横线表示，线的长度就是执行耗时。一眼就能看出哪个驱动是「胖子」。

3.4.2 bootchart：用户空间启动分析

bootchart 侧重分析用户空间的启动过程，也就是 init 进程启动之后的事。它通过一个后台进程采样 CPU、磁盘、进程状态，最后生成 PNG 或 SVG 图表。

在 Tina Linux 上开启 bootchart：

# 内核配置
make kernel_menuconfig
# 选中: General setup -> Kernel .config support
# 选中: General setup -> Kernel bootchart support

# 在 cmdline 里加上
bootargs=... init=/sbin/bootchartd

启动后，bootchart 会在 /var/log/bootchart.tgz 生成数据文件。把它拷到 PC 上，用 pybootchartgui 打开：

pybootchartgui bootchart.tgz

你会看到一张彩色的时序图，每个进程一条泳道，CPU 使用率、磁盘 I/O 都标得清清楚楚。

3.5 四种方法对比

说了这么多，我把四种方法的优缺点整理成一张表，方便你选型：

方法	精度	适用阶段	优点	缺点
硬件示波器	纳秒级	全阶段	最准确，不受软件干扰	需要改硬件，操作麻烦
printk 时间戳	毫秒级	内核阶段	零成本，随手可用	精度受 HZ 限制
initcall_debug	微秒级	内核 initcall	精确到每个函数，定位精准	日志量大，影响串口速度
bootgraph/bootchart	毫秒级	内核+用户空间	可视化，直观易懂	需要额外工具解析

3.6 本章知识结构图

下面这张 SVG 图总结了四种测量方法的定位和关系：

3.7 我的建议

说了这么多，到底该用哪种？我的建议是分三步走：

• 第一步：开 printk 时间戳，先看个大概。如果总时间已经达标，就别折腾了。
• 第二步：如果时间超标，开 initcall_debug 和 bootchart，定位具体瓶颈。
• 第三步：对关键优化点，用示波器做精确验证。

我曾经在一个项目里，客户要求启动时间从 8 秒降到 3 秒。我用 bootchart 一看，发现有个服务在等网络就绪，等了 4 秒。改成异步启动后，直接达标。你看，工具用对了，问题就解决了一半。