From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756816AbdLVSa1 (ORCPT ); Fri, 22 Dec 2017 13:30:27 -0500 Received: from mx1.redhat.com ([209.132.183.28]:51362 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755464AbdLVSaZ (ORCPT ); Fri, 22 Dec 2017 13:30:25 -0500 Date: Fri, 22 Dec 2017 12:30:24 -0600 From: Josh Poimboeuf To: Steven Rostedt Cc: LKML , Ingo Molnar , Thomas Gleixner , Andrew Morton , x86@kernel.org, Linus Torvalds Subject: Re: [RFC][PATCH][REGRESSION FIX] x86/ftrace: Add ORC annotation to 64 bit ftrace assembly Message-ID: <20171222183024.47yadfkznhwhrlgf@treble> References: <20171222131841.4564c975@gandalf.local.home> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline In-Reply-To: <20171222131841.4564c975@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.29]); Fri, 22 Dec 2017 18:30:25 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Fri, Dec 22, 2017 at 01:18:41PM -0500, Steven Rostedt wrote: > From: Steven Rostedt (VMware) > > While doing some debugging, I kicked off the stacktrace trigger, to see > what was doing stacktraces in my code (it was causing a lot of noise in > my function traces). > > I ran: > > # trace-cmd record -p function -l save_stack_trace -l save_stack_trace:stacktrace > > And took a look at the trace, but all I found was this: > > trace-cm-1326 0d..2 107.791049: kernel_stack: > trace-cm-1326 0d..2 107.791077: kernel_stack: > trace-cm-1326 0...2 107.791084: kernel_stack: > trace-cm-1326 0d..2 107.791091: kernel_stack: > trace-cm-1326 0d..2 107.791097: kernel_stack: > trace-cm-1326 0...2 107.791102: kernel_stack: > trace-cm-1326 0d..4 107.791109: kernel_stack: > trace-cm-1326 0d..2 107.791116: kernel_stack: > trace-cm-1326 0d..2 107.791120: kernel_stack: > trace-cm-1326 0...2 107.791125: kernel_stack: > trace-cm-1326 0d..2 107.791133: kernel_stack: > trace-cm-1326 0d..2 107.791140: kernel_stack: > trace-cm-1326 0...2 107.791145: kernel_stack: > trace-cm-1326 0d..4 107.791157: kernel_stack: > [...] > > This was not very useful. I kicked off a bisect to see where it broke, > because it was working fine in 4.14, and this is a new regression in > the 4.15 rc cycle. > > The culprit ended up being: > > fc72ae40e30 "x86/unwind: Make CONFIG_UNWINDER_ORC=y the default in > kconfig for 64-bit" > > As I find this to be a useful option, I don't want to revert it, so I > looked at how to make ftrace work with this new unwinder. I came up > with this solution. I'm not sure it is correct, but now my traces look > like this (and objtool check doesn't complain): > > > splice-t-1301 0d..1 203.199356: function: save_stack_trace > splice-t-1301 0d..2 203.199365: kernel_stack: > => ___slab_alloc (ffffffff81221c5d) > => __slab_alloc.isra.81 (ffffffff81221d08) > => kmem_cache_alloc (ffffffff812227ce) > => getname_flags (ffffffff8124d49a) > => SyS_execve (ffffffff812459f2) > => do_syscall_64 (ffffffff8100394c) > => return_from_SYSCALL_64 (ffffffff817c2dd8) > splice-t-1301 0d..1 203.199379: function: save_stack_trace > splice-t-1301 0d..2 203.199382: kernel_stack: > => ___slab_alloc (ffffffff81221c5d) > => __slab_alloc.isra.81 (ffffffff81221d08) > => kmem_cache_alloc (ffffffff812227ce) > => create_object (ffffffff81237593) > => kmem_cache_alloc (ffffffff81222795) > => getname_flags (ffffffff8124d49a) > => SyS_execve (ffffffff812459f2) > => do_syscall_64 (ffffffff8100394c) > => return_from_SYSCALL_64 (ffffffff817c2dd8) > splice-t-1301 0...1 203.199385: function: save_stack_trace > splice-t-1301 0...2 203.199387: kernel_stack: > => getname_flags (ffffffff8124d49a) > => SyS_execve (ffffffff812459f2) > => do_syscall_64 (ffffffff8100394c) > => return_from_SYSCALL_64 (ffffffff817c2dd8) > splice-t-1301 0d..1 203.199392: function: save_stack_trace > splice-t-1301 0d..2 203.199395: kernel_stack: > => ___slab_alloc (ffffffff81221c5d) > => __slab_alloc.isra.81 (ffffffff81221d08) > => kmem_cache_alloc_trace (ffffffff81222568) > => do_execveat_common.isra.34 (ffffffff81245171) > => SyS_execve (ffffffff81245a0c) > => do_syscall_64 (ffffffff8100394c) > => return_from_SYSCALL_64 (ffffffff817c2dd8) > > P.S. the culprit was SLAB_DEBUG that was doing the stack traces > > Signed-off-by: Steven Rostedt (VMware) > --- > diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile > index 81bb565f4497..5d9eb722a04e 100644 > --- a/arch/x86/kernel/Makefile > +++ b/arch/x86/kernel/Makefile > @@ -29,7 +29,6 @@ KASAN_SANITIZE_stacktrace.o := n > KASAN_SANITIZE_paravirt.o := n > > OBJECT_FILES_NON_STANDARD_relocate_kernel_$(BITS).o := y > -OBJECT_FILES_NON_STANDARD_ftrace_$(BITS).o := y > OBJECT_FILES_NON_STANDARD_test_nx.o := y > OBJECT_FILES_NON_STANDARD_paravirt_patch_$(BITS).o := y > > diff --git a/arch/x86/kernel/ftrace_64.S b/arch/x86/kernel/ftrace_64.S > index c832291d948a..6ab3308d632a 100644 > --- a/arch/x86/kernel/ftrace_64.S > +++ b/arch/x86/kernel/ftrace_64.S > @@ -4,6 +4,7 @@ > */ > > #include > +#include > #include > #include > #include > @@ -148,9 +149,10 @@ EXPORT_SYMBOL(mcount) > > ENTRY(function_hook) > retq > -END(function_hook) > +ENDPROC(function_hook) > > ENTRY(ftrace_caller) > + UNWIND_HINT_FUNC > /* save_mcount_regs fills in first two parameters */ > save_mcount_regs > > @@ -165,6 +167,7 @@ GLOBAL(ftrace_call) > call ftrace_stub > > restore_mcount_regs > + UNWIND_HINT_FUNC > > /* > * The copied trampoline must call ftrace_epilogue as it > @@ -187,11 +190,13 @@ WEAK(ftrace_stub) > END(ftrace_caller) > > ENTRY(ftrace_regs_caller) > + UNWIND_HINT_FUNC > /* Save the current flags before any operations that can change them */ > pushfq > > /* added 8 bytes to save flags */ > save_mcount_regs 8 > + UNWIND_HINT_REGS > /* save_mcount_regs fills in first two parameters */ > > GLOBAL(ftrace_regs_caller_op_ptr) > @@ -241,6 +246,7 @@ GLOBAL(ftrace_regs_call) > movq RBX(%rsp), %rbx > > restore_mcount_regs > + UNWIND_HINT_FUNC > > /* Restore flags */ > popfq > @@ -296,6 +302,7 @@ END(function_hook) > > #ifdef CONFIG_FUNCTION_GRAPH_TRACER > ENTRY(ftrace_graph_caller) > + UNWIND_HINT_FUNC > /* Saves rbp into %rdx and fills first parameter */ > save_mcount_regs > > @@ -311,11 +318,13 @@ ENTRY(ftrace_graph_caller) > call prepare_ftrace_return > > restore_mcount_regs > + UNWIND_HINT_FUNC > > retq > END(ftrace_graph_caller) > > GLOBAL(return_to_handler) > + UNWIND_HINT_EMPTY > subq $24, %rsp > > /* Save the return values */ I'm officially on vacation but I got a chance to look at this myself a few minutes ago. This looks mostly right. In theory, you should able to mark those as functions by changing END to ENDPROC. Then you won't need all the UNWIND_HINT_FUNCs. I tried making that change, but objtool thinks the stack frame is still modified when the functions return. I didn't see anything obvious in save_mcount_regs or restore_mcount_regs that should cause it to think that. I'll need to look into it a little more. -- Josh