Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755006Ab3C2Drv (ORCPT ); Thu, 28 Mar 2013 23:47:51 -0400 Received: from mx1.redhat.com ([209.132.183.28]:54716 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754885Ab3C2Dru (ORCPT ); Thu, 28 Mar 2013 23:47:50 -0400 Message-ID: <51550ED9.7020407@redhat.com> Date: Fri, 29 Mar 2013 11:47:37 +0800 From: WANG Chao User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:17.0) Gecko/20130311 Thunderbird/17.0.4 MIME-Version: 1.0 To: Steven Rostedt CC: linux-kernel@vger.kernel.org, Ingo Molnar , Andrew Morton , Frederic Weisbecker , "zhangwei(Jovi)" Subject: Re: [PATCH 3/3] ftrace: Do not call stub functions in control loop References: <20130328125214.132479321@goodmis.org> <20130328125232.760699684@goodmis.org> In-Reply-To: <20130328125232.760699684@goodmis.org> Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 6505 Lines: 130 On 03/28/2013 08:52 PM, Steven Rostedt wrote: > From: "Steven Rostedt (Red Hat)" > > The function tracing control loop used by perf spits out a warning > if the called function is not a control function. This is because > the control function references a per cpu allocated data structure > on struct ftrace_ops that is not allocated for other types of > functions. > > commit 0a016409e42 "ftrace: Optimize the function tracer list loop" > > Had an optimization done to all function tracing loops to optimize > for a single registered ops. Unfortunately, this allows for a slight > race when tracing starts or ends, where the stub function might be > called after the current registered ops is removed. In this case we > get the following dump: > > root# perf stat -e ftrace:function sleep 1 > [ 74.339105] WARNING: at include/linux/ftrace.h:209 ftrace_ops_control_func+0xde/0xf0() > [ 74.349522] Hardware name: PRIMERGY RX200 S6 > [ 74.357149] Modules linked in: sg igb iTCO_wdt ptp pps_core iTCO_vendor_support i7core_edac dca lpc_ich i2c_i801 coretemp edac_core crc32c_intel mfd_core ghash_clmulni_intel dm_multipath acpi_power_meter pcspk > r microcode vhost_net tun macvtap macvlan nfsd kvm_intel kvm auth_rpcgss nfs_acl lockd sunrpc uinput xfs libcrc32c sd_mod crc_t10dif sr_mod cdrom mgag200 i2c_algo_bit drm_kms_helper ttm qla2xxx mptsas ahci drm li > bahci scsi_transport_sas mptscsih libata scsi_transport_fc i2c_core mptbase scsi_tgt dm_mirror dm_region_hash dm_log dm_mod > [ 74.446233] Pid: 1377, comm: perf Tainted: G W 3.9.0-rc1 #1 > [ 74.453458] Call Trace: > [ 74.456233] [] warn_slowpath_common+0x7f/0xc0 > [ 74.462997] [] ? rcu_note_context_switch+0xa0/0xa0 > [ 74.470272] [] ? __unregister_ftrace_function+0xa2/0x1a0 > [ 74.478117] [] warn_slowpath_null+0x1a/0x20 > [ 74.484681] [] ftrace_ops_control_func+0xde/0xf0 > [ 74.491760] [] ftrace_call+0x5/0x2f > [ 74.497511] [] ? ftrace_call+0x5/0x2f > [ 74.503486] [] ? ftrace_call+0x5/0x2f > [ 74.509500] [] ? synchronize_sched+0x5/0x50 > [ 74.516088] [] ? _cond_resched+0x5/0x40 > [ 74.522268] [] ? synchronize_sched+0x5/0x50 > [ 74.528837] [] ? __unregister_ftrace_function+0xa2/0x1a0 > [ 74.536696] [] ? _cond_resched+0x5/0x40 > [ 74.542878] [] ? mutex_lock+0x1d/0x50 > [ 74.548869] [] unregister_ftrace_function+0x27/0x50 > [ 74.556243] [] perf_ftrace_event_register+0x9f/0x140 > [ 74.563709] [] ? _cond_resched+0x5/0x40 > [ 74.569887] [] ? mutex_lock+0x1d/0x50 > [ 74.575898] [] perf_trace_destroy+0x2e/0x50 > [ 74.582505] [] tp_perf_event_destroy+0x9/0x10 > [ 74.589298] [] free_event+0x70/0x1a0 > [ 74.595208] [] perf_event_release_kernel+0x69/0xa0 > [ 74.602460] [] ? _cond_resched+0x5/0x40 > [ 74.608667] [] put_event+0x90/0xc0 > [ 74.614373] [] perf_release+0x10/0x20 > [ 74.620367] [] __fput+0xf4/0x280 > [ 74.625894] [] ____fput+0xe/0x10 > [ 74.631387] [] task_work_run+0xa7/0xe0 > [ 74.637452] [] do_notify_resume+0x71/0xb0 > [ 74.643843] [] int_signal+0x12/0x17 > > To fix this a new ftrace_ops flag is added that denotes the ftrace_list_end > ftrace_ops stub as just that, a stub. This flag is now checked in the > control loop and the function is not called if the flag is set. > > Thanks to Jovi for not just reporting the bug, but also pointing out > where the bug was in the code. > > Link: http://lkml.kernel.org/r/514A8855.7090402@redhat.com > Link: http://lkml.kernel.org/r/1364377499-1900-15-git-send-email-jovi.zhangwei@huawei.com > > Reported-by: WANG Chao > Reported-by: zhangwei(Jovi) > Signed-off-by: Steven Rostedt > --- > include/linux/ftrace.h | 2 ++ > kernel/trace/ftrace.c | 5 +++-- > 2 files changed, 5 insertions(+), 2 deletions(-) > > diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h > index e5ca8ef..167abf9 100644 > --- a/include/linux/ftrace.h > +++ b/include/linux/ftrace.h > @@ -89,6 +89,7 @@ typedef void (*ftrace_func_t)(unsigned long ip, unsigned long parent_ip, > * that the call back has its own recursion protection. If it does > * not set this, then the ftrace infrastructure will add recursion > * protection for the caller. > + * STUB - The ftrace_ops is just a place holder. > */ > enum { > FTRACE_OPS_FL_ENABLED = 1 << 0, > @@ -98,6 +99,7 @@ enum { > FTRACE_OPS_FL_SAVE_REGS = 1 << 4, > FTRACE_OPS_FL_SAVE_REGS_IF_SUPPORTED = 1 << 5, > FTRACE_OPS_FL_RECURSION_SAFE = 1 << 6, > + FTRACE_OPS_FL_STUB = 1 << 7, > }; > > struct ftrace_ops { > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c > index cc4943c..7e89710 100644 > --- a/kernel/trace/ftrace.c > +++ b/kernel/trace/ftrace.c > @@ -66,7 +66,7 @@ > > static struct ftrace_ops ftrace_list_end __read_mostly = { > .func = ftrace_stub, > - .flags = FTRACE_OPS_FL_RECURSION_SAFE, > + .flags = FTRACE_OPS_FL_RECURSION_SAFE | FTRACE_OPS_FL_STUB, > }; > > /* ftrace_enabled is a method to turn ftrace on or off */ > @@ -4131,7 +4131,8 @@ ftrace_ops_control_func(unsigned long ip, unsigned long parent_ip, > preempt_disable_notrace(); > trace_recursion_set(TRACE_CONTROL_BIT); > do_for_each_ftrace_op(op, ftrace_control_list) { > - if (!ftrace_function_local_disabled(op) && > + if (!(op->flags & FTRACE_OPS_FL_STUB) && > + !ftrace_function_local_disabled(op) && > ftrace_ops_test(op, ip)) > op->func(ip, parent_ip, op, regs); > } while_for_each_ftrace_op(op); > Tested this patch on top of 3.9-rc4 and didn't see this issue any more. Tested by WANG Chao Thanks for the fix. WANG Chao -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/