[v5,1/1] serial/8250: Use fifo in 8250 console driver

Note: I am using a small test app + driver located at [0] for the
problem description. serco is a driver whose write function dispatches
to the serial controller. sertest is a user-mode app that writes n bytes
to the serial console using the serco driver.

While investigating a bug in the RHEL kernel, I noticed that the serial
console throughput is way below the configured speed of 115200 bps in
a HP Proliant DL380 Gen9. I was expecting something above 10KB/s, but
I got 2.5KB/s.

$ time ./sertest -n 2500 /tmp/serco

real    0m0.997s
user    0m0.000s
sys     0m0.997s

With the help of the function tracer, I then noticed the serial
controller was taking around 410us seconds to dispatch one single byte:

$ trace-cmd record -p function_graph -g serial8250_console_write \
   ./sertest -n 1 /tmp/serco

$ trace-cmd report

            |  serial8250_console_write() {
 0.384 us   |    _raw_spin_lock_irqsave();
 1.836 us   |    io_serial_in();
 1.667 us   |    io_serial_out();
            |    uart_console_write() {
            |      serial8250_console_putchar() {
            |        wait_for_xmitr() {
 1.870 us   |          io_serial_in();
 2.238 us   |        }
 1.737 us   |        io_serial_out();
 4.318 us   |      }
 4.675 us   |    }
            |    wait_for_xmitr() {
 1.635 us   |      io_serial_in();
            |      __const_udelay() {
 1.125 us   |        delay_tsc();
 1.429 us   |      }
...
...
...
 1.683 us   |      io_serial_in();
            |      __const_udelay() {
 1.248 us   |        delay_tsc();
 1.486 us   |      }
 1.671 us   |      io_serial_in();
 411.342 us |    }

In another machine, I measured a throughput of 11.5KB/s, with the serial
controller taking between 80-90us to send each byte. That matches the
expected throughput for a configuration of 115200 bps.

This patch changes the serial8250_console_write to use the 16550 fifo
if available. In my benchmarks I got around 25% improvement in the slow
machine, and no performance penalty in the fast machine.

Signed-off-by: Wander Lairson Costa <wander@redhat.com>
---
 drivers/tty/serial/8250/8250_port.c | 68 ++++++++++++++++++++++++++---
 1 file changed, 62 insertions(+), 6 deletions(-)

On Fri, 1 Apr 2022 06:35:58 +0200
Jiri Slaby <jirislaby@kernel.org> wrote:

> > With the help of the function tracer, I then noticed the serial
> > controller was taking around 410us seconds to dispatch one single byte:
> > 
> > $ trace-cmd record -p function_graph -g serial8250_console_write \
> >     ./sertest -n 1 /tmp/serco
> > 
> > $ trace-cmd report
> > 

Note, the function graph tracer can add a noticeable amount of overhead to
these timings. If you want a more accurate time for a function, just trace
that one function:

	trace-cmd record -p function_graph -l serial8250_console_write ...

As that will only trace the serial8250_console_write() function (think of
-l as "limit"), and the overhead of function graph for tracing a single
function becomes negligible, and then you can see the true time of that
function.

-- Steve

On Fri, Apr 1, 2022 at 1:12 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Fri, 1 Apr 2022 06:35:58 +0200
> Jiri Slaby <jirislaby@kernel.org> wrote:
>
> > > With the help of the function tracer, I then noticed the serial
> > > controller was taking around 410us seconds to dispatch one single byte:
> > >
> > > $ trace-cmd record -p function_graph -g serial8250_console_write \
> > >     ./sertest -n 1 /tmp/serco
> > >
> > > $ trace-cmd report
> > >
>
> Note, the function graph tracer can add a noticeable amount of overhead to
> these timings. If you want a more accurate time for a function, just trace
> that one function:
>
>         trace-cmd record -p function_graph -l serial8250_console_write ...
>
> As that will only trace the serial8250_console_write() function (think of
> -l as "limit"), and the overhead of function graph for tracing a single
> function becomes negligible, and then you can see the true time of that
> function.
>

Thanks for the tip. I used bpftrace as a low overhead tracer. Then I
used the function-graph tracer to get the details.

> -- Steve
>