📚 课程目录第3章 U-Boot启动时间测量

3. U-Boot启动时间测量：GPIO、串口时间戳与printk时间戳

启动时间优化，第一步就是得知道时间花在哪了。我见过不少团队，一上来就闷头改代码，改完一测——嗯，好像快了点，但具体快在哪，说不清楚。这不行。

测量U-Boot各阶段耗时，说白了就三种手段：GPIO电平翻转、串口时间戳、printk时间戳。各有各的适用场景，也各有各的坑。今天我把它们掰开揉碎了讲清楚。

核心原则：测量本身不能引入显著开销，否则你测出来的不是真实启动时间，而是“带探针的启动时间”。

3.1 三种测量手段对比

先给个总览表格，方便你快速选型。

方法	精度	开销	硬件依赖	适用阶段
GPIO电平翻转	纳秒级（取决于逻辑分析仪）	几乎为零（几条写寄存器指令）	需要空闲GPIO + 逻辑分析仪/示波器	U-Boot SPL、早期初始化
串口时间戳	毫秒级（受波特率限制）	中等（串口输出本身耗时）	串口线 + 终端软件	U-Boot主阶段、驱动初始化
printk时间戳	微秒级（依赖timer驱动）	低（仅时间戳计算）	无额外硬件	Linux内核启动阶段

我个人习惯是：SPL阶段用GPIO，主U-Boot阶段用串口时间戳，内核阶段用printk。这样覆盖了从ROM代码到内核init的全链路。

3.2 GPIO电平翻转法——最硬核的测量手段

这个方法原理很简单：在关键函数入口拉高GPIO，出口拉低GPIO。用逻辑分析仪抓波形，高电平宽度就是该函数的执行时间。

为什么说它最硬核？因为它不依赖任何软件定时器，不受中断影响，精度只取决于你的测量设备。我在调试某款车规级芯片时，SPL阶段连串口都还没初始化，只能用这招。

3.2.1 实现步骤

选GPIO：找一个启动过程中不会被复用的GPIO。我建议用调试专用GPIO，实在没有就用LED对应的GPIO，但记得初始化时别让LED亮。
写宏：在arch/arm/include/asm/io.h或板级头文件中添加：

#define MEASURE_GPIO_BASE   (0x01C20800)  // 以某款SoC为例
#define MEASURE_GPIO_PIN    (1 << 12)      // GPIO PD12

#define gpio_start() \
    writel(MEASURE_GPIO_PIN, MEASURE_GPIO_BASE + 0x10)  // 拉高
#define gpio_stop()  \
    writel(MEASURE_GPIO_PIN, MEASURE_GPIO_BASE + 0x14)  // 拉低

插桩：在board_init_f()、board_init_r()、main_loop()等关键函数前后插入：

void board_init_f(ulong boot_flags)
{
    gpio_start();  // 开始计时

    // ... 原有初始化代码 ...

    gpio_stop();   // 结束计时
}

抓波形：逻辑分析仪采样率建议至少10MHz，触发条件设为上升沿。

小技巧：如果你有4通道逻辑分析仪，可以同时测4个阶段。每个阶段用不同GPIO，波形图上直接对比，一目了然。

3.2.2 避坑指南

我曾经在一个项目里发现GPIO测量结果比预期多了几十毫秒。排查了半天，原来是GPIO对应的引脚被复用成了其它功能，拉高拉低操作根本没生效。所以——测量前先用万用表确认GPIO电平确实在变化。

另外要注意：有些SoC的GPIO写操作需要经过总线桥，延迟可能达到几百纳秒。对于微秒级的测量来说可以忽略，但如果你要测纳秒级的代码路径，就得用SoC提供的硬件时间戳单元（如ARM的PMU）。

3.3 串口时间戳法——最实用的调试手段

串口时间戳是我用得最多的方法。它不需要额外硬件，一根串口线就能搞定。原理是在串口输出信息前，先打印一个时间戳。

U-Boot里自带了一个__timestamp宏，但那是编译时间，不是运行时间。我们需要的是get_timer()函数，它返回从U-Boot启动到现在的毫秒数。

3.3.1 实现方法

在common/console.c或你自己的调试文件中添加：

#define print_timestamp() \
    printf("[%5lu] ", get_timer(0))

// 使用示例
print_timestamp();
printf("Entering board_init_f\n");

// ... 执行一些操作 ...

print_timestamp();
printf("Leaving board_init_f, elapsed: %lu ms\n", 
       get_timer(start_time));

输出效果：

