[RFC] Enhanced show_stack output to add backing store regs

[RFC] Enhanced show_stack output to add backing store regs

[Bob Montgomery]

I have a patch for arch/ia64/kernel/process.c that changes
ia64_do_show_stack to show the contents of the register backing store
for each level.  I think this will help our post-mortem debugging
of hard-to-reproduce problems, especially when customers do not have
a working kernel core dump facility, by allowing us to see function
argument registers and some of the locals for each function leading
to the oops.  Note: this doesn't capture function arguments per se,
since the argument register(s) could have been modified prior to the
call to the next stack level.  You still have to read disassembly to
debug this way :-)

Is this generally interesting?  I'm wondering if it isn't currently
done because of some issue with oops message size, or excessive
printk's causing problems elsewhere?

The current vs. proposed is shown below.  Thanks for any comments
and advice.

Bob Montgomery, HP


Current Call Trace from the buncho test module's RegNat test case.
The register dump part of the oops output isn't shown here, but
contains registers in the r1-r31 range at the time of the oops-causing
exception only.

Call Trace:
 [<a000000100012940>] show_stack+0x80/0xa0
                                spà000001200df960 bspà000001200d8fb8
 [<a0000001000131c0>] show_regs+0x800/0x820
                                spà000001200dfb30 bspà000001200d8f60
 [<a000000100036b50>] die+0x150/0x280
                                spà000001200dfb40 bspà000001200d8f20
 [<a000000100036cc0>] die_if_kernel+0x40/0x60
                                spà000001200dfb40 bspà000001200d8ef0
 [<a0000001000378d0>] ia64_fault+0x150/0xac0
                                spà000001200dfb40 bspà000001200d8ea8
 [<a00000010000ad20>] ia64_leave_kernel+0x0/0x260
                                spà000001200dfc40 bspà000001200d8ea8
 [<a0000002000689d0>] buncho_going_to_regnat+0x50/0xa0 [buncho]
                                spà000001200dfe10 bspà000001200d8e80
 [<a000000200068e10>] buncho_ioctl+0x390/0x420 [buncho]
                                spà000001200dfe20 bspà000001200d8e48
 [<a000000100156e60>] sys_ioctl+0x240/0x6c0
                                spà000001200dfe20 bspà000001200d8db8
 [<a00000010000aba0>] ia64_ret_from_syscall+0x0/0x20
                                spà000001200dfe30 bspà000001200d8db8
 
-------------------------------------------------------------------------

New Call Trace from the buncho test module's RegNat test case with
register backing store output.  '*" by a register name indicates
that the register has been identified as containing a NaT (e.g. r36
in buncho_going_to_regnat below).  This version hides the actual NaT
bits word stored in the backing store.

