Re: [PATCH v3 1/1] tty: serial: Use fifo in 8250 console driver

[Sebastian Andrzej Siewior]

On 2021-12-22 08:28:30 [-0300], Wander Lairson Costa wrote:
> 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:

was this the HW access or did this include the wait-for-fifo empty?

> $ 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 |    }

So this includes waiting for empty slot. It is wait_for_xmitr() only.

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

Either the HW is slow on starting to work, or…

What I noticed now in -rc1 is this output during boot:

|[    6.370196] ACPI: button: Power Button [PWRF]
|[    6.443501] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
|[0I 15
|      [0I 15
|            [No
|               [ld
|                  [a2
|                     [a20tm
|                           [a2nct
|                                 [s
|[s
|[s
|[s
…
|[sk65,
|      [rt
|         [Pe
|            [a
|               [    6.873611] ata1: SATA link down (SStatus 0 SControl 300)
|[    6.879680] ata3: SATA link down (SStatus 0 SControl 300)

The kernel buffer reports here:

|[    6.370196] ACPI: button: Power Button [PWRF]
|[    6.443501] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
|[    6.450643] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
|[    6.451625] 00:04: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
|[    6.453808] Non-volatile memory driver v1.3
|[    6.475688] loop: module loaded
|[    6.476401] ahci 0000:00:1f.2: version 3.0
|[    6.487238] ahci 0000:00:1f.2: AHCI 0001.0300 32 slots 6 ports 6 Gbps 0x3f impl SATA mode

I did remove the last few lines but it appears that since the
initialisation of the port some of the lines got lost.

Do you see the same?

> Signed-off-by: Wander Lairson Costa <wander@xxxxxxxxxx>

Sebastian