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

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

Posted by David Sauerwein 1 month, 2 weeks ago

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

Posted by Catalin Marinas 1 month, 1 week ago

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

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

Posted by David Sauerwein 1 month, 1 week ago

On Wed, May 06, 2026 at 11:58:44AM +0100, Catalin Marinas wrote:
> 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).

I think the change is still needed in either case. Other threads can log
something unrelated to the stack traces which can still cause the
register lines to be broken. After all, use of pr_cont is discouraged.
checkpatch.pl warns saying "Avoid logging continuation uses where
feasible" when adding new callers of pr_cont.

I agree though that forcing stack traces to be printed sequentially
would help with readability. Maybe this can be added as a separate
change.

Thanks,
David

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

Posted by Will Deacon 4 weeks ago

On Thu, May 07, 2026 at 12:38:46PM +0000, David Sauerwein wrote:
> On Wed, May 06, 2026 at 11:58:44AM +0100, Catalin Marinas wrote:
> > 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).
> 
> I think the change is still needed in either case. Other threads can log
> something unrelated to the stack traces which can still cause the
> register lines to be broken. After all, use of pr_cont is discouraged.
> checkpatch.pl warns saying "Avoid logging continuation uses where
> feasible" when adding new callers of pr_cont.
> 
> I agree though that forcing stack traces to be printed sequentially
> would help with readability. Maybe this can be added as a separate
> change.

Presumably it would replace this patch?

Will