[PATCH] ARM: Adjust backtrace messages to line up with x86 kernel

[PATCH] ARM: Adjust backtrace messages to line up with x86 kernel

[Simon Glass]

It is nice to print the backtrace message on its own line, and also
regardless of the setting of CONFIG_ARM_UNWIND. This means that tools
which parse the backtrace don't need a special case for the first line.
It also makes it more like the x86 kernel output.

I believe we should also put KERN_EMERG at the start of this. Otherwise
it won't appear in console output (although it will appear in the logs
after a reboot).

The impact of this change is that the log output changes from something
like:

[    2.861692] 7fe0: 01beb1b8 befcb7d4 0000aebb 40284334 80000010 01be4668 00000000 00000000
[    2.869866] Backtrace: [<c00bb3f4>] (module_put+0x44/0xc0) from [<c00bdd98>] (sys_init_module+0x186c/0x19c4)
[    2.881144] [<c00bdd98>] (sys_init_module+0x186c/0x19c4) from [<c0052e00>] (ret_fast_syscall+0x0/0x30)

to:

[    2.861692] 7fe0: 01beb1b8 befcb7d4 0000aebb 40284334 80000010 01be4668 00000000 00000000
[    2.869866] Backtrace:
[    2.872248] [<c00bb3f4>] (module_put+0x44/0xc0) from [<c00bdd98>] (sys_init_module+0x186c/0x19c4)
[    2.881144] [<c00bdd98>] (sys_init_module+0x186c/0x19c4) from [<c0052e00>] (ret_fast_syscall+0x0/0x30)

(although previously the Backtrace: line didn't appear with CONFIG_ARM_UNWIND
defined)

Signed-off-by: Simon Glass <sjg@chromium.org>
---
 arch/arm/kernel/traps.c |    3 ++-
 1 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/arch/arm/kernel/traps.c b/arch/arm/kernel/traps.c
index 99a5727..78a5bbc 100644
--- a/arch/arm/kernel/traps.c
+++ b/arch/arm/kernel/traps.c
@@ -165,6 +165,7 @@ static void dump_instr(const char *lvl, struct pt_regs *regs)
 #ifdef CONFIG_ARM_UNWIND
 static inline void dump_backtrace(struct pt_regs *regs, struct task_struct *tsk)
 {
+	printk(KERN_EMERG "Backtrace:\n");
 	unwind_backtrace(regs, tsk);
 }
 #else
@@ -173,7 +174,7 @@ static void dump_backtrace(struct pt_regs *regs, struct task_struct *tsk)
 	unsigned int fp, mode;
 	int ok = 1;
 
-	printk("Backtrace: ");
+	printkK(ERN_EMERG "Backtrace:\n");
 
 	if (!tsk)
 		tsk = current;
-- 
1.7.7.3

Re: [PATCH] ARM: Adjust backtrace messages to line up with x86 kernel

[Russell King - ARM Linux]

On Tue, Jan 17, 2012 at 12:16:01PM -0800, Simon Glass wrote:
> It is nice to print the backtrace message on its own line, and also
> regardless of the setting of CONFIG_ARM_UNWIND. This means that tools
> which parse the backtrace don't need a special case for the first line.
> It also makes it more like the x86 kernel output.
> 
> I believe we should also put KERN_EMERG at the start of this. Otherwise
> it won't appear in console output (although it will appear in the logs
> after a reboot).
> 
> The impact of this change is that the log output changes from something
> like:
> 
> [    2.861692] 7fe0: 01beb1b8 befcb7d4 0000aebb 40284334 80000010 01be4668 00000000 00000000
> [    2.869866] Backtrace: [<c00bb3f4>] (module_put+0x44/0xc0) from [<c00bdd98>] (sys_init_module+0x186c/0x19c4)

You should not be getting it like this; I've never seen an oops dump
containing stuff formatted in this way on ARM.

If you care to look at the code, you'll notice that we have:

        printk("Backtrace: ");
...
	if () {
                printk("no frame pointer");
	} else if () {
                printk("invalid frame pointer 0x%08x", fp);
	} else if ()
                printk("frame pointer underflow");
	printk("\n");

	if (ok)
		c_backtrace();

So, by adding the '\n' at the end of the first printk, not only will you
add an additional blank line to the backtrace, but also move those
backtrace warning messages onto their own line, further pushing up the
number of lines an oops dump produces.

However, the lack of "Backtrace:" with ARM_UNWIND set needs fixing -
but please look at the unwind_backtrace() function first, and notice
that it contains its own version of this message (using __func__
instead - which is probably a bad idea.)  That needs fixing too.

Re: [PATCH] ARM: Adjust backtrace messages to line up with x86 kernel

