Re: Serial console and interrupts latency.

[Jiri Slaby <jslaby@suse.cz>]

On 24. 03. 20, 10:04, Sergey Organov wrote:
> Hello,
> 
> [Extended CC list to try to get some attention]
> 
> I was investigating random serial overruns on my embedded board and
> figured it strongly correlates with serial output (to another serial
> port) from kernel printk() calls, that forced me to dig into the kernel
> sources, and now I'm very confused.
> 
> I'm reading drivers/tty/serial/8250/8250_port.c, and
> serial8250_console_write() function in particular (being on tty-next
> branch).
> 
> What I see is that it locks interrupts
> 
> 3141:		spin_lock_irqsave(&port->lock, flags);
> 
> and then calls wait_for_xmitr() both indirectly here:
> 
> 3159:	uart_console_write(port, s, count, serial8250_console_putchar);
> 
> and then directly as well:
> 
> 3165:	wait_for_xmitr(up, BOTH_EMPTY);
> 
> before re-enabling interrupts at:
> 
> 3179:		spin_unlock_irqrestore(&port->lock, flags);
> 
> Now, wait_for_xmitr(), even according to comments, could busy-wait for
> up to 10+1000 milliseconds, and in this case this huge delay will happen
> at interrupts disabled?
> 
> Does it mean any serial console output out of printk() could cause 10
> milliseconds or even 1 second interrupts latency? Somehow I can't
> believe it.
> 
> What do I miss?

1 second _timeout_ is for flow-control-enabled consoles.

10 ms is _timeout_ for a character. With slow 9600 baud console, sending
one character takes 0.8 ms. With 115200, it is 70 us.

If you send one line (80 chars), it is really 66 and 5.5 ms, respectively.

So yes, serial consoles can slow down the boot and add latency. Use
faster speeds or faster devices for consoles, if you mind. And do not
enable flow control. Serial is serial.

You can also try to eliminate the interrupts disablement, but that would
be a bit tough task, IMO.

thanks,
-- 
js
suse labs