How can I determine if a latency is due to a driver or the scheduler?

Question

Using an oscilloscope and toggling some pins I sometimes see latencies of 1-2 seconds from when an 8-byte UART packet is transmitted to when a blocking read returns. The packets are 1 second part with a few milliseconds of jitter. I also measured timing to the system calls (see below) using strace and the results agreed with my I/O measurements.

I'm trying to determine if this latency is in the UART driver or if other tasks are bumping my task which has a niceness value of -20. The reason I'm wondering about the driver is that an earlier version of this code reliably used the UART to transmit packets that were ~26 kB each second (the driver buffer is 4 kB).

The process is a Python script that is using pyserial. In this failing case strace reports the time between epoll_wait and clock_gettime as more than 3 seconds.

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

The repeated actions are: Receive 8-byte packet to request Linux to read N number of bytes via SPI. Perform the SPI. Read 8-byte packet to see if the SPI request completed successfully. The SPI transfer takes about 40 ms. The healthy pattern is ~40 ms between request packet and result packet. And ~960 ms until it receives the next request.

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]

what sort of blocking read? is it trying to grab a full line, or a particular number of bytes before returning? — thrig, Jan 24 '18 at 21:04
@thrig I've tried a couple of different ways with the same result. One was to do a blocking read on 8 bytes. Another was to do a read with a 100 ms timeout looping until a full 8 bytes arrived. — Kenny, Jan 25 '18 at 01:20
@ilkkachu In the `strace` output 3.004 seconds have elapsed between calls to `epoll_wait` and `clock_gettime`. I'll agree that this is not definitive and I'll add some other information to clear that up. I also toggled an IO before and after the blocking read and looked at that relative to when the UART packet shows up on an oscilloscope. — Kenny, Jan 25 '18 at 01:27
Note that vanilla Linux isn't a realtime system; it's just not deterministic enough. If you've got strong RT requirements you should either use a RT-enabled kernel, or a RTOS altogether. — Murphy, Jan 25 '18 at 09:54
@Murphy Understood. I have an RTOS running on the other processor. I've considered an RT build of the kernel but I'm concerned about the amount of testing this would trigger. I can tolerate some dropped frames. 1-2 seconds of latency for a high-priority process seemed excessive. Wondering if this is a driver bug or scheduling issue. — Kenny, Jan 25 '18 at 17:36
Are you using epoll() in edge triggered mode (EPOLLET)? If the uart driver not a standard Linux one you might try setting via pyserial the equivalent of VMIN and VTIME as described in termios(3) for C. — meuh, Jan 25 '18 at 18:22

score 2 · Accepted Answer · answered Jan 26 '18 at 20:31

strace is not likely to give you the necessary level of detail; you will probably need SystemTap, sysdig, or similar kernel-level debugging to better show when what is happening. For example with SystemTap installed and all the necessary debuginfo and setup details taken care of one could start with:

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);
}

and run that via

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

which for a serial test program and an attached Arduino for me shows:

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
...

You may also need to consult the SystemTap tapsets documentation for other probe points of interest (scheduler, I/O scheduler, IRQs?) if the above does not show where the delay is. And possibly to compare timings against the old version of the code/driver/system...

Thanks so much for this detailed answer. In my profiling above I only know that more than 2 seconds elapsed between the entry of calls to read() but not how long it spent in those calls. — Kenny, Jan 27 '18 at 02:10
Will this help me with scheduling latency though? If I find that `epoll_wait` did indeed take more than 1 second I'll still need to learn something about why it took the scheduler so long to get back to it. — Kenny, Jan 27 '18 at 02:13
@Kenny not directly, but the timing may indicate what is being slow and help avoid chasing red herrings — thrig, Jan 31 '18 at 20:58

How can I determine if a latency is due to a driver or the scheduler?

1 Answers1