[Simon Glass]

Hi Russell,

On Tue, Jan 17, 2012 at 12:24 PM, Russell King - ARM Linux
<linux@arm.linux.org.uk> wrote:
> On Tue, Jan 17, 2012 at 12:16:01PM -0800, Simon Glass wrote:
>> It is nice to print the backtrace message on its own line, and also
>> regardless of the setting of CONFIG_ARM_UNWIND. This means that tools
>> which parse the backtrace don't need a special case for the first line.
>> It also makes it more like the x86 kernel output.
>>
>> I believe we should also put KERN_EMERG at the start of this. Otherwise
>> it won't appear in console output (although it will appear in the logs
>> after a reboot).
>>
>> The impact of this change is that the log output changes from something
>> like:
>>
>> [    2.861692] 7fe0: 01beb1b8 befcb7d4 0000aebb 40284334 80000010 01be4668 00000000 00000000
>> [    2.869866] Backtrace: [<c00bb3f4>] (module_put+0x44/0xc0) from [<c00bdd98>] (sys_init_module+0x186c/0x19c4)
>
> You should not be getting it like this; I've never seen an oops dump
> containing stuff formatted in this way on ARM.
>
> If you care to look at the code, you'll notice that we have:
>
>        printk("Backtrace: ");
> ...
>        if () {
>                printk("no frame pointer");
>        } else if () {
>                printk("invalid frame pointer 0x%08x", fp);
>        } else if ()
>                printk("frame pointer underflow");
>        printk("\n");
>
>        if (ok)
>                c_backtrace();
>
> So, by adding the '\n' at the end of the first printk, not only will you
> add an additional blank line to the backtrace, but also move those
> backtrace warning messages onto their own line, further pushing up the
> number of lines an oops dump produces.
>
> However, the lack of "Backtrace:" with ARM_UNWIND set needs fixing -
> but please look at the unwind_backtrace() function first, and notice
> that it contains its own version of this message (using __func__
> instead - which is probably a bad idea.)  That needs fixing too.

Sorry my patch was so awful but I am pleased to get a response.

I will send a v2 - but keep the pr_debug() in unwind_backtrace() since
I don't see a reason to remove it. Because it is pr_debug() it
generally won't appear anyway I suppose.

Regards,
Simon

[PATCH v2] ARM: Adjust backtrace messages to line up with x86 kernel

[Simon Glass]

It is nice to print the backtrace message on its own line, and also
regardless of the setting of CONFIG_ARM_UNWIND. This means that tools
which parse the backtrace don't need a special case for the first line.
It also makes it more like the x86 kernel output.

I believe we should also put KERN_EMERG at the start of this. Otherwise
it won't appear in console output (although it will appear in the logs
after a reboot).

Signed-off-by: Simon Glass <sjg@chromium.org>
---
Changes in v2:
- Fix typo and remove \n from non CONFIG_ARM_UNWIND path
- Remove __func__ from the unwind_backtrace() function

 arch/arm/kernel/traps.c  |    3 ++-
 arch/arm/kernel/unwind.c |    2 +-
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/arch/arm/kernel/traps.c b/arch/arm/kernel/traps.c
index 99a5727..3d3cae2 100644
--- a/arch/arm/kernel/traps.c
+++ b/arch/arm/kernel/traps.c
@@ -165,6 +165,7 @@ static void dump_instr(const char *lvl, struct pt_regs *regs)
 #ifdef CONFIG_ARM_UNWIND
 static inline void dump_backtrace(struct pt_regs *regs, struct task_struct *tsk)
 {
+	printk(KERN_EMERG "Backtrace:\n");
 	unwind_backtrace(regs, tsk);
 }
 #else
@@ -173,7 +174,7 @@ static void dump_backtrace(struct pt_regs *regs, struct task_struct *tsk)
 	unsigned int fp, mode;
 	int ok = 1;
 
-	printk("Backtrace: ");
+	printk(KERN_EMERG "Backtrace: ");
 
 	if (!tsk)
 		tsk = current;
diff --git a/arch/arm/kernel/unwind.c b/arch/arm/kernel/unwind.c
index 00df012..451852a 100644
--- a/arch/arm/kernel/unwind.c
+++ b/arch/arm/kernel/unwind.c
@@ -410,7 +410,7 @@ void unwind_backtrace(struct pt_regs *regs, struct task_struct *tsk)
 	struct stackframe frame;
 	register unsigned long current_sp asm ("sp");
 
-	pr_debug("%s(regs = %p tsk = %p)\n", __func__, regs, tsk);
+	pr_debug("(regs = %p tsk = %p)\n", regs, tsk);
 
 	if (!tsk)
 		tsk = current;
-- 
1.7.7.3