[    0] Entering board_init_f
[   12] DRAM init done
[   45] Leaving board_init_f, elapsed: 45 ms
[   48] Entering board_init_r
[  120] MMC init done
[  180] Leaving board_init_r, elapsed: 132 ms

注意：串口输出本身是有延迟的。115200波特率下，输出一个字符大约需要87微秒。如果你在循环里频繁打印时间戳，测量结果会严重失真。我建议只在阶段切换处打印，不要每个函数都打。

3.3.2 进阶用法：自动记录到内存缓冲区

串口输出慢，但内存写入快。我们可以先把时间戳记录到内存缓冲区，最后统一输出。这样测量开销几乎为零。

#define MAX_TIMESTAMPS 64
static struct {
    ulong time;
    char  msg[32];
} ts_buf[MAX_TIMESTAMPS];
static int ts_idx = 0;

#define record_timestamp(msg) do { \
    if (ts_idx < MAX_TIMESTAMPS) { \
        ts_buf[ts_idx].time = get_timer(0); \
        strncpy(ts_buf[ts_idx].msg, msg, 31); \
        ts_idx++; \
    } \
} while (0)

// 在main_loop最后输出
void dump_timestamps(void)
{
    for (int i = 0; i < ts_idx; i++) {
        printf("[%5lu] %s\n", ts_buf[i].time, ts_buf[i].msg);
    }
}

这个方法我在调试NAND Flash驱动时用过。当时串口输出太多，导致启动时间从2秒变成了5秒。改用内存缓冲区后，测量结果才真实反映实际性能。

3.4 printk时间戳法——内核阶段的利器

进入Linux内核后，我们有了更强大的工具：printk时间戳。它由内核的clock_source提供，精度通常能达到微秒级。

3.4.1 开启方法

内核启动参数中添加：

printk.time=1

或者在/proc/sys/kernel/printk中动态开启：

echo 1 > /proc/sys/kernel/printk_time

开启后，内核日志会变成这样：

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000123] Machine model: MyBoard v2
[    0.456789] mmc0: new high speed SD card at address 1234
[    1.234567] EXT4-fs (mmcblk0p2): mounted filesystem

方括号里的数字就是从内核启动开始到现在的秒数（精度到微秒）。

3.4.2 如何分析

我通常用dmesg导出日志，然后用脚本分析。比如找出耗时最长的驱动初始化：

dmesg | grep -E "initcall|probe" | awk '{
    match($0, /\[ *([0-9]+\.[0-9]+)\]/, t);
    if (prev_time) {
        diff = t[1] - prev_time;
        if (diff > 0.1) print diff, $0;
    }
    prev_time = t[1];
}'

这个脚本会输出所有耗时超过100ms的initcall。我在一个项目中用这个脚本发现，某个GPIO驱动probe花了800ms——原因是它等待了一个不存在的硬件复位完成。

关键点：printk时间戳的精度取决于内核使用的clocksource。如果用的是jiffies（精度10ms），那微秒级的时间戳就是假的。一定要确认/sys/devices/system/clocksource/clocksource0/current_clocksource是arch_sys_counter或armv8_timer这类高精度源。

3.5 三种方法的协同使用——实战流程

下面这张图展示了我在实际项目中如何组合使用这三种方法：

3.6 实战案例：一次完整的启动时间测量

拿我最近调试的一块i.MX8M板子举例。客户反馈说启动到根文件系统挂载需要4.5秒，要求优化到3秒以内。

我的测量步骤：

SPL阶段：用GPIO法测量，发现SPL花了320ms。其中DDR初始化占了280ms——嗯，这个后面可以优化。
U-Boot主阶段：用串口时间戳+内存缓冲，测得总耗时780ms。其中MMC初始化花了350ms，原因是它扫描了4个MMC控制器，实际上只用了一个。
内核阶段：开启printk时间戳，用脚本分析dmesg。发现一个GPIO驱动probe花了600ms，原因是它等待了一个外部中断超时。

最终优化结果：SPL的DDR初始化改用快速训练模式（省200ms），U-Boot里禁用未使用的MMC控制器（省250ms），内核GPIO驱动改用轮询模式（省500ms）。总启动时间从4.5秒降到了2.8秒。

我的经验：启动优化遵循“二八定律”——80%的耗时集中在20%的代码路径上。先用测量手段找到那20%，然后集中精力优化。别在无关紧要的地方浪费时间。

3.7 总结

三种测量方法各有千秋，没有银弹。我的建议是：

SPL阶段：GPIO电平翻转法，精度最高，无依赖。
U-Boot主阶段：串口时间戳+内存缓冲，平衡精度和便利性。
内核阶段：printk时间戳+脚本分析，自动化程度高。