Hi Sergey,
Am 27.03.23 um 17:11 schrieb Sergey Organov:
Stefan Wahren <stefan.wahren@xxxxxxxx> writes:
Hi,
Am 25.03.23 um 16:11 schrieb Uwe Kleine-König:
[...]
today i had time to do some testing. At first i tested with different RXTL_DEFAULT values.
1 No overrun
2 No overrun
4 No overrun
8 Overruns
After that i look at the # echo 0 > /proc/sys/kernel/printk approach,
but this didn't change anything. The kernel is usually silent about
log message after boot and the console works still with echo.
Enforcing some driver to call printk periodically would make the
console unusuable.
As you figured that printk() is not the cause, it must be something else
that causes overruns, so there is no need to check printk case further.
Finally i tried to disabled the spin_lock in imx_uart_console_write:
diff --git a/drivers/tty/serial/imx.c b/drivers/tty/serial/imx.c
index f07c4f9ff13c..c342559ff1a2 100644
--- a/drivers/tty/serial/imx.c
+++ b/drivers/tty/serial/imx.c
@@ -2007,14 +2007,12 @@ imx_uart_console_write(struct console *co, const char *s, unsigned int count)
struct imx_port_ucrs old_ucr;
unsigned long flags;
unsigned int ucr1;
- int locked = 1;
+ int locked = 0;
if (sport->port.sysrq)
locked = 0;
else if (oops_in_progress)
locked = spin_trylock_irqsave(&sport->port.lock, flags);
- else
- spin_lock_irqsave(&sport->port.lock, flags);
/*
* First, save UCR1/2/3 and then disable interrupts
But the overruns still occured. Is this because the serial core
already helds a lock?
This probably isn't even called when there is no printk() output, as
user-space writes to /dev/console are rather performed through regular
generic code, AFAIK.
i had some time today to investigate this a little bit. I thought it
would be a good idea to use debugfs as a ugly quick hack:
diff --git a/drivers/tty/serial/imx.c b/drivers/tty/serial/imx.c
index b8c817d26b00..d5bde4754004 100644
--- a/drivers/tty/serial/imx.c
+++ b/drivers/tty/serial/imx.c
@@ -30,6 +30,7 @@
#include <linux/dma-mapping.h>
#include <asm/irq.h>
+#include <linux/debugfs.h>
#include <linux/dma/imx-dma.h>
#include "serial_mctrl_gpio.h"
@@ -237,8 +238,19 @@ struct imx_port {
enum imx_tx_state tx_state;
struct hrtimer trigger_start_tx;
struct hrtimer trigger_stop_tx;
+
+ struct dentry *debugfs_dir;
+
+ /* stats exposed through debugf */
+ s64 total_duration_us;
+ s64 rx_duration_us;
+ s64 tx_duration_us;
+ u32 received;
+ u32 send;
};
+static struct dentry *imx_debugfs_root;
+
struct imx_port_ucrs {
unsigned int ucr1;
unsigned int ucr2;
@@ -536,12 +548,15 @@ static void imx_uart_dma_tx(struct imx_port *sport);
static inline void imx_uart_transmit_buffer(struct imx_port *sport)
{
struct circ_buf *xmit = &sport->port.state->xmit;
+ u32 send = 0;
if (sport->port.x_char) {
/* Send next char */
imx_uart_writel(sport, sport->port.x_char, URTX0);
sport->port.icount.tx++;
sport->port.x_char = 0;
+ if (sport->send == 0)
+ sport->send = 1;
return;
}
@@ -576,8 +591,12 @@ static inline void imx_uart_transmit_buffer(struct
imx_port *sport)
imx_uart_writel(sport, xmit->buf[xmit->tail], URTX0);
xmit->tail = (xmit->tail + 1) & (UART_XMIT_SIZE - 1);
sport->port.icount.tx++;
+ send++;
}
+ if (send > sport->send)
+ sport->send = send;
+
if (uart_circ_chars_pending(xmit) < WAKEUP_CHARS)
uart_write_wakeup(&sport->port);
@@ -808,6 +827,7 @@ static irqreturn_t __imx_uart_rxint(int irq, void
*dev_id)
{
struct imx_port *sport = dev_id;
unsigned int rx, flg, ignored = 0;
+ u32 received = 0;
struct tty_port *port = &sport->port.state->port;
while (imx_uart_readl(sport, USR2) & USR2_RDR) {
@@ -815,6 +835,7 @@ static irqreturn_t __imx_uart_rxint(int irq, void
*dev_id)
flg = TTY_NORMAL;
sport->port.icount.rx++;
+ received++;
rx = imx_uart_readl(sport, URXD0);
@@ -868,6 +889,9 @@ static irqreturn_t __imx_uart_rxint(int irq, void
*dev_id)
out:
tty_flip_buffer_push(port);
+ if (received > sport->received)
+ sport->received = received;
+
return IRQ_HANDLED;
}
@@ -942,6 +966,8 @@ static irqreturn_t imx_uart_int(int irq, void *dev_id)
struct imx_port *sport = dev_id;
unsigned int usr1, usr2, ucr1, ucr2, ucr3, ucr4;
irqreturn_t ret = IRQ_NONE;
+ ktime_t total_start = ktime_get();
+ s64 total_duration_us, rx_duration_us, tx_duration_us;
spin_lock(&sport->port.lock);
@@ -978,14 +1004,24 @@ static irqreturn_t imx_uart_int(int irq, void
*dev_id)
usr2 &= ~USR2_ORE;
if (usr1 & (USR1_RRDY | USR1_AGTIM)) {
+ ktime_t rx_start = ktime_get();
imx_uart_writel(sport, USR1_AGTIM, USR1);
__imx_uart_rxint(irq, dev_id);
+ rx_duration_us = ktime_us_delta(ktime_get(), rx_start);
+ if (rx_duration_us > sport->rx_duration_us)
+ sport->rx_duration_us = rx_duration_us;
+
ret = IRQ_HANDLED;
}
if ((usr1 & USR1_TRDY) || (usr2 & USR2_TXDC)) {
+ ktime_t tx_start = ktime_get();
imx_uart_transmit_buffer(sport);
+ tx_duration_us = ktime_us_delta(ktime_get(), tx_start);
+ if (tx_duration_us > sport->tx_duration_us)
+ sport->tx_duration_us = tx_duration_us;
+
ret = IRQ_HANDLED;
}
@@ -1015,6 +1051,10 @@ static irqreturn_t imx_uart_int(int irq, void
*dev_id)
spin_unlock(&sport->port.lock);
+ total_duration_us = ktime_us_delta(ktime_get(), total_start);
+ if (total_duration_us > sport->total_duration_us)
+ sport->total_duration_us = total_duration_us;
+
return ret;
}
@@ -2233,6 +2273,26 @@ static const struct serial_rs485
imx_rs485_supported = {
#define RX_DMA_PERIODS 16
#define RX_DMA_PERIOD_LEN (PAGE_SIZE / 4)
+static int debugfs_stats_show(struct seq_file *s, void *unused)
+{
+ struct imx_port *sport = s->private;
+
+ seq_printf(s, "total_duration_us:\t%lld\n", sport->total_duration_us);
+ seq_printf(s, "rx_duration_us:\t%lld\n", sport->rx_duration_us);
+ seq_printf(s, "tx_duration_us:\t%lld\n", sport->tx_duration_us);
+ seq_printf(s, "received:\t\t%u\n", sport->received);
+ seq_printf(s, "send:\t\t%u\n", sport->send);
+ return 0;
+}
+DEFINE_SHOW_ATTRIBUTE(debugfs_stats);
+
+static void imx_init_debugfs(struct imx_port *sport, const char *device)
+{
+ sport->debugfs_dir = debugfs_create_dir(device, imx_debugfs_root);
+ debugfs_create_file("stats", 0444, sport->debugfs_dir, sport,
+ &debugfs_stats_fops);
+}
+
static int imx_uart_probe(struct platform_device *pdev)
{
struct device_node *np = pdev->dev.of_node;
@@ -2485,6 +2545,7 @@ static int imx_uart_probe(struct platform_device
*pdev)
imx_uart_ports[sport->port.line] = sport;
platform_set_drvdata(pdev, sport);
+ imx_init_debugfs(sport, dev_name(&pdev->dev));
return uart_add_one_port(&imx_uart_uart_driver, &sport->port);
}
@@ -2678,9 +2739,14 @@ static int __init imx_uart_init(void)
if (ret)
return ret;
+ imx_debugfs_root = debugfs_create_dir(
+ imx_uart_platform_driver.driver.name, NULL);
+
ret = platform_driver_register(&imx_uart_platform_driver);
- if (ret != 0)
+ if (ret != 0) {
+ debugfs_remove_recursive(imx_debugfs_root);
uart_unregister_driver(&imx_uart_uart_driver);
+ }
return ret;
}
@@ -2688,6 +2754,7 @@ static int __init imx_uart_init(void)
static void __exit imx_uart_exit(void)
{
platform_driver_unregister(&imx_uart_platform_driver);
+ debugfs_remove_recursive(imx_debugfs_root);
uart_unregister_driver(&imx_uart_uart_driver);
}
Using this i was able to better compare the behavior with RXTL_DEFAULT 1
(without overrun errors) and RXTL_DEFAULT 8 (with overrun errors) on my
i.MX6ULL test platform. After doing my usual test scenario (copy some
text lines to console) i got the following results:
RXTL_DEFAULT 1
21f0000.serial/stats:total_duration_us: 61
21f0000.serial/stats:rx_duration_us: 36
21f0000.serial/stats:tx_duration_us: 48
21f0000.serial/stats:received: 28
21f0000.serial/stats:send: 33
RXTL_DEFAULT 8
21f0000.serial/stats:total_duration_us: 78
21f0000.serial/stats:rx_duration_us: 46
21f0000.serial/stats:tx_duration_us: 47
21f0000.serial/stats:received: 33
21f0000.serial/stats:send: 33
So based on the maximum of received characters on RX interrupt, i
consider the root cause of this issue has already been there because the
amount is near to the maximum of the FIFO (32 chars). So finally
increasing RXTL_DEFAULT makes the situation even worse by adding enough
latency for overrun errors.
Best regards
Best regards,
-- Sergey Organov
