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
