如何確定延遲是由驅動程序還是調度程序引起的？

使用示波器並切換一些引腳，我有時會看到從傳輸 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不太可能為您提供必要的詳細資訊；您可能需要 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？）。並且可能將時間與舊版本的程式碼/驅動程序/系統進行比較……

引用自：https://unix.stackexchange.com/questions/419449