[PATCH] arm64: Fix garbled logs caused by race between multiple stack traces

[PATCH] arm64: Fix garbled logs caused by race between multiple stack traces

[David Sauerwein]

When multiple stack traces are printed at the same time, the lines that
contain register values may get split into multiple separate lines.
Some stray empty lines may appear as well.

[ 2013.814455] ------------[ cut here ]------------
[ 2013.814455] ------------[ cut here ]------------
[ 2013.814459] WARNING: CPU: 12 PID: 626 at src/arch/arm64/kvm/../../../virt/kvm/kvm_main.c:3860 mark_page_dirty_in_slot+0x5c/0xd8
[ 2013.814457] WARNING: CPU: 3 PID: 620 at src/arch/arm64/kvm/../../../virt/kvm/kvm_main.c:3860 mark_page_dirty_in_slot+0x5c/0xd8
[...]
[ 2013.814483] x29: ffff8000873b3b10
[ 2013.814484] x29: ffff800083fd3b10
[ 2013.814484]  x28: ffff00001d71e300 x27: 0000000000000001
[ 2013.814486] x26: ffff800080c63b80 x25: ffff800080c63000
[ 2013.814487]  x28: ffff00001d71a100 x27: 0000000000000001
[ 2013.814488]  x24: 0000000000401b14
[ 2013.814489]
[ 2013.814489] x26: ffff800080f5bb80 x25: ffff800080f5b000
[ 2013.814491]
[ 2013.814491] x23: ffff0000117b2000 x22: ffff00001e22bd88 x21: 0000ff9cc1b14000
[ 2013.814493]  x24: 0000000000402230
[ 2013.814494]
[ 2013.814495] x20: ffff800080c63000
[ 2013.814495] x23: ffff00001d916f00
[ 2013.814496]  x19: 0000000000000000 x18: ffff8000808c1660
[ 2013.814497] x17: 0000000000000000
[...]

(Example observed on v6.6 based kernel)

This happens because __show_regs uses pr_cont. The two threads printing
the traces race when printing partial register lines.

While the lines of the stack traces may still interleave, the individual
lines printing up to 3 register values should not be split. To fix this,
buffer the output and print all registers in a single printk instead of
using pr_cont.

Assisted-by: Kiro:claude-opus-4.6
Signed-off-by: David Sauerwein <dssauerw@amazon.de>
---
 arch/arm64/kernel/process.c | 16 +++++++++++++---
 1 file changed, 13 insertions(+), 3 deletions(-)

diff --git a/arch/arm64/kernel/process.c b/arch/arm64/kernel/process.c
index 033643cd4e5ed..27779539e3b4f 100644
--- a/arch/arm64/kernel/process.c
+++ b/arch/arm64/kernel/process.c
@@ -235,12 +235,22 @@ void __show_regs(struct pt_regs *regs)
 	i = top_reg;
 
 	while (i >= 0) {
-		printk("x%-2d: %016llx", i, regs->regs[i]);
+		/*
+		 * Buffer is big enough to hold the output for 3 register
+		 * plus some extra.
+		 */
+		char buf[80];
+		int len;
+
+		len = scnprintf(buf, sizeof(buf), "x%-2d: %016llx",
+				i, regs->regs[i]);
 
 		while (i-- % 3)
-			pr_cont(" x%-2d: %016llx", i, regs->regs[i]);
+			len += scnprintf(buf + len, sizeof(buf) - len,
+					 " x%-2d: %016llx",
+					 i, regs->regs[i]);
 
-		pr_cont("\n");
+		printk("%s\n", buf);
 	}
 }
 
-- 
2.47.3




Amazon Web Services Development Center Germany GmbH
Tamara-Danz-Str. 13
10243 Berlin
Geschaeftsfuehrung: Christof Hellmis, Andreas Stieger
Eingetragen am Amtsgericht Charlottenburg unter HRB 257764 B
Sitz: Berlin
Ust-ID: DE 365 538 597

Re: [PATCH] arm64: Fix garbled logs caused by race between multiple stack traces

[Catalin Marinas]

On Thu, Apr 30, 2026 at 08:47:38AM +0000, David Sauerwein wrote:
> When multiple stack traces are printed at the same time, the lines that
> contain register values may get split into multiple separate lines.
> Some stray empty lines may appear as well.
> 
> [ 2013.814455] ------------[ cut here ]------------
> [ 2013.814455] ------------[ cut here ]------------
> [ 2013.814459] WARNING: CPU: 12 PID: 626 at src/arch/arm64/kvm/../../../virt/kvm/kvm_main.c:3860 mark_page_dirty_in_slot+0x5c/0xd8
> [ 2013.814457] WARNING: CPU: 3 PID: 620 at src/arch/arm64/kvm/../../../virt/kvm/kvm_main.c:3860 mark_page_dirty_in_slot+0x5c/0xd8
> [...]
> [ 2013.814483] x29: ffff8000873b3b10
> [ 2013.814484] x29: ffff800083fd3b10
> [ 2013.814484]  x28: ffff00001d71e300 x27: 0000000000000001
> [ 2013.814486] x26: ffff800080c63b80 x25: ffff800080c63000
> [ 2013.814487]  x28: ffff00001d71a100 x27: 0000000000000001
> [ 2013.814488]  x24: 0000000000401b14
> [ 2013.814489]
> [ 2013.814489] x26: ffff800080f5bb80 x25: ffff800080f5b000
> [ 2013.814491]
> [ 2013.814491] x23: ffff0000117b2000 x22: ffff00001e22bd88 x21: 0000ff9cc1b14000
> [ 2013.814493]  x24: 0000000000402230
> [ 2013.814494]
> [ 2013.814495] x20: ffff800080c63000
> [ 2013.814495] x23: ffff00001d916f00
> [ 2013.814496]  x19: 0000000000000000 x18: ffff8000808c1660
> [ 2013.814497] x17: 0000000000000000
> [...]
[...]
> @@ -235,12 +235,22 @@ void __show_regs(struct pt_regs *regs)
>  	i = top_reg;
>  
>  	while (i >= 0) {
> -		printk("x%-2d: %016llx", i, regs->regs[i]);
> +		/*
> +		 * Buffer is big enough to hold the output for 3 register
> +		 * plus some extra.
> +		 */
> +		char buf[80];
> +		int len;
> +
> +		len = scnprintf(buf, sizeof(buf), "x%-2d: %016llx",
> +				i, regs->regs[i]);
>  
>  		while (i-- % 3)
> -			pr_cont(" x%-2d: %016llx", i, regs->regs[i]);
> +			len += scnprintf(buf + len, sizeof(buf) - len,
> +					 " x%-2d: %016llx",
> +					 i, regs->regs[i]);
>  
> -		pr_cont("\n");
> +		printk("%s\n", buf);

While the above does solve the line splitting, the trace is still not
that readable as we get line interleaving.

I wonder whether we could do something like dump_stack_lvl() at the
show_regs() level to synchronise the printing. If that works, we
wouldn't need the above change (which isn't incorrect but maybe we can
do better).

Thanks.

-- 
Catalin