printk: console output corrupted

printk: console output corrupted

[André Pribil]

Hi,

I'm using a IMX8MP board with kernel 5.10.165-rt81. UART3 is used as the console device.
When the device boots the serial outputs on this UART get corrupted at some point.
It looks like only one line is corrupted. However, this line often confuses my terminal, so that
the lines behind are also not shown correctly. A reset of the terminal fixes that.

I could not figure out why this happens, yet. I only know that the issue does not occur
when I remove the preempt-rt patch or when I specify the "maxcpus=1" kernel command 
line parameter. I also tried to enable/disable the "earlycon" setting, but this seem to only 
change the time when this happens during the boot messages. 

When the boot messages are afterwards displayed with "dmesg", they do not contain
corrupted characters. Therefore, I assume that the corruption occurs at the UART level.
Maybe some lock issue and therefore some concurrent access to the UART registers?

I don't know how to further trace this. Any help is appreciated.

Thanks,
Andre

Re: printk: console output corrupted

[John Ogness]

Hi Andre,

On 2023-02-21, André Pribil <Andre.Pribil@hms-networks.com> wrote:
> I'm using a IMX8MP board with kernel 5.10.165-rt81. UART3 is used as
> the console device.  When the device boots the serial outputs on this
> UART get corrupted at some point.  It looks like only one line is
> corrupted. However, this line often confuses my terminal, so that the
> lines behind are also not shown correctly. A reset of the terminal
> fixes that.
>
> I could not figure out why this happens, yet. I only know that the
> issue does not occur when I remove the preempt-rt patch or when I
> specify the "maxcpus=1" kernel command line parameter. I also tried to
> enable/disable the "earlycon" setting, but this seem to only change
> the time when this happens during the boot messages.
>
> When the boot messages are afterwards displayed with "dmesg", they do
> not contain corrupted characters. Therefore, I assume that the
> corruption occurs at the UART level.  Maybe some lock issue and
> therefore some concurrent access to the UART registers?

There is a known problem [0] with this printk implementation that it
does not support boot consoles. I will follow-up this email with the
rebased patch from Petr Mladek, which should work around the
issue. Please check if it works for you.

John Ogness

[0] https://lore.kernel.org/lkml/YrCO04oNncE1xF5K@alley

[PATCH] printk/console: Enable console kthreads only when there is no boot console left

[John Ogness]

The console kthreads uncovered several races in console drivers.
All problems were in situation when a console was being properly
initialized and registered while an early console, using the same
port, was being used.

These problems are pretty hard to debug because they often result
into silent boot crashes. It would be nice to fix them but it
looks like a can of worms.

Prevent these problems by delaying the use of console kthreads
after all early consoles are gone. It might later be optimized.
But let's close this can of worms with a big hammer for now
so that they do not break first impression on the kthreads
that solve other real problems.

Link: https://lore.kernel.org/r/20220619204949.50d9154d@thinkpad
Link: https://lore.kernel.org/r/2a82eae7-a256-f70c-fd82-4e510750906e@samsung.com
Reported-by: Marek Behún <kabel@kernel.org>
Signed-off-by: Petr Mladek <pmladek@suse.com>
Tested-by: Marek Behún <kabel@kernel.org>
[ rebased for 5.10.165-rt81 by john.ogness ]
---
 kernel/printk/printk.c | 31 ++++++++++++++++++++++++++-----
 1 file changed, 26 insertions(+), 5 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index d2205872304d..db095bd0f17c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2986,6 +2986,21 @@ void __init console_init(void)
 	}
 }
 
+#ifdef CONFIG_PRINTK
+static int __init printk_activate_kthreads(void)
+{
+	struct console *con;
+
+	console_lock();
+	for_each_console(con)
+		printk_start_kthread(con);
+	kthreads_started = true;
+	console_unlock();
+
+	return 0;
+}
+#endif
+
 /*
  * Some boot consoles access data that is in the init section and which will
  * be discarded after the initcalls have been run. To make sure that no code
@@ -3002,6 +3017,7 @@ void __init console_init(void)
  */
 static int __init printk_late_init(void)
 {
+	bool no_bootcon = true;
 	struct console *con;
 	int ret;
 
@@ -3023,15 +3039,20 @@ static int __init printk_late_init(void)
 			pr_warn("bootconsole [%s%d] uses init memory and must be disabled even before the real one is ready\n",
 				con->name, con->index);
 			unregister_console(con);
+			continue;
 		}
+
+		no_bootcon = false;
 	}
 
 #ifdef CONFIG_PRINTK
-	console_lock();
-	for_each_console(con)
-		start_printk_kthread(con);
-	kthreads_started = true;
-	console_unlock();
+	/*
+	 * Some console drivers are not ready to use the same port with
+	 * boot (early) and normal console in parallel. Stay on the safe
+	 * side and enable kthreads only when there is no boot console.
+	 */
+	if (no_bootcon)
+		printk_activate_kthreads();
 #endif
 
 	ret = cpuhp_setup_state_nocalls(CPUHP_PRINTK_DEAD, "printk:dead", NULL,
-- 
2.30.2

RE: [PATCH] printk/console: Enable console kthreads only when there is no boot console left

[André Pribil]

Hi John,

On 2023-02-21, John Ogness <john.ogness@linutronix.de> wrote:
> The console kthreads uncovered several races in console drivers.
> All problems were in situation when a console was being properly
> initialized and registered while an early console, using the same
> port, was being used.
>
> These problems are pretty hard to debug because they often result
> into silent boot crashes. It would be nice to fix them but it
> looks like a can of worms.
>
> Prevent these problems by delaying the use of console kthreads
> after all early consoles are gone. It might later be optimized.
> But let's close this can of worms with a big hammer for now
> so that they do not break first impression on the kthreads
> that solve other real problems.

Thanks a lot for the patch.
I needed to change a line in the patch to make it compile.
Renamed the call to printk_start_kthread to start_printk_kthread.
However, unfortunately this patch does not fix the problem for me.
I still see the garbage characters when booting.

Andre

RE: [PATCH] printk/console: Enable console kthreads only when there is no boot console left

[André Pribil]

Hi John,

here is some further information about the issue. 

Not sure if this is just a coincidence, but I found the following workaround for me:
I had a "stdout-path = &uart3;" setting in the device-tree and a "console=ttymxc2,115200" 
kernel command line parameter at the same time. If I remove the "console" command line
parameter, then I don't see this corruption anymore. 

Andre