10、性能日志：记录函数执行时间，使用clock()和gettimeofday()，性能分析基础

性能日志，说白了就是给代码装个秒表。

你写了一个函数，它跑得快不快？瓶颈在哪？哪个环节拖了后腿？没有数据，全靠猜，那跟闭着眼开车没区别。我早年做嵌入式项目时，就吃过这个亏——系统偶尔卡顿，查了三天，最后发现是一个日志打印函数本身占用了大量CPU时间。从那以后，我养成了一个习惯：凡是关键路径上的函数，必须记录执行时间。

10.1 为什么需要性能日志？

性能日志不是锦上添花，而是雪中送炭。它的核心价值有三点：

• 定位瓶颈：哪个函数最耗时？是算法问题还是IO等待？数据说话。
• 回归验证：优化后到底快了多少？没有基线数据，优化就是玄学。
• 异常预警：某个函数突然变慢，可能是资源耗尽或硬件退化。

你想想看，一个系统跑着跑着突然慢了，如果没有性能日志，你只能靠猜。有了它，直接看数据，一目了然。

10.2 两种计时工具：clock() vs gettimeofday()

C语言里最常用的两个计时函数，就是clock()和gettimeofday()。它们各有各的脾气，用错了会出大问题。

10.2.1 clock()：CPU时间，不是墙钟时间

clock()返回的是程序占用的CPU时钟滴答数。注意，它不包含睡眠、等待IO的时间。换句话说，它只算你真正在干活的时间。

#include <time.h>

double get_cpu_time_ms(void) {
    clock_t t = clock();
    return (double)t / CLOCKS_PER_SEC * 1000.0;
}

void test_function() {
    clock_t start = clock();
    // 模拟一些计算
    for (volatile int i = 0; i < 1000000; i++);
    clock_t end = clock();
    double elapsed = (double)(end - start) / CLOCKS_PER_SEC * 1000.0;
    printf("CPU时间: %.3f ms\n", elapsed);
}

10.2.2 gettimeofday()：墙钟时间，更精确

gettimeofday()返回的是从1970年1月1日到现在的秒数和微秒数。它测量的是真实流逝的时间，包括线程休眠、IO等待等。精度微秒级，适合大多数场景。

#include <sys/time.h>

long long get_wall_time_us(void) {
    struct timeval tv;
    gettimeofday(&tv, NULL);
    return (long long)tv.tv_sec * 1000000 + tv.tv_usec;
}

void test_function() {
    long long start = get_wall_time_us();
    // 模拟一些操作
    usleep(1000); // 休眠1ms
    long long end = get_wall_time_us();
    double elapsed = (end - start) / 1000.0;
    printf("墙钟时间: %.3f ms\n", elapsed);
}

10.3 封装一个性能日志工具

每次手动写start/end太麻烦。我建议封装一个宏或函数，自动记录函数执行时间。下面是我常用的一个轻量级工具：

#include <stdio.h>
#include <time.h>
#include <sys/time.h>

typedef enum {
    TIMER_CPU,
    TIMER_WALL
} TimerType;

typedef struct {
    TimerType type;
    union {
        clock_t cpu_start;
        struct timeval wall_start;
    } u;
} Timer;

void timer_start(Timer *t, TimerType type) {
    t->type = type;
    if (type == TIMER_CPU) {
        t->u.cpu_start = clock();
    } else {
        gettimeofday(&t->u.wall_start, NULL);
    }
}

double timer_stop(Timer *t) {
    if (t->type == TIMER_CPU) {
        clock_t end = clock();
        return (double)(end - t->u.cpu_start) / CLOCKS_PER_SEC * 1000.0;
    } else {
        struct timeval end;
        gettimeofday(&end, NULL);
        long long diff = (end.tv_sec - t->u.wall_start.tv_sec) * 1000000 +
                         (end.tv_usec - t->u.wall_start.tv_usec);
        return diff / 1000.0;
    }
}

// 使用示例
#define LOG_PERF(name, code_block) do { \
    Timer t; \
    timer_start(&t, TIMER_WALL); \
    code_block; \
    double ms = timer_stop(&t); \
    printf("[PERF] %s: %.3f ms\n", name, ms); \
} while(0)

// 调用
LOG_PERF("数据排序", {
    // 排序代码
    for (int i = 0; i < 10000; i++);
});

10.4 性能分析基础：数据怎么看？

有了数据，还得会看。我总结了几条经验：

• 关注异常值：平均时间正常，但偶尔出现一个很大的值，这往往是问题的信号。可能是缓存未命中、中断处理、或资源竞争。
• 区分CPU时间和墙钟时间：如果CPU时间远小于墙钟时间，说明函数大部分时间在等待（IO、锁、休眠）。反之，如果两者接近，说明是计算密集型。
• 多次测量取中位数：单次测量受系统负载影响很大。我一般跑100次，去掉最高最低，取中位数。平均值容易被极端值带偏。

举个例子，我曾经优化一个图像处理函数。用clock()测CPU时间只有5ms，但用gettimeofday()测墙钟时间却高达50ms。一查，发现函数里有个fopen()操作，每次打开文件都要等磁盘IO。后来改成内存映射，墙钟时间降到了6ms。

10.5 避坑指南

10.6 知识体系图

下面这张图总结了性能日志的核心逻辑和工具选择路径：

10.7 小结

性能日志是嵌入式开发者的基本功。选对计时工具、封装好工具函数、学会看数据，你就能从「感觉慢」进化到「知道哪里慢」。我个人建议，每个项目从一开始就集成性能日志模块，不要等到出问题再补。嗯，这就像给代码买保险——平时觉得没用，真出事时才知道它的价值。