From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757275AbcHCCGt (ORCPT ); Tue, 2 Aug 2016 22:06:49 -0400 Received: from mx1.redhat.com ([209.132.183.28]:34206 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752199AbcHCCGj (ORCPT ); Tue, 2 Aug 2016 22:06:39 -0400 Date: Tue, 2 Aug 2016 20:56:56 -0500 From: Josh Poimboeuf To: Steven Rostedt Cc: Thomas Gleixner , Ingo Molnar , "H . Peter Anvin" , x86@kernel.org, linux-kernel@vger.kernel.org, Andy Lutomirski , Linus Torvalds , Brian Gerst , Kees Cook , Peter Zijlstra , Frederic Weisbecker , Byungchul Park Subject: Re: [PATCH 05/19] x86/dumpstack: fix function graph tracing stack dump reliability issues Message-ID: <20160803015656.j6fxrgucmghh5gfn@treble> References: <20160729185521.62a5cd2a@gandalf.local.home> <20160730005059.5krpl2xsvqfbnntj@treble> <20160729222036.340b51ce@grimm.local.home> <20160730135125.qqw5qz24szlc2crz@treble> <20160801102821.1d6261a9@gandalf.local.home> <20160801153633.c7sa2rclkqwbdagd@treble> <20160802210011.k6li4mnyvky5jtev@treble> <20160802171610.09156c90@gandalf.local.home> <20160802221359.tkb3mkjzkq3petrq@treble> <20160802191622.466f53d2@gandalf.local.home> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline In-Reply-To: <20160802191622.466f53d2@gandalf.local.home> User-Agent: Mutt/1.6.0.1 (2016-04-01) X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.32]); Wed, 03 Aug 2016 01:57:00 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, Aug 02, 2016 at 07:16:22PM -0400, Steven Rostedt wrote: > On Tue, 2 Aug 2016 17:13:59 -0500 > Josh Poimboeuf 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 [] save_stack_trace_tsk+0x22/0x40 [] proc_pid_stack+0xb9/0x110 [] proc_single_show+0x54/0x80 [] seq_read+0x108/0x3e0 [] __vfs_read+0x37/0x140 [] vfs_read+0x99/0x140 [] SyS_read+0x58/0xc0 [] entry_SYSCALL_64_fastpath+0x1f/0xbd [] 0xffffffffffffffff $ echo function_graph > /sys/kernel/debug/tracing/current_tracer $ cat /proc/self/stack [] return_to_handler+0x0/0x27 [] print_context_stack+0xfc/0x100 [] return_to_handler+0x0/0x27 [] dump_trace+0x12b/0x350 [] return_to_handler+0x0/0x27 [] save_stack_trace_tsk+0x22/0x40 [] return_to_handler+0x0/0x27 [] proc_pid_stack+0xb9/0x110 [] return_to_handler+0x0/0x27 [] proc_single_show+0x54/0x80 [] return_to_handler+0x0/0x27 [] seq_read+0x108/0x3e0 [] return_to_handler+0x0/0x27 [] __vfs_read+0x37/0x140 [] return_to_handler+0x0/0x27 [] vfs_read+0x99/0x140 [] 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