On Tue, Aug 02, 2016 at 07:16:22PM -0400, Steven Rostedt wrote: > On Tue, 2 Aug 2016 17:13:59 -0500 > Josh Poimboeuf <jpoim...@redhat.com> 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