Call Trace:
 [<a000000100012940>] show_stack+0x80/0xa0
                                spà000001200df960 bspà000001200d8fb8
 [<a0000001000131c0>] show_regs+0x800/0x820
                                spà000001200dfb30 bspà000001200d8f60
    r32 : e0000001200dfc50 r33 : 0000000000000000 r34 : e0000001200dfd08
    r35 : e0000001200dfcc8 r36 : e0000001200dfce0 r37 : e0000001200dfca0
    r38 : e0000001200dfc90 r39 : 00000fffffffbfff r40 : a000000100036b50
    r41 : 000000000000040e r42 : e0000001a00dfbce
 [<a000000100036b50>] die+0x150/0x280
                                spà000001200dfb40 bspà000001200d8f20
    r32 : e0000001200dfbd0 r33 : e0000001200dfc50 r34 : 0000020200000010
    r35 : a00000010066a1b8 r36 : a00000010066a1bc r37 : a000000100036cc0
    r38 : 0000000000000309 r39 : a00000010056ebe8
 [<a000000100036cc0>] die_if_kernel+0x40/0x60
                                spà000001200dfb40 bspà000001200d8ef0
    r32 : e0000001200dfbd0 r33 : e0000001200dfc50 r34 : 0000020200000010
    r35 : a0000001000378d0 r36 : 000000000000048e r37 : a00000010067a1d0
 [<a0000001000378d0>] ia64_fault+0x150/0xac0
                                spà000001200dfb40 bspà000001200d8ea8
    r32 : 000000000000001a r33 : 0000020200000010 r34 : c0000000fee01000
    r35 : 0000000000030002 r36 : e0000001200dfc50 r37 : e0000001200dfbd0
    r38 : a00000010000ad20 r39 : 0000000000000005 r40 : e0000001200dfde0
 [<a00000010000ad20>] ia64_leave_kernel+0x0/0x260
                                spà000001200dfc40 bspà000001200d8ea8
 [<a0000002000689d0>] buncho_going_to_regnat+0x50/0xa0 [buncho]
                                spà000001200dfe10 bspà000001200d8e80
    r32 : a000000200068e10 r33 : 0000000000000389 r34 : a000000200268000
    r35 : e0000001200dfe20 r36 :*0000000000000000
 [<a000000200068e10>] buncho_ioctl+0x390/0x420 [buncho]
                                spà000001200dfe20 bspà000001200d8e48
    r32 : e0000001fc908460 r33 : e0000040fe75e700 r34 : 000000000000006e
    r35 : 0000000000000000 r36 : a000000100156e60 r37 : 0000000000000895
    r38 : a000000200268000
 [<a000000100156e60>] sys_ioctl+0x240/0x6c0
                                spà000001200dfe20 bspà000001200d8db8
    r32 : 0000000000000003 r33 : 000000000000006e r34 : 0000000000000000
    r35 : 0000000000000002 r36 : 60000fffffffb9d8 r37 : 4000000000002670
    r38 : 4000000000002660 r39 : 200000000003a558 r40 : 000000000000006e
    r41 : a000000200068a80 r42 : ffffffffffffffe7 r43 : e0000040fe75e700
    r44 : a00000020006b000 r45 : a00000010000aba0 r46 : 0000000000000008
    r47 : a000000100963810 r48 : 0000000000168359
 [<a00000010000aba0>] ia64_ret_from_syscall+0x0/0x20
                                spà000001200dfe30 bspà000001200d8db8
 

-- 
Bob Montgomery <bob.montgomery@hp.com>

RE: [RFC] Enhanced show_stack output to add backing store regs

[Chen, Kenneth W]

Bob Montgomery wrote on Friday, March 11, 2005 10:40 AM
>
> I have a patch for arch/ia64/kernel/process.c that changes
> ia64_do_show_stack to show the contents of the register backing store
> for each level.  I think this will help our post-mortem debugging
> of hard-to-reproduce problems, especially when customers do not have
> a working kernel core dump facility, by allowing us to see function
> argument registers and some of the locals for each function leading
> to the oops.  Note: this doesn't capture function arguments per se,
> since the argument register(s) could have been modified prior to the
> call to the next stack level.  You still have to read disassembly to
> debug this way :-)
>
> Is this generally interesting?  I'm wondering if it isn't currently
> done because of some issue with oops message size, or excessive
> printk's causing problems elsewhere?

Very nice and I think is extremely valuable for debugging, especially
the stack register dump.  I vote YES!!

- Ken

Re: [RFC] Enhanced show_stack output to add backing store regs

[Matthew Wilcox]

On Fri, Mar 11, 2005 at 11:40:04AM -0700, Bob Montgomery wrote:
> argument registers and some of the locals for each function leading
> to the oops.  Note: this doesn't capture function arguments per se,

I've been wanting this for a while.  I think it'd be *very* useful.

> The current vs. proposed is shown below.  Thanks for any comments
> and advice.

I know your patch leaaves this unchanged, but I don't think it's helpful
to show the 'show_stack' and 'show_regs' frames.  Can we get rid of them,
or is there a reason they're useful?

> Call Trace:
>  [<a000000100012940>] show_stack+0x80/0xa0
>                                 spà000001200df960 bspà000001200d8fb8
>  [<a0000001000131c0>] show_regs+0x800/0x820
>                                 spà000001200dfb30 bspà000001200d8f60
>     r32 : e0000001200dfc50 r33 : 0000000000000000 r34 : e0000001200dfd08
>     r35 : e0000001200dfcc8 r36 : e0000001200dfce0 r37 : e0000001200dfca0
>     r38 : e0000001200dfc90 r39 : 00000fffffffbfff r40 : a000000100036b50
>     r41 : 000000000000040e r42 : e0000001a00dfbce
>  [<a000000100036b50>] die+0x150/0x280
>                                 spà000001200dfb40 bspà000001200d8f20
>     r32 : e0000001200dfbd0 r33 : e0000001200dfc50 r34 : 0000020200000010
>     r35 : a00000010066a1b8 r36 : a00000010066a1bc r37 : a000000100036cc0
>     r38 : 0000000000000309 r39 : a00000010056ebe8

