[PATCH] x86_64 stack trace cleanup

[PATCH] x86_64 stack trace cleanup

[Andres Salomon]

[-- Attachment #1.1: Type: text/plain, Size: 2597 bytes --]

Hi,

This patch cleans up the clutter of x86_64 stack traces, making the
output closer to what i386 and sparc64 stack traces look like.  It uses
print_symbol instead of resolving the symbols manually, and prints one
frame per line instead of displaying multiple frames per line.  I left
the other stuff in the stack dump alone; this affects only the frame
list.

I know this has been brought up before
(http://www.uwsg.iu.edu/hypermail/linux/kernel/0602.0/2238.html,
although I noticed a slight problem w/ that patch, as __print_symbol
returns void); however, for people that don't spend all their time
looking at x86_64 backtraces, I think this consistency shouldn't be
scoffed at.  When you switch back and forth between different archs,
x86_64's backtrace is cluttered and confusing in comparison.

With this patch, traces end up looking as follows:

 getty         S ffff81001e7d1db8     0  3812      1          3814  3811
(NOTLB)
 ffff81001e7d1db8 0000000000000008 ffffffff80240323 0000000000001d93
        ffff81001f82a2d8 ffff81001f82a0c0 ffff81001f68b0c0
0000000000000000
        ffff81001fa841fc ffff81001e7d0000
 Call Trace:
  [<ffffffff80240323>] do_con_write+0x1853/0x1890
  [<ffffffff80164daa>] __pagevec_free+0x2a/0x40
  [<ffffffff802e0e55>] schedule_timeout+0x25/0xd0
  [<ffffffff80134868>] release_console_sem+0x1a8/0x220
  [<ffffffff8014b93c>] add_wait_queue+0x1c/0x60
  [<ffffffff8023441f>] read_chan+0x48f/0x6e2
  [<ffffffff8012e7e0>] default_wake_function+0x0/0x10
  [<ffffffff8022f292>] tty_read+0xa2/0x110
  [<ffffffff80185eff>] vfs_read+0xdf/0x1a0
  [<ffffffff80186b63>] sys_read+0x53/0x90
  [<ffffffff8010afee>] system_call+0x7e/0x83


The old-style trace:

 pdflush       D ffff810037a417a0 0  4293     11          4294  4292
(L-TLB)
 ffff810031fb3d68 0000000000000046 ffff8100107b1d78 0000000000000f60
        0000000000000160 ffff810037a419b8 ffff810037a417a0 f
fff810037a40300
        ffff810001707d80 ffffffff80146b79
 Call Trace:<ffffffff80146b79>{lock_timer_base+41}
<ffffffff8014785d>{__mod_timer+189}
        <ffffffff80154690>{keventd_create_kthread+0}
<ffffffff8030f96a>{schedule_timeout+154}
        <ffffffff80147110>{process_timeout+0}
<ffffffff8030e621>{__sched_text_start+49}
        <ffffffff801fd279>{blk_congestion_wait+153}
<ffffffff80154bc0>{autoremove_wake_function+0}
        <ffffffff801b4051>{writeback_inodes+177}
<ffffffff8016d2d5>{background_writeout+165}
        <ffffffff8016df40>{pdflush+0} <ffffffff8016e095>{pdflush+341}




Signed-off-by: Andres Salomon <dilinger@debian.org>

[-- Attachment #1.2: x86_64-stack-trace.patch --]
[-- Type: text/x-patch, Size: 3252 bytes --]

diff --git a/arch/x86_64/kernel/traps.c b/arch/x86_64/kernel/traps.c
index 28d50dc..7598107 100644
--- a/arch/x86_64/kernel/traps.c
+++ b/arch/x86_64/kernel/traps.c
@@ -17,6 +17,7 @@
 #include <linux/config.h>
 #include <linux/sched.h>
 #include <linux/kernel.h>
+#include <linux/kallsyms.h> 
 #include <linux/string.h>
 #include <linux/errno.h>
 #include <linux/ptrace.h>
@@ -106,30 +107,11 @@ static inline void preempt_conditional_c
 
 static int kstack_depth_to_print = 10;
 
-#ifdef CONFIG_KALLSYMS
-#include <linux/kallsyms.h> 
-int printk_address(unsigned long address)
+void printk_address(unsigned long address)
 { 
-	unsigned long offset = 0, symsize;
-	const char *symname;
-	char *modname;
-	char *delim = ":"; 
-	char namebuf[128];
-
-	symname = kallsyms_lookup(address, &symsize, &offset, &modname, namebuf); 
-	if (!symname) 
-		return printk("[<%016lx>]", address);
-	if (!modname) 
-		modname = delim = ""; 		
-        return printk("<%016lx>{%s%s%s%s%+ld}",
-		      address,delim,modname,delim,symname,offset); 
+	printk(" [<%016lx>] ", address);
+	print_symbol("%s\n", address);
 } 
-#else
-int printk_address(unsigned long address)
-{ 
-	return printk("[<%016lx>]", address);
-} 
-#endif
 
 static unsigned long *in_exception_stack(unsigned cpu, unsigned long stack,
 					unsigned *usedp, const char **idp)
@@ -205,24 +187,23 @@ void show_trace(unsigned long *stack)
 	printk("\nCall Trace:");
 
 #define HANDLE_STACK(cond) \
-	do while (cond) { \
-		unsigned long addr = *stack++; \
-		if (kernel_text_address(addr)) { \
-			if (i > 50) { \
-				printk("\n       "); \
-				i = 0; \
+	do { \
+		i = 0; \
+		printk("\n"); \
+		while (cond) { \
+			unsigned long addr = *stack++; \
+			if (kernel_text_address(addr)) { \
+				/* \
+				 * If the address is either in the text segment \
+				 * of the kernel, or in the region which \
+				 * contains vmalloc'ed memory, it *may* be the \
+				 * address of a calling routine; if so, print it \
+				 * so that someone tracing down the cause of the \
+				 * crash will be able to figure out the call \
+				 * path that was taken. \
+				 */ \
+				printk_address(addr); \
 			} \
-			else \
-				i += printk(" "); \
-			/* \
-			 * If the address is either in the text segment of the \
-			 * kernel, or in the region which contains vmalloc'ed \
-			 * memory, it *may* be the address of a calling \
-			 * routine; if so, print it so that someone tracing \
-			 * down the cause of the crash will be able to figure \
-			 * out the call path that was taken. \
-			 */ \
-			i += printk_address(addr); \
 		} \
 	} while (0)
 
diff --git a/include/asm-x86_64/kdebug.h b/include/asm-x86_64/kdebug.h
index b9ed4c0..72f5261 100644
--- a/include/asm-x86_64/kdebug.h
+++ b/include/asm-x86_64/kdebug.h
@@ -48,7 +48,7 @@ static inline int notify_die(enum die_va
 	return notifier_call_chain(&die_chain, val, &args); 
 } 
 
-extern int printk_address(unsigned long address);
+extern void printk_address(unsigned long address);
 extern void die(const char *,struct pt_regs *,long);
 extern void __die(const char *,struct pt_regs *,long);
 extern void show_registers(struct pt_regs *regs);

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 191 bytes --]

Re: [PATCH] x86_64 stack trace cleanup

[Andi Kleen]

On Friday 24 February 2006 11:41, Andres Salomon wrote:
> Hi,
> 
> This patch cleans up the clutter of x86_64 stack traces, making the
> output closer to what i386 and sparc64 stack traces look like.  It uses
> print_symbol instead of resolving the symbols manually, and prints one
> frame per line instead of displaying multiple frames per line.  I left
> the other stuff in the stack dump alone; this affects only the frame
> list.
> 
> I know this has been brought up before
> (http://www.uwsg.iu.edu/hypermail/linux/kernel/0602.0/2238.html,
> although I noticed a slight problem w/ that patch, as __print_symbol
> returns void); however, for people that don't spend all their time
> looking at x86_64 backtraces, I think this consistency shouldn't be
> scoffed at.  When you switch back and forth between different archs,
> x86_64's backtrace is cluttered and confusing in comparison.

If the formatting of the oopses is  your only problem you are a 
lucky man.

The problem is your new format uses more screen estate, which is precious
after an oops because the VGA scrollback is so small.
That is why i rejected the earlier attempts at changing this.

I can offer you a deal though: if you fix VGA scrollback to have
at least 1000 lines by default we can change the oops formatting too.

-Andi

Re: [PATCH] x86_64 stack trace cleanup

[Andres Salomon]

[-- Attachment #1: Type: text/plain, Size: 2151 bytes --]

On Fri, 2006-02-24 at 11:47 +0100, Andi Kleen wrote:
> On Friday 24 February 2006 11:41, Andres Salomon wrote:
> > Hi,
> > 
> > This patch cleans up the clutter of x86_64 stack traces, making the
> > output closer to what i386 and sparc64 stack traces look like.  It uses
> > print_symbol instead of resolving the symbols manually, and prints one
> > frame per line instead of displaying multiple frames per line.  I left
> > the other stuff in the stack dump alone; this affects only the frame
> > list.
> > 
> > I know this has been brought up before
> > (http://www.uwsg.iu.edu/hypermail/linux/kernel/0602.0/2238.html,
> > although I noticed a slight problem w/ that patch, as __print_symbol
> > returns void); however, for people that don't spend all their time
> > looking at x86_64 backtraces, I think this consistency shouldn't be
> > scoffed at.  When you switch back and forth between different archs,
> > x86_64's backtrace is cluttered and confusing in comparison.
> 
> If the formatting of the oopses is  your only problem you are a 
> lucky man.
> 

That would be nice.  Unfortunately, I'm trying to figure out why my dual
opteron box likes to push the load up to 15 and then hang while doing
i/o to the 3ware 9500S-8 card.  Looks like the load/d-state processes
are caused by a whole lot (well, MAX_PDFLUSH_THREADS) of pdflush
processes spinning on base->lock in lock_timer_base(); not sure if
that's intentional or not, but it seems rather odd.  Whether the hanging
is related to the high load remains to be seen.


> The problem is your new format uses more screen estate, which is precious
> after an oops because the VGA scrollback is so small.
> That is why i rejected the earlier attempts at changing this.
> 

I don't see why this is a problem.  Other architectures have done this
for ages, without problems.  I suspect most people get their backtraces
from either serial console or logs, as copying them down from the screen
or taking a picture of the panic is a rather large pain.  It seems like
you're penalizing everyone for a few select use cases.

Of course, this is all opinion.

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 191 bytes --]

Re: [PATCH] x86_64 stack trace cleanup

[Andi Kleen]

On Friday 24 February 2006 12:29, Andres Salomon wrote:

> That would be nice.  Unfortunately, I'm trying to figure out why my dual
> opteron box likes to push the load up to 15 and then hang while doing
> i/o to the 3ware 9500S-8 card.  Looks like the load/d-state processes
> are caused by a whole lot (well, MAX_PDFLUSH_THREADS) of pdflush
> processes spinning on base->lock in lock_timer_base(); not sure if
> that's intentional or not, but it seems rather odd.  Whether the hanging
> is related to the high load remains to be seen.

Sounds like some timer handler is broken. You have to find out which
one it is.
 

> I don't see why this is a problem.  Other architectures have done this
> for ages, without problems.  I suspect most people get their backtraces
> from either serial console or logs, as copying them down from the screen
> or taking a picture of the panic is a rather large pain.  It seems like
> you're penalizing everyone for a few select use cases.

People submitting jpegs of photographed oopses or even badly scribbled
down oopses is quite common. Serial consoles are only used by a small
elite.

-Andi

Re: [PATCH] x86_64 stack trace cleanup

[Alistair John Strachan]

On Friday 24 February 2006 12:22, Andi Kleen wrote:
> On Friday 24 February 2006 12:29, Andres Salomon wrote:
> > That would be nice.  Unfortunately, I'm trying to figure out why my dual
> > opteron box likes to push the load up to 15 and then hang while doing
> > i/o to the 3ware 9500S-8 card.  Looks like the load/d-state processes
> > are caused by a whole lot (well, MAX_PDFLUSH_THREADS) of pdflush
> > processes spinning on base->lock in lock_timer_base(); not sure if
> > that's intentional or not, but it seems rather odd.  Whether the hanging
> > is related to the high load remains to be seen.
>
> Sounds like some timer handler is broken. You have to find out which
> one it is.
>
> > I don't see why this is a problem.  Other architectures have done this
> > for ages, without problems.  I suspect most people get their backtraces
> > from either serial console or logs, as copying them down from the screen
> > or taking a picture of the panic is a rather large pain.  It seems like
> > you're penalizing everyone for a few select use cases.
>
> People submitting jpegs of photographed oopses or even badly scribbled
> down oopses is quite common. Serial consoles are only used by a small
> elite.

I agree, I've had to report using a JPEG file on multiple occasions, because 
my mainboard has no serial ports. However, if you're using a 1280x1024 
vesafb, which is supported by most systems, you can get a lot of lines on 
screen at once..

-- 
Cheers,
Alistair.

'No sense being pessimistic, it probably wouldn't work anyway.'
Third year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.

Re: [PATCH] x86_64 stack trace cleanup

[Jesper Juhl]

On 2/24/06, Alistair John Strachan <s0348365@sms.ed.ac.uk> wrote:
> On Friday 24 February 2006 12:22, Andi Kleen wrote:
> > On Friday 24 February 2006 12:29, Andres Salomon wrote:
> > > That would be nice.  Unfortunately, I'm trying to figure out why my dual
> > > opteron box likes to push the load up to 15 and then hang while doing
> > > i/o to the 3ware 9500S-8 card.  Looks like the load/d-state processes
> > > are caused by a whole lot (well, MAX_PDFLUSH_THREADS) of pdflush
> > > processes spinning on base->lock in lock_timer_base(); not sure if
> > > that's intentional or not, but it seems rather odd.  Whether the hanging
> > > is related to the high load remains to be seen.
> >
> > Sounds like some timer handler is broken. You have to find out which
> > one it is.
> >
> > > I don't see why this is a problem.  Other architectures have done this
> > > for ages, without problems.  I suspect most people get their backtraces
> > > from either serial console or logs, as copying them down from the screen
> > > or taking a picture of the panic is a rather large pain.  It seems like
> > > you're penalizing everyone for a few select use cases.
> >
> > People submitting jpegs of photographed oopses or even badly scribbled
> > down oopses is quite common. Serial consoles are only used by a small
> > elite.
>
> I agree, I've had to report using a JPEG file on multiple occasions, because
> my mainboard has no serial ports. However, if you're using a 1280x1024
> vesafb, which is supported by most systems, you can get a lot of lines on
> screen at once..
>

true, but still, if you have two columns of output you get even more
lines on-screen (and in the cases where the oops os long that's IMHO a
good thing).

--
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: [PATCH] x86_64 stack trace cleanup

[Jesper Juhl]

On 2/24/06, Andres Salomon <dilinger@debian.org> wrote:
> On Fri, 2006-02-24 at 11:47 +0100, Andi Kleen wrote:
[snip]
>
> > The problem is your new format uses more screen estate, which is precious
> > after an oops because the VGA scrollback is so small.
> > That is why i rejected the earlier attempts at changing this.
> >
>
> I don't see why this is a problem.  Other architectures have done this
> for ages, without problems.  I suspect most people get their backtraces
> from either serial console or logs, as copying them down from the screen
> or taking a picture of the panic is a rather large pain.  It seems like
> you're penalizing everyone for a few select use cases.
>

Some of us don't have a digital camera for taking a picture (and
besides, being able to take a picture doesn't fix the problem of oops
output scrolling out of the visible screen area).
Some of us also don't have a second PC on which to capture logs via
netconsole or serial console.
Copying oopses down by hand from screen to paper sure is a pain (I
know, I've had to do it quite a few times), but for some it's the only
option and then we generally want as much info as possible on-screen
to copy down.

And btw, multi-column oops output has recently become an option for
i386 as well - in my oppinion a good thing.

--
Jesper Juhl <jesper.juhl@gmail.com>
Don't top-post  http://www.catb.org/~esr/jargon/html/T/top-post.html
Plain text mails only, please      http://www.expita.com/nomime.html

Re: [PATCH] x86_64 stack trace cleanup

[Andrew Morton]

Andi Kleen <ak@suse.de> wrote:
>
> I can offer you a deal though: if you fix VGA scrollback to have
>  at least 1000 lines by default we can change the oops formatting too.

ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.16-rc4/2.6.16-rc4-mm2/broken-out/vgacon-add-support-for-soft-scrollback.patch

Problem is, scrollback doesn't work after panic().  I don't know why..

Re: [PATCH] x86_64 stack trace cleanup

[Andi Kleen]

On Friday 24 February 2006 13:50, Andrew Morton wrote:
> Andi Kleen <ak@suse.de> wrote:
> >
> > I can offer you a deal though: if you fix VGA scrollback to have
> >  at least 1000 lines by default we can change the oops formatting too.
> 
> ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.16-rc4/2.6.16-rc4-mm2/broken-out/vgacon-add-support-for-soft-scrollback.patch

Once that is in and works we can consider changing the oopses.

> Problem is, scrollback doesn't work after panic().  I don't know why..

Someone claimed it was related to the panic keyboard blinking.  Never verified 
though. But without it working we still can't change the oops.

-Andi
 

Re: [PATCH] x86_64 stack trace cleanup

[Andrew Morton]

Andi Kleen <ak@suse.de> wrote:
>
> On Friday 24 February 2006 13:50, Andrew Morton wrote:
> > Andi Kleen <ak@suse.de> wrote:
> > >
> > > I can offer you a deal though: if you fix VGA scrollback to have
> > >  at least 1000 lines by default we can change the oops formatting too.
> > 
> > ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.16-rc4/2.6.16-rc4-mm2/broken-out/vgacon-add-support-for-soft-scrollback.patch
> 
> Once that is in and works we can consider changing the oopses.
>

I don't think we should change the oops format.

Apart from no longer printing a hex-base+decimal-offset, which is braindead.

> > Problem is, scrollback doesn't work after panic().  I don't know why..
> 
> Someone claimed it was related to the panic keyboard blinking.
>

Strange.  It looks pretty harmless.

Re: [PATCH] x86_64 stack trace cleanup

[Andi Kleen]

On Friday 24 February 2006 14:13, Andrew Morton wrote:


> 
> > > Problem is, scrollback doesn't work after panic().  I don't know why..
> > 
> > Someone claimed it was related to the panic keyboard blinking.
> >
> 
> Strange.  It looks pretty harmless.

[just speculation, haven't examined the code in detail]

One credible theory also was that the keyboard or console driver does too much
work in workqueues, which need the scheduler and scheduling doesn't work anymore
after panic. I remember hacking around a problem with this long ago on 2.4
The hack was to just check after_panic and call the function directly.

-Andi

Re: [PATCH] x86_64 stack trace cleanup

[Randy.Dunlap]

On Fri, 24 Feb 2006, Andrew Morton wrote:

> Andi Kleen <ak@suse.de> wrote:
> >
> > On Friday 24 February 2006 13:50, Andrew Morton wrote:
> > > Andi Kleen <ak@suse.de> wrote:
> > > >
> > > > I can offer you a deal though: if you fix VGA scrollback to have
> > > >  at least 1000 lines by default we can change the oops formatting too.
> > >
> > > ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.16-rc4/2.6.16-rc4-mm2/broken-out/vgacon-add-support-for-soft-scrollback.patch
> >
> > Once that is in and works we can consider changing the oopses.
> >
>
> I don't think we should change the oops format.
>
> Apart from no longer printing a hex-base+decimal-offset, which is braindead.

strongly agree with the hex/decimal braindead part.

> > > Problem is, scrollback doesn't work after panic().  I don't know why..
> >
> > Someone claimed it was related to the panic keyboard blinking.
> >
>
> Strange.  It looks pretty harmless.

-- 
~Randy