Re: Serial console and interrupts latency.

[Russell King - ARM Linux admin <linux@armlinux.org.uk>]

On Fri, Mar 27, 2020 at 02:13:12PM +0100, Jiri Slaby wrote:
> 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.

... and likely difficult to implement, since the spinlock is there to
prevent coincident usage from userspace and kernel space to the port.
If userspace is outputting a message in unison with a kernel console
message, there must be exclusivity, otherwise the two messages will
either be intermingled, or completely corrupted due to TX FIFO
overflow, making the console quite useless.

Higher latency is something that IMHO has to be accepted as a result
of using serial console.

As Jiri says, the way around that is to use as fast a baud rate as
possible on the serial console.

-- 
RMK's Patch system: https://www.armlinux.org.uk/developer/patches/
FTTC broadband for 0.8mile line in suburbia: sync at 10.2Mbps down 587kbps up