主页 / unix / 问题 / 419449
Accepted
Kenny
Asked: 2018-01-25 12:29:09 +0800 CST

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

  • 772

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

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

该过程是一个 Python 脚本，它使用pyserial. 在这种失败的情况下strace，报告介于epoll_wait和之间的时间clock_gettime超过 3 秒。

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 毫秒。请求数据包和结果数据包之间的健康模式约为 40 ms。大约 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]
strace uart

1 个回答

  1. Best Answer

    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？）。并且可能将时间与旧版本的代码/驱动程序/系统进行比较......

    • 2

相关问题