为何gettimeofday/clock_gettime统计ReadData耗时远大于子操作之和？

我在使用gettimeofday()和clock_gettime()统计ReadData()函数的执行耗时，该函数包含两个核心操作：读取/dev/spiio0设备（耗时记为timer1）、SPI读写操作（耗时记为timer2）。理论上总耗时Timer应该接近timer1与timer2的和，但偶尔会出现Timer远大于两者之和的异常情况，比如某次测试数据：

timer1=8242 us，timer2=440 us，timer=95027 us

可能的原因 #

• 线程调度抢占：系统在ReadData()执行过程中，内核将当前线程切换到后台，总耗时包含了线程被阻塞的等待时间，但子步骤计时只覆盖了各自操作的实际执行时间。
• 隐性内核态等待：函数内可能存在未被计时的隐性操作，比如/dev/spiio0打开后的锁竞争、设备队列阻塞、页缓存同步，或者SPI操作后的硬件等待逻辑，这些等待时间被计入总Timer，但未被统计到timer1和timer2中。
• 计时边界错误：总Timer的起始/结束点可能包含了函数调用前后的额外操作，比如函数入口前的栈准备、函数返回后的清理，或者子步骤计时点的位置不准确（比如timer1的结束点到timer2的起始点之间有未计时的代码）。
• 系统负载波动：异常发生时系统可能处于高负载状态，比如其他进程占用CPU、磁盘IO繁忙，导致整个函数的执行被延迟。

排查建议 #

1. 切换CPU时间计时：改用clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts)统计线程的CPU时间（而非墙上时间），对比总CPU时间与子步骤CPU时间之和，判断是否是调度抢占导致的差异。
2. 细化计时粒度：在ReadData()的每一个关键节点（函数入口、设备打开前后、读取前后、SPI操作前后、函数出口）都添加计时，定位具体是哪一段出现了额外耗时。
3. 监控系统状态：异常发生时查看系统日志、top/vmstat/iostat等工具的输出，检查是否有高上下文切换、IO等待、中断风暴等情况。
4. 检查隐性操作：排查代码中是否存在未被计时的操作，比如锁的获取释放、内存分配、数据拷贝、错误处理分支等。

测试代码示例 #

#include <stdio.h>
#include <stdlib.h>
#include <sys/time.h>
#include <unistd.h>
#include <fcntl.h>
#include <errno.h>
#include <string.h>

#define USEC_PER_SEC 1000000LL

// 获取当前时间（微秒）
static inline long long get_current_usec() {
    struct timeval tv;
    gettimeofday(&tv, NULL);
    return (long long)tv.tv_sec * USEC_PER_SEC + tv.tv_usec;
}

void ReadData() {
    long long total_start = get_current_usec();

    // 打开/dev/spiio0
    int fd = open("/dev/spiio0", O_RDONLY);
    if (fd < 0) {
        fprintf(stderr, "open /dev/spiio0 failed: %s\n", strerror(errno));
        return;
    }

    // 统计/dev/spiio0读取耗时
    long long timer1_start = get_current_usec();
    char buf[1024];
    ssize_t read_len = read(fd, buf, sizeof(buf));
    long long timer1_end = get_current_usec();
    long long timer1 = timer1_end - timer1_start;
    printf("timer1 (read /dev/spiio0): %lld us\n", timer1);

    close(fd);

    // 统计SPI操作耗时（替换为实际SPI代码）
    long long timer2_start = get_current_usec();
    // 模拟SPI操作耗时，实际场景替换为SPI读写逻辑
    usleep(440);
    long long timer2_end = get_current_usec();
    long long timer2 = timer2_end - timer2_start;
    printf("timer2 (SPI operation): %lld us\n", timer2);

    long long total_end = get_current_usec();
    long long total_timer = total_end - total_start;
    printf("Total Timer: %lld us\n", total_timer);
}

int main() {
    // 循环测试，触发异常情况
    for (int i = 0; i < 100; ++i) {
        printf("===== Test Round %d =====\n", i + 1);
        ReadData();
        printf("\n");
    }
    return 0;
}

内容的提问来源于stack exchange，提问作者Vimer