stack trace changes

stack trace changes

[Martin Hunt]

I've checked in a rewrite of the stack trace code.  I rewrote i386 and
x86_64 only. ppc64 and ia64 should still work as before, unless I made
any errors while reorganizing the code.

In 2.6.18 there is code to use DWARF to accurately unwind the stacks.
The new code uses this if available, otherwise it falls back to the
inaccurate unwinder.  Some situations like kretprobe trampolines confuse
the unwinder and it does what it can accurately then uses the inaccurate
unwinder. In all cases, it now says when the trace in not accurate.

I also added some related functions:
stack_size() - stack size
stack_used() - bytes of stack used
stack_unused() - bytes of stack unused
caller() - for kretprobes only right now, returns the calling function
name and address.
caller_addr() - ditto but returns an address only

Example output looks like this:

WITH NEW UNWINDER

(normal probe)
0xc04a28ac : meminfo_read_proc+0xf/0x313 []
 0xc04a01ad : proc_file_read+0x110/0x237 []
 0xc046f77c : vfs_read+0xa6/0x157 []
 0xc046fbeb : sys_read+0x41/0x67 []
 0xc0403f97 : syscall_call+0x7/0xb []

(normal probe when a return probe is on the same function)
0xc04a1bc3 : uptime_read_proc+0xe/0x99 []
 0xc06143c5 : kretprobe_trampoline+0x0/0x2b []
 0x00000c00
Leftover inexact backtrace:
 0xc04a009d : proc_file_read+0x0/0x237 []
 0xc046f77c : vfs_read+0xa6/0x157 []
 0xc046fbeb : sys_read+0x41/0x67 []
 0xc0403f97 : syscall_call+0x7/0xb []

(return probe)
Returning from: 0xc04a1bb5 : uptime_read_proc+0x0/0x99 []
Returning to: 0xc04a01ad : proc_file_read+0x110/0x237 []
Inexact backtrace:
 0xc04a009d : proc_file_read+0x0/0x237 []
 0xc046f77c : vfs_read+0xa6/0x157 []
 0xc046fbeb : sys_read+0x41/0x67 []
 0xc0403f97 : syscall_call+0x7/0xb []

WITHOUT NEW UNWINDER

0xc04a1c54 : meminfo_read_proc+0xf/0x27a []
Inexact backtrace:
 0xc048091e : dput+0x35/0x230 []
 0xc0479907 : __link_path_walk+0xbf4/0xd31 []
 0xc048091e : dput+0x35/0x230 []
 0xc0484fad : mntput_no_expire+0x11/0x6e []
 0xc0479af7 : link_path_walk+0xb3/0xbd []
 0xc06181fe : _read_unlock_irq+0x5/0x7 []
 0xc044c938 : find_get_page+0x3a/0x40 []
 0xc044f103 : filemap_nopage+0x192/0x31f []
 0xc0451564 : get_page_from_freelist+0x2a8/0x411 []
 0xc045bb40 : vma_adjust+0x3c8/0x43e []
 0xc045173a : __alloc_pages+0x6d/0x2c2 []
 0xc045c04f : vma_merge+0x18a/0x19a []
 0xc04a1c45 : meminfo_read_proc+0x0/0x27a []
 0xc04a028a : proc_file_read+0x110/0x237 []
 0xc04a017a : proc_file_read+0x0/0x237 []
 0xc046bac2 : vfs_read+0xa6/0x14e []
 0xc046bf26 : sys_read+0x41/0x67 []
 0xc0403e3f : syscall_call+0x7/0xb []

0xc04a1ecd : uptime_read_proc+0xe/0x99 []
Inexact backtrace:
 0xc06183fe : debug_stack_correct+0x1e/0x24 []
 0xc04a1ebf : uptime_read_proc+0x0/0x99 []
 0xc04a1ebf : uptime_read_proc+0x0/0x99 []
 0xc06188cf : kretprobe_trampoline+0x0/0x2b []
 0xc04a017a : proc_file_read+0x0/0x237 []
 0xc046bac2 : vfs_read+0xa6/0x14e []
 0xc046bf26 : sys_read+0x41/0x67 []
 0xc0403e3f : syscall_call+0x7/0xb []