-- 
"Next the statesmen will invent cheap lies, putting the blame upon 
the nation that is attacked, and every man will be glad of those
conscience-soothing falsities, and will diligently study them, and refuse
to examine any refutations of them; and thus he will by and by convince 
himself that the war is just, and will thank God for the better sleep 
he enjoys after this process of grotesque self-deception." -- Mark Twain

Re: [RFC] Enhanced show_stack output to add backing store regs

[David Mosberger]

>>>>> On Fri, 11 Mar 2005 20:25:26 +0000, Matthew Wilcox <matthew@wil.cx> said:

  Matthew> I know your patch leaaves this unchanged, but I don't think it's helpful
  Matthew> to show the 'show_stack' and 'show_regs' frames.  Can we get rid of them,
  Matthew> or is there a reason they're useful?

There were useful in the early days, when I didn't trust the unwinder... ;-)
I agree that we should drop them.  Just unwind to the interruption-frame
(pt_regs), then start printing the frames.

That'll also be more in line with the other arches.

	--david

RE: [RFC] Enhanced show_stack output to add backing store regs

[Luck, Tony]

>Is this generally interesting?  I'm wondering if it isn't currently
>done because of some issue with oops message size, or excessive
>printk's causing problems elsewhere?

On a VGA console the "iip" is _sometimes_ still visible on the screen
after an oops (and if your users can only be trained to copy down one
number from an oops, this is the most useful one to have). Adding these
extra lines would guarantee that iip always scrolls off the top.

But I'd be fine sacrificing this in exchange for seeing all the
backing store registers.

-Tony

Re: [RFC] Enhanced show_stack output to add backing store regs

[Bob Montgomery]

On Fri, 2005-03-11 at 12:59 -0800, David Mosberger wrote:
> >>>>> On Fri, 11 Mar 2005 20:25:26 +0000, Matthew Wilcox <matthew@wil.cx> said:
> 
>   Matthew> I know your patch leaaves this unchanged, but I don't think it's helpful
>   Matthew> to show the 'show_stack' and 'show_regs' frames.  Can we get rid of them,
>   Matthew> or is there a reason they're useful?
> 
> There were useful in the early days, when I didn't trust the unwinder... ;-)
> I agree that we should drop them.  Just unwind to the interruption-frame
> (pt_regs), then start printing the frames.
> 
> That'll also be more in line with the other arches.


You might trust the unwinder, and that *might* be a reason to lop off
the top two (show regs and show stack), but I still want to see what
kernel handler was used, and it's still reassuring to be able to check
at show_stack to verify that bsp < sp to eliminate stack overflow as
the source of either the problem, or the problem with the unwinding that
follows.


I'm assuming in my example, that not printing until the interruption
frame would eliminate what is shown below, and I would like to keep
that:

 [<a000000100036b50>] die+0x150/0x280
                                spà000001200dfb40 bspà000001200d8f20
 [<a000000100036cc0>] die_if_kernel+0x40/0x60
                                spà000001200dfb40 bspà000001200d8ef0
 [<a0000001000378d0>] ia64_fault+0x150/0xac0
                                spà000001200dfb40 bspà000001200d8ea8
 [<a00000010000ad20>] ia64_leave_kernel+0x0/0x260
                                spà000001200dfc40 bspà000001200d8ea8

and not just see the stack top out at
 
 [<a0000002000689d0>] buncho_going_to_regnat+0x50/0xa0 [buncho]
                                spà000001200dfe10 bspà000001200d8e80
...

where the error occurred.

-- 
Bob Montgomery <bob.montgomery@hp.com>

Re: [RFC] Enhanced show_stack output to add backing store regs

[David Mosberger]

