This is v5 of the serial fifo patch. In relation to the previous
reverted patch, I describe the main changes in the "What changed from
v3" section.
What changed from v4
--------------------
* It squashes all the patches in a single patch
* It adds `port-state &&` check in the `use_fifo` condition as a
* preventive measure.
What changed from v3
--------------------
* Reads the FCR value from the port struct. The earlier patch
erroneously read the value from the controller, but FCR is a write-only
register. Thanks to Jiri Slaby for point this out.
* Use tx_loadsz as the transmitter fifo size. We previously used the
port->fifosize field, which caused data loss in some controllers. Thanks
Jon Hunter for the bug report.
* Exclude the BCM283x from fifo write. This is based on Phil Elwell's
original patch [1].
* Check if the port is initialized before write through fifo.
The serial driver set the value of uart_8250_port.fcr in the function
serial8250_config_port, but only writes the value to the controller
register later in the initalization code. That opens a small window in
which is not safe to use the fifo for console write. Unfortunately, I
lost track of who originally reported the issue. If s/he is reading
this, please speak up so I can give you the due credit.
[1] https://lore.kernel.org/all/[email protected]/
Wander Lairson Costa (1):
serial/8250: Use fifo in 8250 console driver
drivers/tty/serial/8250/8250_port.c | 68 ++++++++++++++++++++++++++---
1 file changed, 62 insertions(+), 6 deletions(-)
--
2.35.1
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 <[email protected]>
---
drivers/tty/serial/8250/8250_port.c | 68 ++++++++++++++++++++++++++---
1 file changed, 62 insertions(+), 6 deletions(-)
diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
index 318af6f13605..8f7eba5e71cf 100644
--- a/drivers/tty/serial/8250/8250_port.c
+++ b/drivers/tty/serial/8250/8250_port.c
@@ -2077,10 +2077,7 @@ static void serial8250_break_ctl(struct uart_port *port, int break_state)
serial8250_rpm_put(up);
}
-/*
- * Wait for transmitter & holding register to empty
- */
-static void wait_for_xmitr(struct uart_8250_port *up, int bits)
+static void wait_for_lsr(struct uart_8250_port *up, int bits)
{
unsigned int status, tmout = 10000;
@@ -2097,6 +2094,16 @@ static void wait_for_xmitr(struct uart_8250_port *up, int bits)
udelay(1);
touch_nmi_watchdog();
}
+}
+
+/*
+ * Wait for transmitter & holding register to empty
+ */
+static void wait_for_xmitr(struct uart_8250_port *up, int bits)
+{
+ unsigned int tmout;
+
+ wait_for_lsr(up, bits);
/* Wait up to 1s for flow control if necessary */
if (up->port.flags & UPF_CONS_FLOW) {
@@ -3332,6 +3339,35 @@ static void serial8250_console_restore(struct uart_8250_port *up)
serial8250_out_MCR(up, UART_MCR_DTR | UART_MCR_RTS);
}
+/*
+ * Print a string to the serial port using the device FIFO
+ *
+ * It sends fifosize bytes and then waits for the fifo
+ * to get empty.
+ */
+static void serial8250_console_fifo_write(struct uart_8250_port *up,
+ const char *s, unsigned int count)
+{
+ int i;
+ const char *end = s + count;
+ unsigned int fifosize = up->tx_loadsz;
+ bool cr_sent = false;
+
+ while (s != end) {
+ wait_for_lsr(up, UART_LSR_THRE);
+
+ for (i = 0; i < fifosize && s != end; ++i) {
+ if (*s == '\n' && !cr_sent) {
+ serial_out(up, UART_TX, '\r');
+ cr_sent = true;
+ } else {
+ serial_out(up, UART_TX, *s++);
+ cr_sent = false;
+ }
+ }
+ }
+}
+
/*
* Print a string to the serial port trying not to disturb
* any possible real use of the port...
@@ -3347,7 +3383,7 @@ void serial8250_console_write(struct uart_8250_port *up, const char *s,
struct uart_8250_em485 *em485 = up->em485;
struct uart_port *port = &up->port;
unsigned long flags;
- unsigned int ier;
+ unsigned int ier, use_fifo;
int locked = 1;
touch_nmi_watchdog();
@@ -3379,7 +3415,27 @@ void serial8250_console_write(struct uart_8250_port *up, const char *s,
mdelay(port->rs485.delay_rts_before_send);
}
- uart_console_write(port, s, count, serial8250_console_putchar);
+ use_fifo = (up->capabilities & UART_CAP_FIFO) &&
+ /*
+ * BCM283x requires to check the fifo
+ * after each byte.
+ */
+ !(up->capabilities & UART_CAP_MINI) &&
+ up->tx_loadsz > 1 &&
+ (up->fcr & UART_FCR_ENABLE_FIFO) &&
+ port-state &&
+ test_bit(TTY_PORT_INITIALIZED, &port->state->port.iflags) &&
+ /*
+ * After we put a data in the fifo, the controller will send
+ * it regardless of the CTS state. Therefore, only use fifo
+ * if we don't use control flow.
+ */
+ !(up->port.flags & UPF_CONS_FLOW);
+
+ if (likely(use_fifo))
+ serial8250_console_fifo_write(up, s, count);
+ else
+ uart_console_write(port, s, count, serial8250_console_putchar);
/*
* Finally, wait for transmitter to become empty
--
2.35.1
On Fri, 1 Apr 2022 06:35:58 +0200
Jiri Slaby <[email protected]> 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 <[email protected]> wrote:
>
> On Fri, 1 Apr 2022 06:35:58 +0200
> Jiri Slaby <[email protected]> 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
>
On 31. 03. 22, 21:02, 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:
>
> $ 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 <[email protected]>
> ---
> drivers/tty/serial/8250/8250_port.c | 68 ++++++++++++++++++++++++++---
> 1 file changed, 62 insertions(+), 6 deletions(-)
>
> diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
> index 318af6f13605..8f7eba5e71cf 100644
> --- a/drivers/tty/serial/8250/8250_port.c
> +++ b/drivers/tty/serial/8250/8250_port.c
> @@ -2077,10 +2077,7 @@ static void serial8250_break_ctl(struct uart_port *port, int break_state)
> serial8250_rpm_put(up);
> }
>
> -/*
> - * Wait for transmitter & holding register to empty
> - */
> -static void wait_for_xmitr(struct uart_8250_port *up, int bits)
> +static void wait_for_lsr(struct uart_8250_port *up, int bits)
> {
> unsigned int status, tmout = 10000;
>
> @@ -2097,6 +2094,16 @@ static void wait_for_xmitr(struct uart_8250_port *up, int bits)
> udelay(1);
> touch_nmi_watchdog();
> }
> +}
> +
> +/*
> + * Wait for transmitter & holding register to empty
> + */
> +static void wait_for_xmitr(struct uart_8250_port *up, int bits)
> +{
> + unsigned int tmout;
> +
> + wait_for_lsr(up, bits);
>
> /* Wait up to 1s for flow control if necessary */
> if (up->port.flags & UPF_CONS_FLOW) {
> @@ -3332,6 +3339,35 @@ static void serial8250_console_restore(struct uart_8250_port *up)
> serial8250_out_MCR(up, UART_MCR_DTR | UART_MCR_RTS);
> }
>
> +/*
> + * Print a string to the serial port using the device FIFO
> + *
> + * It sends fifosize bytes and then waits for the fifo
> + * to get empty.
> + */
> +static void serial8250_console_fifo_write(struct uart_8250_port *up,
> + const char *s, unsigned int count)
> +{
> + int i;
> + const char *end = s + count;
> + unsigned int fifosize = up->tx_loadsz;
> + bool cr_sent = false;
> +
> + while (s != end) {
> + wait_for_lsr(up, UART_LSR_THRE);
> +
> + for (i = 0; i < fifosize && s != end; ++i) {
> + if (*s == '\n' && !cr_sent) {
> + serial_out(up, UART_TX, '\r');
> + cr_sent = true;
> + } else {
> + serial_out(up, UART_TX, *s++);
> + cr_sent = false;
> + }
> + }
> + }
> +}
> +
> /*
> * Print a string to the serial port trying not to disturb
> * any possible real use of the port...
> @@ -3347,7 +3383,7 @@ void serial8250_console_write(struct uart_8250_port *up, const char *s,
> struct uart_8250_em485 *em485 = up->em485;
> struct uart_port *port = &up->port;
> unsigned long flags;
> - unsigned int ier;
> + unsigned int ier, use_fifo;
> int locked = 1;
>
> touch_nmi_watchdog();
> @@ -3379,7 +3415,27 @@ void serial8250_console_write(struct uart_8250_port *up, const char *s,
> mdelay(port->rs485.delay_rts_before_send);
> }
>
> - uart_console_write(port, s, count, serial8250_console_putchar);
> + use_fifo = (up->capabilities & UART_CAP_FIFO) &&
> + /*
> + * BCM283x requires to check the fifo
> + * after each byte.
> + */
> + !(up->capabilities & UART_CAP_MINI) &&
> + up->tx_loadsz > 1 &&
> + (up->fcr & UART_FCR_ENABLE_FIFO) &&
> + port-state &&
">" missing here. Doesn't a compiler warn about subtracting different types?
regards,
--
js
suse labs
On Fri, Apr 1, 2022 at 1:36 AM Jiri Slaby <[email protected]> wrote:
>
>
> ">" missing here. Doesn't a compiler warn about subtracting different types?
>
My local machine doesn't generate a warning; it causes a build error.
So my question was, how was I able to build and test yesterday in a
remote server? It turns out I built it with make -j40, so I missed the
error message because of the parallel build, and I didn't pay
attention that the output didn't display the modules_install typical
output. Usually, I do my tests in an RHEL9 machine, which ships with
kernel 5.14, but this time I tested in a Fedora machine, which ships
kernel 5.16. And for a moment, I forgot that. So when I booted with
kernel 5.16, I believed I was running my custom kernel. Luckily, v5
mainly was a squash of v4 with this port->state check added. Anyway,
sorry about the typo. v6 is on the way.