Returning from: 0xc04a1ebf : uptime_read_proc+0x0/0x99 []
Returning to: 0xc04a028a : proc_file_read+0x110/0x237 []
Inexact backtrace:
 0xc04a017a : proc_file_read+0x0/0x237 []
 0xc046bac2 : vfs_read+0xa6/0x14e []
 0xc046bf26 : sys_read+0x41/0x67 []
 0xc0403e3f : syscall_call+0x7/0xb []

Re: stack trace changes

[Mike Mason]

Thanks for working on this.  See comments below...

Martin Hunt wrote:
> I've checked in a rewrite of the stack trace code.  I rewrote i386 and
> x86_64 only. ppc64 and ia64 should still work as before, unless I made
> any errors while reorganizing the code.

I'll test on ppc64 after the build error is fixed in the ppc64 runtine
(see bug 3051).

> 
> In 2.6.18 there is code to use DWARF to accurately unwind the stacks.
> The new code uses this if available, otherwise it falls back to the
> inaccurate unwinder.  Some situations like kretprobe trampolines confuse
> the unwinder and it does what it can accurately then uses the inaccurate
> unwinder. In all cases, it now says when the trace in not accurate.

I tested print_backtrace on 2.6.17-1.2187_FC5 on x86_64. I now see a 
single line(as before) followed by "Inexact backtrace:" and then 
nothing. Is there no way to get additional stack info on x86_64 
kernels earlier than 2.6.18?  Just want to know what to expect.

I tested on 2.6.18 as well and it appears to work as you described.

Thanks again for your efforts.

- Mike

Re: stack trace changes

[Martin Hunt]

On Thu, 2006-10-12 at 15:18 -0700, Mike Mason wrote:

> I tested print_backtrace on 2.6.17-1.2187_FC5 on x86_64. I now see a 
> single line(as before) followed by "Inexact backtrace:" and then 
> nothing. 

Are you using the example from 3050?

probe kernel.function("schedule@kernel/sched.c") {
        print_backtrace();
}

On RHEL4 (2.6.9-42.0.3.ELsmp), I get

0xffffffff80309677 : schedule+0x15/0xb6f []
Inexact backtrace:
 0xffffffff8010e7f4 : cpu_idle+0x32/0x34 []
 0xffffffff804eb67b : start_kernel+0x1d6/0x1da []
 0xffffffff804eb1d5 : _sinittext+0x1d5/0x1d7 []

0xffffffff80309677 : schedule+0x15/0xb6f []
Inexact backtrace:
 0xffffffff8013575f : autoremove_wake_function+0x9/0x2e []
 0xffffffff80133dfe : __wake_up_common+0x43/0x63 []
 0xffffffff80147795 : worker_thread+0xe2/0x22a []
 0xffffffff80133dad : default_wake_function+0x0/0xe []
 0xffffffff80133dad : default_wake_function+0x0/0xe []
 0xffffffff8014b4f4 : keventd_create_kthread+0x0/0x48 []
 0xffffffff801476b3 : worker_thread+0x0/0x22a []
 0xffffffff8014b4f4 : keventd_create_kthread+0x0/0x48 []
 0xffffffff8014b4cb : kthread+0xc8/0xf1 []
 0xffffffff80110f47 : child_rip+0x8/0x11 []
 0xffffffff8014b4f4 : keventd_create_kthread+0x0/0x48 []
 0xffffffff8014b403 : kthread+0x0/0xf1 []
 0xffffffff80110f3f : child_rip+0x0/0x11 []

0xffffffff80309677 : schedule+0x15/0xb6f []
Inexact backtrace:
 0xffffffff8010e7f4 : cpu_idle+0x32/0x34 []
[...]

I don't have FC5 installed on x86_64, but I tried FC6 with the 
new unwinder disabled and it worked just like it did with the 
old 2.6.9 kernel.

So it should work.