☰

遅延がドライバによって発生したのか、スケジューラによって発生したのかをどのように確認できますか？

tag-icon • tag-icon strace uart latency
遅延がドライバによって発生したのか、スケジューラによって発生したのかをどのように確認できますか？

オシロスコープを使用して一部のピンを切り替えると、8バイトのUARTパケット転送とブロッキングリードリターンの間に1〜2秒の遅延が発生することがあります。パケットの持続時間は1秒で、数ミリ秒のジッタがあります。また（下記参照）を使用してシステムコールのタイミングを測定し、strace結果はI / O測定と一致しました。

UARTドライバにこの遅延があるかどうか、または他のタスクが私のタスクに影響を与えるかどうか（適切な値は-20）確認しようとします。ドライバについて疑問に思ったのは、このコードの以前のバージョンがUARTを安定して使用して、毎秒〜26kBのパケットを送信したためです（ドライババッファは4kBでした）。

プロセスは使用ですpyserial。この失敗したケースでstrace報告された時間間隔は3秒以上epoll_waitでしたclock_gettime。

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バイトのデータパケットを受信し、SPIを介してLinuxにNバイトを読み取るように要求します。 SPIを実行します。 8バイトのパケットを読み取り、SPI要求が正常に完了したことを確認します。 SPI転送には約40msかかります。要求パケットと結果パケットの間の通常モードは約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？）を確認することをお勧めします。また、以前のバージョンのコード/ドライバ/システムと時間を比較することもできます。

関連情報