From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932520AbcH1Xua (ORCPT ); Sun, 28 Aug 2016 19:50:30 -0400 Received: from mail.kernel.org ([198.145.29.136]:49002 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752228AbcH1Xu3 (ORCPT ); Sun, 28 Aug 2016 19:50:29 -0400 Date: Mon, 29 Aug 2016 08:50:03 +0900 From: Masami Hiramatsu To: Binoy Jayan Cc: Arnd Bergmann , linaro-kernel@lists.linaro.org, Daniel Wagner , Carsten Emde , Linux kernel mailing list , "Steven Rostedt (Red Hat)" Subject: Re: [PATCH v2 1/3] tracing: Deference pointers without RCU checks Message-Id: <20160829085003.15103ac1f1ba20251d3fe01c@kernel.org> In-Reply-To: References: <1472037450-8907-1-git-send-email-binoy.jayan@linaro.org> <1472037450-8907-2-git-send-email-binoy.jayan@linaro.org> <20160826104913.71b0200cde155220cf5d5c00@kernel.org> X-Mailer: Sylpheed 3.5.0 (GTK+ 2.24.30; x86_64-redhat-linux-gnu) Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hi Binoy, On Fri, 26 Aug 2016 10:56:12 +0530 Binoy Jayan wrote: > On 26 August 2016 at 07:19, Masami Hiramatsu wrote: > > On Wed, 24 Aug 2016 16:47:28 +0530 > >> "__local_bh_enable() tests if this is the last SOFTIRQ_OFFSET, if so it > >> tells lockdep softirqs are enabled with trace_softirqs_on() after that > >> we go an actually modify the preempt_count with preempt_count_sub(). > >> Then in preempt_count_sub() you call into trace_preempt_on() if this > >> was the last preempt_count increment but you do that _before_ you > >> actually change the preempt_count with __preempt_count_sub() at this > >> point lockdep and preempt_count think the world differs and *boom*" > >> > >> So the simplest way to avoid this is by disabling the consistency > >> checks. > >> > >> We also need to take care of the iterating in trace_events_trigger.c > >> to avoid a splatter in conjunction with the hist trigger. > > > > Special care for lockdep inside tracepoint handler is reasonable. > > > > Reviewed-by: Masami Hiramatsu > > > > Steven, since this seems a bugfix, could you pick this from the series? > > > > Thank you, > > > > -- > > Masami Hiramatsu > > > Hi Daniel/Masami, > > I ran into a similar rcu error while using same tracepoint for all > three latency types > and using a filter like below to trigger only events falling under a > specific type. > > echo 'hist:key=ltype,cpu:val=latency:sort=ltype,cpu if ltype==0' > \ > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger > > The error occurs only when I use the predicate 'if ltype==0' as filter. > > It occurs in 'filter_match_preds' during a call to 'rcu_dereference_sched'. > kernel/trace/trace_events_filter.c +611 : filter_match_preds() > > Surprisingly, this happens only the first time the echo command is used on > the trigger file after each boot. > > Do you think it is similar to the bug you have fixed? May be i'll try using > "rcu_dereference_raw_notrace" instead of 'rcu_dereference_sched'. Yes, I think we should fix that too. No rcu_derefaernce_sched used in trace callees. (except for kprobe events, since it is out of context) Thank you, > > Binoy > > > [ 1029.324257] =============================== > [ 1029.324785] [ INFO: suspicious RCU usage. ] > [ 1029.328698] 4.7.0+ #49 Not tainted > [ 1029.332858] ------------------------------- > [ 1029.336334] /local/mnt/workspace/src/korg/linux/kernel/trace/trace_events_filter.c:611 > suspicious rcu_dereference_check() usage! > [ 1029.340423] > [ 1029.340423] other info that might help us debug this: > [ 1029.340423] > [ 1029.352226] > [ 1029.352226] RCU used illegally from idle CPU! > [ 1029.352226] rcu_scheduler_active = 1, debug_locks = 0 > [ 1029.359953] RCU used illegally from extended quiescent state! > [ 1029.371057] no locks held by swapper/0/0. > [ 1029.376696] > [ 1029.376696] stack backtrace: > [ 1029.380693] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.7.0+ #49 > [ 1029.385033] Hardware name: Qualcomm Technologies, Inc. APQ 8016 SBC (DT) > [ 1029.391111] Call trace: > [ 1029.397798] [] dump_backtrace+0x0/0x1e0 > [ 1029.399967] [] show_stack+0x24/0x2c > [ 1029.405523] [] dump_stack+0xb0/0xf0 > [ 1029.410557] [] lockdep_rcu_suspicious+0xe8/0x120 > [ 1029.415595] [] filter_match_preds+0x108/0x118 > [ 1029.421669] [] event_triggers_call+0x5c/0xc0 > [ 1029.427485] [] trace_event_buffer_commit+0x11c/0x244 > [ 1029.433390] [] > trace_event_raw_event_latency_template+0x58/0xa4 > [ 1029.439902] [] time_hardirqs_on+0x264/0x290 > [ 1029.447450] [] trace_hardirqs_on_caller+0x20/0x180 > [ 1029.453179] [] trace_hardirqs_on+0x10/0x18 > [ 1029.459604] [] cpuidle_enter_state+0xc8/0x2e0 > [ 1029.465246] [] cpuidle_enter+0x34/0x40 > [ 1029.470888] [] call_cpuidle+0x3c/0x5c > [ 1029.476442] [] cpu_startup_entry+0x1c0/0x360 > [ 1029.481392] [] rest_init+0x150/0x160 > [ 1029.487293] [] start_kernel+0x3a4/0x3b8 > [ 1029.492415] [] __primary_switched+0x30/0x74 > > Binoy -- Masami Hiramatsu