☰

如何确定延迟是由驱动程序还是调度程序造成的？

tag-icon • tag-icon strace uart latency
如何确定延迟是由驱动程序还是调度程序造成的？

使用示波器并切换一些引脚，我有时会看到从传输 8 字节 UART 数据包到阻塞读取返回之间有 1-2 秒的延迟。数据包时长为 1 秒，有几毫秒的抖动。我还使用测量了系统调用的时序（见下文）strace，结果与我的 I/O 测量一致。

我正在尝试确定此延迟是否存在于 UART 驱动程序中，或者其他任务是否正在影响我的任务（其良好值为 -20）。我对驱动程序感到好奇的原因是，此代码的早期版本可靠地使用 UART 来传输每秒约 26 kB 的数据包（驱动程序缓冲区为 4 kB）。

该过程是一个使用pyserial.在这个失败的案例中，strace报告的时间间隔epoll_wait为clock_gettime3 秒以上。

0.000883 epoll_ctl(3, EPOLL_CTL_ADD, 7, {EPOLLIN, {u32=7, u64=8589934599}}) = -1 EEXIST (File exists)
0.000681 clock_gettime(CLOCK_MONOTONIC, {92406, 209555006}) = 0
0.000655 epoll_wait(3, {}, 64, 98) = 0
3.004082 clock_gettime(CLOCK_MONOTONIC, {92409, 214251206}) = 0

重复动作为： 接收8字节数据包，请求Linux通过SPI读取N个字节。执行 SPI。读取 8 字节数据包以查看 SPI 请求是否成功完成。 SPI 传输大约需要 40 ms。请求数据包和结果数据包之间的正常模式约为 40 毫秒。大约需要 960 毫秒，直到收到下一个请求。

Duchess: strace -r -e read -p 7564
Process 7564 attached
     0.000000 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.049142 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.950381 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.050035 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.949962 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.049601 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.950417 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.049654 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.950507 read(7, "\355\336\255\336\20d\0\0", 8) = 80.950516 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.049944 read(7, "\255\336\355\336\1\0\0\0", 8) = 8 [Success]
     2.196903 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.048876 read(7, "\255\336\355\336\0\0\0\0", 8) = 8 [Failure]
     0.015570 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.053889 read(7, "\255\336\355\336\0\0\0\0", 8) = 8 [Failure]
     0.634720 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.050070 read(7, "\255\336\355\336\1\0\0\0", 8) = 8 [Success]

答案1

strace不太可能为您提供必要的详细信息；您可能需要 SystemTap、sysdig 或类似的内核级调试来更好地显示发生的情况。例如，安装了 SystemTap 并处理了所有必要的调试信息和设置详细信息后，可以从以下开始：

probe begin
{
        printf("%-16s %s\n", "TIME", "WHAT");
}

probe tty.{ioctl,receive}
{
        if (pid() != target()) next;
        printf("%d ttyx    %s\n", gettimeofday_us(), name);
}

probe tty.poll
{
        if (pid() != target()) next;
        printf("%d ttypoll %s\n", gettimeofday_us(), file_name);
}

probe tty.{read,write}
{
        if (pid() != target()) next;
        printf("%d ttyio   %s %d\n", gettimeofday_us(), file_name, nr);
}

probe syscall.{read,write,epoll_*}
{
        if (pid() != target()) next;
        printf("%d syscall %s\tenter\n", gettimeofday_us(), name);
}

probe syscall.{read,write,epoll_*}.return
{
        if (pid() != target()) next;
        printf("%d syscall %s\treturn\n", gettimeofday_us(), name);
}

并通过运行

$ sudo stap -x "$(pidof ...)" filecontainingtheabovecode.stp

这对于串行测试程序和附加的 Arduino对我来说显示：

TIME             WHAT
1516997916648359 syscall read   enter
1516997916648366 ttyio   ttyACM0 4096
1516997916652456 syscall read   return
1516997916652465 syscall read   enter
1516997916652470 ttyio   ttyACM0 4096
1516997916656459 syscall read   return
1516997916656497 syscall write  enter
1516997916656503 ttyio   4 21
1516997916656511 syscall write  return
...

如果上面没有显示延迟在哪里，您可能还需要查阅 SystemTap Tapsets 文档以了解其他感兴趣的探测点（调度程序、I/O 调度程序、IRQ？）。并可能将时间与旧版本的代码/驱动程序/系统进行比较......

相关内容