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

[Josh Poimboeuf]

On Mon, Aug 01, 2016 at 10:36:33AM -0500, Josh Poimboeuf wrote:
> On Mon, Aug 01, 2016 at 10:28:21AM -0400, Steven Rostedt wrote:
> > On Sat, 30 Jul 2016 08:51:25 -0500
> > Josh Poimboeuf <jpoimboe@xxxxxxxxxx> wrote:
> > 
> > > On Fri, Jul 29, 2016 at 10:20:36PM -0400, Steven Rostedt wrote:
> > > > On Fri, 29 Jul 2016 19:50:59 -0500
> > > > Josh Poimboeuf <jpoimboe@xxxxxxxxxx> wrote:
> > > >   
> > > > > BTW, it would be really nice if ftrace_graph_ret_addr() were idempotent
> > > > > so we could get the "real" return address without having to pass in a
> > > > > state variable.
> > > > > 
> > > > > For example we could add an "unsigned long *retp" pointer to
> > > > > ftrace_ret_stack, which points to the return address on the stack.  Then
> > > > > we could get rid of the index state variable in ftrace_graph_ret_addr,
> > > > > and also then there would never be a chance of the stack dump getting
> > > > > out of sync with the ret_stack.
> > > > > 
> > > > > What do you think?
> > > > >   
> > > > 
> > > > I don't want to extend ret_stack as that is allocated 50 of these
> > > > structures for every task. That said, we have the "fp" field that's
> > > > used to check for frame pointer corruption when mcount is used. With
> > > > CC_USING_FENTRY, that field is ignored. Perhaps we could overload that
> > > > field for this.  
> > > 
> > > In that case, I guess we would need two versions of
> > > ftrace_graph_ret_addr(), with the current implementation still needed
> > > for mcount+HAVE_FUNCTION_GRAPH_FP_TEST.
> > 
> > How hard would it be in that case?
> 
> Well, it would be easy enough, but then the caller would still need to
> pass in the state variable.  So maybe it's not worth the trouble.

I did some stack trace testing on mainline with function graph tracing.
As it turns out, print_ftrace_graph_addr() is already buggy today if the
caller of dump_trace() specifies a stack pointer or a pt_regs (which is
usually done in order to skip some irrelevant stack frames in the
trace).

For example, here's a stack trace based on NMI regs:

  $ echo 1 > /proc/sys/kernel/sysrq
  $ echo l > /proc/sysrq-trigger
  ...
  Call Trace:
   [<ffffffff81066141>] ?  __x2apic_send_IPI_dest.constprop.4+0x31/0x40
   [<ffffffff810661e5>] __x2apic_send_IPI_mask+0x95/0xe0
   [<ffffffff81061d70>] ? irq_force_complete_move+0xf0/0xf0
   [<ffffffff810662a3>] x2apic_send_IPI_mask+0x13/0x20
   [<ffffffff81061d8b>] nmi_raise_cpu_backtrace+0x1b/0x20
   [<ffffffff8144ff76>] nmi_trigger_all_cpu_backtrace+0xc6/0xf0
   [<ffffffff81061de9>] arch_trigger_all_cpu_backtrace+0x19/0x20
   [<ffffffff8155c463>] sysrq_handle_showallcpus+0x13/0x20
   [<ffffffff8155cc18>] __handle_sysrq+0x138/0x220
   [<ffffffff8155cae5>] ? __handle_sysrq+0x5/0x220
   [<ffffffff8155d111>] write_sysrq_trigger+0x51/0x60
   [<ffffffff813104e2>] proc_reg_write+0x42/0x70
   [<ffffffff81291877>] __vfs_write+0x37/0x140
   [<ffffffff8110d161>] ? update_fast_ctr+0x51/0x80
   [<ffffffff8110d217>] ? percpu_down_read+0x57/0xa0
   [<ffffffff81296074>] ? __sb_start_write+0xb4/0xf0
   [<ffffffff81296074>] ? __sb_start_write+0xb4/0xf0
   [<ffffffff81292b38>] vfs_write+0xb8/0x1a0
   [<ffffffff81293fe8>] SyS_write+0x58/0xc0
   [<ffffffff818af97c>] entry_SYSCALL_64_fastpath+0x1f/0xbd

And here's the same trace with function graph tracing:

  $ echo function_graph > /sys/kernel/debug/tracing/current_tracer 
  $ echo l > /proc/sysrq-trigger
  ...
  Call Trace:
   [<ffffffff81066141>] ?  __x2apic_send_IPI_dest.constprop.4+0x31/0x40
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff810394cc>] print_context_stack+0xfc/0x100
   [<ffffffff81061d70>] ? irq_force_complete_move+0xf0/0xf0
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff8103891b>] dump_trace+0x12b/0x350
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff810396eb>] show_trace_log_lvl+0x4b/0x60
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff81038c76>] show_stack_log_lvl+0x136/0x1d0
   [<ffffffff81061de9>] arch_trigger_all_cpu_backtrace+0x19/0x20
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff81038db8>] show_regs+0xa8/0x1b0
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff8144fe96>] nmi_cpu_backtrace+0x46/0x60
   [<ffffffff8155cae5>] ? __handle_sysrq+0x5/0x220
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff81039b5f>] nmi_handle+0xbf/0x2f0
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff8103a2b3>] default_do_nmi+0x73/0x180
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff8103a4d9>] do_nmi+0x119/0x170
   [<ffffffff811bb3cd>] ?  ftrace_return_to_handler+0x9d/0x110
   [<ffffffff81291845>] ? __vfs_write+0x5/0x140
   [<ffffffff81291845>] ? __vfs_write+0x5/0x140
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff810661e5>] __x2apic_send_IPI_mask+0x95/0xe0
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff810662a3>] x2apic_send_IPI_mask+0x13/0x20
   [<ffffffff818b2428>] ftrace_graph_caller+0xa8/0xa8
   [<ffffffff81061d8b>] nmi_raise_cpu_backtrace+0x1b/0x20

The ret_stack is out of sync with the stack dump because the stack dump
was started with the regs from the NMI, instead of being started from
the current frame.

So I guess there are a couple of ways to fix it:

  a) keep track of the return address pointer like we discussed above;

     or

  b) have the unwinder count the # of skipped frames which refer to
     'return_to_handler', and pass that as the initial index value to
     ftrace_graph_ret_addr().

Option a) would be much cleaner.  But to fix it for both mcount and
fentry, we couldn't override 'fp' so I guess we'd need to add a new
field to ftrace_ret_stack.

Option b) is uglier, but I could probably make it work with the new
unwinder.

-- 
Josh