Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack

From	Josh Poimboeuf <jpoimboe@redhat.com>
Newsgroups	linux.kernel
Subject	Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack
Date	2016-07-23 00:30 +0200
Message-ID	<rXR7c-3iw-31@gated-at.bofh.it> (permalink)
References	(2 earlier) <rXuNk-5nE-1@gated-at.bofh.it> <rXztE-dP-11@gated-at.bofh.it> <rXB2p-1pp-5@gated-at.bofh.it> <rXL1M-7Ib-27@gated-at.bofh.it> <rXQut-2Qh-5@gated-at.bofh.it>
Organization	linux.* mail to news gateway

Show all headers | View raw

On Fri, Jul 22, 2016 at 02:46:10PM -0700, Andy Lutomirski wrote:
> On Fri, Jul 22, 2016 at 8:57 AM, Josh Poimboeuf <jpoimboe@redhat.com> wrote:
> > On Thu, Jul 21, 2016 at 10:13:03PM -0700, Andy Lutomirski wrote:
> >> On Thu, Jul 21, 2016 at 8:30 PM, Josh Poimboeuf <jpoimboe@redhat.com> wrote:
> >> > On Thu, Jul 21, 2016 at 03:32:32PM -0700, Andy Lutomirski wrote:
> >> >> On Thu, Jul 21, 2016 at 2:21 PM, Josh Poimboeuf <jpoimboe@redhat.com> wrote:
> >> >> > Now that we can find pt_regs registers in the middle of the stack due to
> >> >> > an interrupt or exception, we can print them.  Here's what it looks
> >> >> > like:
> >> >> >
> >> >> >    ...
> >> >> >    [<ffffffff8106f7dc>] do_async_page_fault+0x2c/0xa0
> >> >> >    [<ffffffff8189f558>] async_page_fault+0x28/0x30
> >> >> >   RIP: 0010:[<ffffffff814529e2>]  [<ffffffff814529e2>] __clear_user+0x42/0x70
> >> >> >   RSP: 0018:ffff88007876fd38  EFLAGS: 00010202
> >> >> >   RAX: 0000000000000000 RBX: 0000000000000138 RCX: 0000000000000138
> >> >> >   RDX: 0000000000000000 RSI: 0000000000000008 RDI: 000000000061b640
> >> >> >   RBP: ffff88007876fd48 R08: 0000000dc2ced0d0 R09: 0000000000000000
> >> >> >   R10: 0000000000000001 R11: 0000000000000000 R12: 000000000061b640
> >> >> >   R13: 0000000000000000 R14: ffff880078770000 R15: ffff880079947200
> >> >> >    [<ffffffff814529e2>] ? __clear_user+0x42/0x70
> >> >> >    [<ffffffff814529c3>] ? __clear_user+0x23/0x70
> >> >> >    [<ffffffff81452a7b>] clear_user+0x2b/0x40
> >> >> >    ...
> >> >>
> >> >> This looks wrong.  Here are some theories:
> >> >>
> >> >> (a) __clear_user is a reliable address that is indicated by RIP: ....
> >> >> Then it's found again as an unreliable address as "?
> >> >> __clear_user+0x42/0x70" by scanning the stack.  "?
> >> >> __clear_user+0x23/0x70" is a genuine leftover artifact on the stack.
> >> >> In this case, shouldn't "? __clear_user+0x42/0x70" have been
> >> >> suppressed because it matched a reliable address?
> >> >>
> >> >> (b) You actually intended for all the addresses to be printed, in
> >> >> which case "? __clear_user+0x42/0x70" should have been
> >> >> "__clear_user+0x42/0x70" and you have a bug.  In this case, it's
> >> >> plausible that your state machine got a bit lost leading to "?
> >> >> __clear_user+0x23/0x70" as well (i.e. it's not just an artifact --
> >> >> it's a real frame and you didn't find it).
> >> >>
> >> >> (c) Something else and I'm confused.
> >> >
> >> > So there's a subtle difference between addresses reported by regs->ip
> >> > and normal return addresses.  For example:
> >> >
> >> >    ...
> >> >    [<ffffffff8189ff4d>] smp_apic_timer_interrupt+0x3d/0x50
> >> >    [<ffffffff8189de6e>] apic_timer_interrupt+0x9e/0xb0
> >> >   RIP: 0010:[<ffffffff8129b350>]  [<ffffffff8129b350>] path_init+0x0/0x750
> >> >   RSP: 0018:ffff880036a3fd80  EFLAGS: 00000296
> >> >   RAX: ffff88003691aa40 RBX: ffff880036a3ff08 RCX: ffff880036a3ff08
> >> >   RDX: ffff880036a3ff08 RSI: 0000000000000041 RDI: ffff880036a3fdb0
> >> >   RBP: ffff880036a3fda0 R08: 0000000000000000 R09: 0000000000000010
> >> >   R10: 8080808080808080 R11: fefefefefefefeff R12: ffff880036a3fdb0
> >> >   R13: 0000000000000001 R14: ffff880036a3ff08 R15: 0000000000000000
> >> >    <EOI>
> >> >    [<ffffffff8129b350>] ? lookup_fast+0x3d0/0x3d0
> >> >    [<ffffffff8129c81b>] ? path_lookupat+0x1b/0x120
> >> >    [<ffffffff8129ddd1>] filename_lookup+0xb1/0x180
> >> >    ...
> >> >
> >> > In this case the irq hit right after path_lookupat() called into
> >> > path_init().  So the "path_init+0x0" printed by __show_regs() is right.
> >> >
> >> > Note the backtrace reports the same address, but it instead describes it
> >> > as "lookup_fast+0x3d0", which is the end of lookup_fast().  That's
> >> > because normally, such an address after a call instruction at the end of
> >> > a function would indicate a tail call (e.g., to a noreturn function).
> >> > If that were the case, printing "path_init+0x0" would be completely
> >> > wrong, because path_init() just happens to be the function located
> >> > immediately after lookup_fast().
> >> >
> >> > Maybe I could add some special logic to say: "if this return address was
> >> > from a call, use printk_stack_address(); else if it was from a pt_regs,
> >> > use printk_address()."  (The former prints the preceding function, the
> >> > latter prints the current function.)  Then we could remove the question
> >> > mark.
> >> >
> >> > There's also the question of whether or not the address should be
> >> > printed again, after it's already been printed by __show_regs().  I
> >> > don't have a strong opinion either way.
> >> >
> >>
> >> IIRC we don't show the actual faulting function in the call trace, so
> >> we probably shouldn't duplicate the entry after the show_regs.
> >
> > Just to clarify, that's true today for cases where the stack dump starts
> > from a handler which has regs.  It starts dumping based on regs->ip and
> > regs->bp, so the regs themselves aren't dumped.
> >
> > But for cases where regs are in the middle of the stack, they aren't
> > detected today, and you'll still see the value of regs->ip dumped with a
> > question mark.
> >
> > That said, with this patch, now that regs in the middle of the stack
> > *are* being printed, I can't think of a good reason to print the return
> > address twice: both in regs and the stack trace.  So removing it from
> > the stack trace is fine with me.
> >
> >> That being said, I'm still confused by the question marks.  What
> >> exactly is going on?  Is the code really doing the right thing wrt
> >> resuming the unwind?  Is there a git tree with these patches applied
> >> somewhere so I can look at it easily in context?
> >
> > show_trace_log_lvl() is doing two things in parallel: scanning all
> > kernel text addresses on the stack while simultaneously using the
> > unwinder to walk the frame pointers.  Only those scanned addresses which
> > are also found by the unwinder are printed without question marks.
> >
> > The pt_regs aren't in a frame of their own; they're just data inside of
> > a bigger frame.  (You may recall that you objected to my proposal to put
> > them in their own frame :-))  So that's why the address stored in
> > regs->ip was printed with a question mark: it's not in the header of a
> > real frame; it's just data.
> 
> It wasn't the separate frame part I was objecting to -- it was their
> encoding on the stack.  Maybe they should unwind as though they're a
> separate frame.  For example, the unwind API could give the frame that
> returns to apic_timer_interrupt+0x9e/0xb0 and then the next frame
> could literally list regs->ip as its retaddr (and maybe that frame or
> even the following one should be the one with non-NULL
> unwind_get_entry_regs).

