Re: [PATCH 05/19] x86/dumpstack: fix function graph tracing stack dump reliability issues

[Josh Poimboeuf]

On Tue, Aug 02, 2016 at 07:16:22PM -0400, Steven Rostedt wrote:
> On Tue, 2 Aug 2016 17:13:59 -0500
> Josh Poimboeuf <jpoimboe@xxxxxxxxxx> wrote:
> 
> 
> > > Then we only need the fp use case when FRAME_POINTER is not set. As
> > > mcount forces FRAME_POINTER, we only need to worry about the fentry
> > > case.  
> > 
> > Hm, I'm confused.  First, I don't see where mcount forces FRAME_POINTER.
> 
> Hmm, we should probably force it generally, as gcc itself requires
> mcount to be used with framepointers. -mcount can't be used without
> them.
> 
> > 
> > Second, I don't see why that even matters.  If mcount and frame pointers
> > are enabled, then the 'fp' field of ftrace_ret_stack is needed for the
> > gcc sanity check, right?  So we couldn't override 'fp', and the old
> > "stateful index" version of ftrace_graph_ret_addr() would have to be
> > used in the code above for reliable addresses, and we'd still have the
> > same out-of-sync bug.
> > 
> > Or am I missing something?
> > 
> 
> Or I missed something. How did we get out of sync? If we have frame
> pointers, shouldn't the "return_to_handler" be seen as reliable by the
> code (not that we save it as such)? That is, if the frame pointer shows
> that the next function is return_to_handler, then we increment the
> index into ret_stack, otherwise we simply record the return_to_handler
> as a normal "unreliable" function, without any processing of it.
> 
> I guess I don't actually understand how the NMI screwed it up, as
> function graph doesn't trace "do_nmi()" itself nor anything before that.
> I'm guessing it really got out of sync because there's a
> "return_to_handler" in the stack that wasn't really called (not a frame
> pointer). The ftrace_graph_ret_addr() will shift the index currently
> regardless if the return_to_handler found is part of a stack frame, or
> just left over in the stack. THAT is why I think it got out of sync.

It's not specific to NMIs.  The problem is that dump_trace() is starting
from the frame pointed to by a pt_regs, rather than the current frame.
Instead of starting with the current frame, the first 10 functions on
the stack are skipped by the unwinder, but they're *not* skipped on the
ret_stack.  So it starts out out-of-sync.

If it had first initialized the graph index variable to 10 instead of 0
before passing it to ftrace_graph_ret_addr(), it would have worked.

The problem isn't specific to NMIs.  It happens anywhere the first few
stack frames are skipped, which is very common.  For example:

  $ cat /proc/self/stack
  [<ffffffff810489a2>] save_stack_trace_tsk+0x22/0x40
  [<ffffffff81311a89>] proc_pid_stack+0xb9/0x110
  [<ffffffff813127c4>] proc_single_show+0x54/0x80
  [<ffffffff812be088>] seq_read+0x108/0x3e0
  [<ffffffff812923d7>] __vfs_read+0x37/0x140
  [<ffffffff812929d9>] vfs_read+0x99/0x140
  [<ffffffff81293f28>] SyS_read+0x58/0xc0
  [<ffffffff818af97c>] entry_SYSCALL_64_fastpath+0x1f/0xbd
  [<ffffffffffffffff>] 0xffffffffffffffff

  $ echo function_graph > /sys/kernel/debug/tracing/current_tracer 
  $ cat /proc/self/stack
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff810394cc>] print_context_stack+0xfc/0x100
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff8103891b>] dump_trace+0x12b/0x350
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff810489a2>] save_stack_trace_tsk+0x22/0x40
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff81311a89>] proc_pid_stack+0xb9/0x110
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff813127c4>] proc_single_show+0x54/0x80
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff812be088>] seq_read+0x108/0x3e0
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff812923d7>] __vfs_read+0x37/0x140
  [<ffffffff818b2428>] return_to_handler+0x0/0x27
  [<ffffffff812929d9>] vfs_read+0x99/0x140
  [<ffffffffffffffff>] 0xffffffffffffffff

In this case, it's offset by two frames.  With function graph tracing
enabled, it starts with print_context_stack() instead of
save_stack_trace_tsk(), and it doesn't show the last two frames.

-- 
Josh