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
  • How do you measure when the read returns? – ilkkachu Jan 24 '18 at 21:12
  • @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 1: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 1:27
  • 1
    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

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 2: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 2: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

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.