Having the unwinder treat the pt_regs as a "fake" frame is problematic:

- As I described above, you can't treat regs->ip as a normal return
  value anyway.

- Also, for exceptions and nested interrupts, the regs are stored on the
  interrupting stack.  But for non-nested interrupts, they're stored on
  the thread stack.  So the regs aren't always on the same stack as the
  corresponding encoded pt_regs pointer.  Another issue is that there's
  not always a frame after the regs.  For those reasons, creating a
  "fake" frame abstraction in the state machine is quite a bit trickier
  than just dealing with those details in the only place that cares
  about them: show_trace_log_lvl().

> In some sense, the regs belong to the frame that got interrupted, not
> the frame that did the interrupting.  But maybe that's backwards -- if
> we have DWARF, then the regs correspond to the regs at the time of a
> call, and those regs are reasonably likely to contain the arguments to
> the called function.
> 
> But regardless of which way this goes, it seems quite awkward to me
> that regs->ip never shows up as the return addr of any frame as
> exposed by the unwind API.

Again, regs->ip is special.  It's not a call return address and we
shouldn't force it to be.

-- 
Josh

Thread

[PATCH 00/19] x86/dumpstack: rewrite x86 stack dump code Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 05/19] x86/dumpstack: fix function graph tracing stack dump reliability issues Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 04/19] x86/dumpstack: make printk_stack_address() more generally useful Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 18/19] x86/dumpstack: print stack identifier on its own line Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 13/19] x86/stacktrace: convert save_stack_trace_*() to the new unwinder Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
    Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Andy Lutomirski <luto@amacapital.net> - 2016-07-22 00:40 +0200
      Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-22 05:40 +0200
        Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Andy Lutomirski <luto@amacapital.net> - 2016-07-22 07:20 +0200
          Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-22 18:00 +0200
            Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Andy Lutomirski <luto@amacapital.net> - 2016-07-22 23:50 +0200
              Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 00:30 +0200
                Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Andy Lutomirski <luto@amacapital.net> - 2016-07-23 01:20 +0200
                Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Andy Lutomirski <luto@amacapital.net> - 2016-07-23 01:40 +0200
                Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 02:10 +0200
                Re: [PATCH 19/19] x86/dumpstack: print any pt_regs found on the stack Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 01:40 +0200
  [PATCH 08/19] x86/dumpstack: don't disable preemption in show_stack_log_lvl() and dump_trace() Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 14/19] oprofile/x86: convert x86_backtrace() to the new unwinder Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 06/19] x86/dumpstack: remove extra brackets around "EOE" Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 10/19] x86/dumpstack: add get_stack_info() interface Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
    Re: [PATCH 10/19] x86/dumpstack: add get_stack_info() interface Andy Lutomirski <luto@amacapital.net> - 2016-07-23 01:30 +0200
      Re: [PATCH 10/19] x86/dumpstack: add get_stack_info() interface Andy Lutomirski <luto@amacapital.net> - 2016-07-23 02:00 +0200
        Re: [PATCH 10/19] x86/dumpstack: add get_stack_info() interface Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 15:10 +0200
      Re: [PATCH 10/19] x86/dumpstack: add get_stack_info() interface Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 02:00 +0200
        Re: [PATCH 10/19] x86/dumpstack: add get_stack_info() interface Andy Lutomirski <luto@amacapital.net> - 2016-07-23 02:20 +0200
          Re: [PATCH 10/19] x86/dumpstack: add get_stack_info() interface Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 16:10 +0200
  [PATCH 01/19] x86/dumpstack: remove show_trace() Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
    Re: [PATCH 01/19] x86/dumpstack: remove show_trace() Andy Lutomirski <luto@amacapital.net> - 2016-07-22 00:00 +0200
  [PATCH 12/19] perf/x86: convert perf_callchain_kernel() to the new unwinder Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 02/19] x86/dumpstack: add get_stack_pointer() and get_frame_pointer() Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
    Re: [PATCH 02/19] x86/dumpstack: add get_stack_pointer() and get_frame_pointer() Andy Lutomirski <luto@amacapital.net> - 2016-07-22 00:00 +0200
  [PATCH 11/19] x86/dumptrace: add new unwind interface and implementations Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
  [PATCH 09/19] x86/dumpstack: simplify in_exception_stack() Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
    Re: [PATCH 09/19] x86/dumpstack: simplify in_exception_stack() Andy Lutomirski <luto@amacapital.net> - 2016-07-22 00:10 +0200
  [PATCH 07/19] x86/dumpstack: add IRQ_USABLE_STACK_SIZE define Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-21 23:30 +0200
    Re: [PATCH 07/19] x86/dumpstack: add IRQ_USABLE_STACK_SIZE define Andy Lutomirski <luto@amacapital.net> - 2016-07-22 00:10 +0200
      Re: [PATCH 07/19] x86/dumpstack: add IRQ_USABLE_STACK_SIZE define Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-22 03:50 +0200
        Re: [PATCH 07/19] x86/dumpstack: add IRQ_USABLE_STACK_SIZE define Ingo Molnar <mingo@kernel.org> - 2016-07-22 10:30 +0200
  Re: [PATCH 00/19] x86/dumpstack: rewrite x86 stack dump code Linus Torvalds <torvalds@linux-foundation.org> - 2016-07-23 02:30 +0200
    Re: [PATCH 00/19] x86/dumpstack: rewrite x86 stack dump code Andy Lutomirski <luto@amacapital.net> - 2016-07-23 02:40 +0200
      Re: [PATCH 00/19] x86/dumpstack: rewrite x86 stack dump code Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 07:40 +0200
        Re: [PATCH 00/19] x86/dumpstack: rewrite x86 stack dump code Linus Torvalds <torvalds@linux-foundation.org> - 2016-07-23 07:50 +0200
          Re: [PATCH 00/19] x86/dumpstack: rewrite x86 stack dump code Josh Poimboeuf <jpoimboe@redhat.com> - 2016-07-23 15:00 +0200

csiph-web