>>>>> On Fri, 11 Mar 2005 14:19:49 -0700, Bob Montgomery <bob.montgomery@hp.com> said:

  Bob> You might trust the unwinder, and that *might* be a reason to lop off
  Bob> the top two (show regs and show stack), but I still want to see what
  Bob> kernel handler was used, and it's still reassuring to be able to check
  Bob> at show_stack to verify that bsp < sp to eliminate stack overflow as
  Bob> the source of either the problem, or the problem with the unwinding that
  Bob> follows.

That's true.

  Bob> I'm assuming in my example, that not printing until the interruption
  Bob> frame would eliminate what is shown below, and I would like to keep
  Bob> that:

  Bob> [<a000000100036b50>] die+0x150/0x280
  Bob> spà000001200dfb40 bspà000001200d8f20
  Bob> [<a000000100036cc0>] die_if_kernel+0x40/0x60
  Bob> spà000001200dfb40 bspà000001200d8ef0
  Bob> [<a0000001000378d0>] ia64_fault+0x150/0xac0
  Bob> spà000001200dfb40 bspà000001200d8ea8
  Bob> [<a00000010000ad20>] ia64_leave_kernel+0x0/0x260
  Bob> spà000001200dfc40 bspà000001200d8ea8

  Bob> and not just see the stack top out at

  Bob> [<a0000002000689d0>] buncho_going_to_regnat+0x50/0xa0 [buncho]
  Bob> spà000001200dfe10 bspà000001200d8e80
  Bob> ...

  Bob> where the error occurred.

No, other arches start past the interrupt frame, i.e., you'd get the
latter output.

Stack-corruption is an important concern, I agree.  That's the only
reason I haven't gotten rid of the "sp" and "bsp" printing.

	--david

Re: [RFC] Enhanced show_stack output to add backing store regs

[Alex Tsariounov]

On Fri, Mar 11, 2005 at 01:00:08PM -0800, Luck, Tony wrote:
> >Is this generally interesting?  I'm wondering if it isn't currently
> >done because of some issue with oops message size, or excessive
> >printk's causing problems elsewhere?
> 
> On a VGA console the "iip" is _sometimes_ still visible on the screen
> after an oops (and if your users can only be trained to copy down one
> number from an oops, this is the most useful one to have). Adding these
> extra lines would guarantee that iip always scrolls off the top.

Doesn't hitting Shift-PgUp bring the scrolled-off portions back
into view on a VGA console, or does that key not always work?

Regards,
Alex

RE: [RFC] Enhanced show_stack output to add backing store regs

[Luck, Tony]

>>Adding these extra lines would guarantee that iip always scrolls off the top.
>
>Doesn't hitting Shift-PgUp bring the scrolled-off portions back
>into view on a VGA console, or does that key not always work?

I've never seen Shift-PgUp work after the kernel has oopsed ... aren't
keyboard interrupts disabled by that point?

-Tony

Re: [RFC] Enhanced show_stack output to add backing store regs

[Alex Tsariounov]

On Mon, Mar 14, 2005 at 11:04:53AM -0800, Luck, Tony wrote:
> >>Adding these extra lines would guarantee that iip always scrolls off the top.
> >
> >Doesn't hitting Shift-PgUp bring the scrolled-off portions back
> >into view on a VGA console, or does that key not always work?
> 
> I've never seen Shift-PgUp work after the kernel has oopsed ... aren't
> keyboard interrupts disabled by that point?

Ah... I forgot about that little point.

Alex

Re: [RFC] Enhanced show_stack output to add backing store regs

[Keith Owens]

On Mon, 14 Mar 2005 11:51:36 -0700, 
alext@fc.hp.com (Alex Tsariounov) wrote:
>On Fri, Mar 11, 2005 at 01:00:08PM -0800, Luck, Tony wrote:
>> >Is this generally interesting?  I'm wondering if it isn't currently
>> >done because of some issue with oops message size, or excessive
>> >printk's causing problems elsewhere?
>> 
>> On a VGA console the "iip" is _sometimes_ still visible on the screen
>> after an oops (and if your users can only be trained to copy down one
>> number from an oops, this is the most useful one to have). Adding these
>> extra lines would guarantee that iip always scrolls off the top.
>
>Doesn't hitting Shift-PgUp bring the scrolled-off portions back
>into view on a VGA console, or does that key not always work?

Shift-PgUp requires working interrupts.  Not always available when the
kernel is having problems.