From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751490AbdF0NyH (ORCPT ); Tue, 27 Jun 2017 09:54:07 -0400 Received: from mail.kernel.org ([198.145.29.99]:33468 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750829AbdF0NyA (ORCPT ); Tue, 27 Jun 2017 09:54:00 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 7C65E214D7 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=kernel.org Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=mhiramat@kernel.org Date: Tue, 27 Jun 2017 22:53:56 +0900 From: Masami Hiramatsu To: Steven Rostedt Cc: linux-kernel@vger.kernel.org, "Paul E. McKenney" Subject: Re: [BUG] ftrace: WARNING: suspicious RCU usage Message-Id: <20170627225356.318f81d3c687973b7f4f49b1@kernel.org> In-Reply-To: <20170627092926.0d712e3a@gandalf.local.home> References: <20170627205126.6c5261d10472539b528ca144@kernel.org> <20170627092926.0d712e3a@gandalf.local.home> X-Mailer: Sylpheed 3.5.0 (GTK+ 2.24.31; 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 On Tue, 27 Jun 2017 09:29:26 -0400 Steven Rostedt wrote: > On Tue, 27 Jun 2017 20:51:26 +0900 > Masami Hiramatsu wrote: > > > Hello Steve, > > > > I've faced the following RCU warning while I ran ftracetest testcase > > "ftrace - function graph filters with stack tracer" on qemu. > > The kernel is ftrace/core branch. > > > > [ 10.919174] ============================= > > [ 10.920077] WARNING: suspicious RCU usage > > [ 10.920977] 4.12.0-rc5+ #1 Not tainted > > [ 10.921828] ----------------------------- > > [ 10.922748] /home/mhiramat/ksrc/linux/include/trace/events/rcu.h:454 suspicious rcu_dereference_check() usage! > > [ 10.924761] > > [ 10.924761] other info that might help us debug this: > > [ 10.924761] > > [ 10.926775] > > [ 10.926775] RCU used illegally from idle CPU! > > [ 10.926775] rcu_scheduler_active = 2, debug_locks = 1 > > [ 10.929176] RCU used illegally from extended quiescent state! > > [ 10.930525] no locks held by swapper/7/0. > > [ 10.931547] > > [ 10.931547] stack backtrace: > > [ 10.932777] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1 > > [ 10.934025] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014 > > [ 10.935869] Call Trace: > > [ 10.936550] dump_stack+0x86/0xcf > > [ 10.937359] lockdep_rcu_suspicious+0xc5/0x100 > > [ 10.938327] ? rcu_eqs_exit_common.isra.53+0x5/0x150 > > > [ 10.939229] rcu_irq_enter+0x18d/0x1a0 > > Strange, it triggered in rcu_irq_enter()? > > > [ 10.939902] ? rcu_eqs_exit_common.isra.53+0x5/0x150 > > [ 10.940683] check_stack+0xbb/0x2f0 > > [ 10.941333] stack_trace_call+0x3f/0x50 > > [ 10.942010] 0xffffffffa0000077 > > [ 10.942620] ? ftrace_graph_caller+0x78/0xa8 > > [ 10.943342] ? rcu_eqs_exit_common.isra.53+0x5/0x150 > > [ 10.944214] ? rcu_idle_exit+0x5/0x90 > > > [ 10.944937] rcu_eqs_exit_common.isra.53+0x5/0x150 > > Hmm, we are tracing rcu_eqs_exit_common. > > > Do you have this commit in this branch? > > Commit 03ecd3f4 "rcu/tracing: Add rcu_disabled to denote when > rcu_irq_enter() will not work" Yes, that is merged. Hmm, I'll check this is correctly enabled again, since this time I couldn't reproduce it. Thank you, > > -- Steve > > > [ 10.945754] rcu_idle_exit+0x8c/0x90 > > [ 10.946612] ? rcu_eqs_exit_common.isra.53+0x5/0x150 > > [ 10.947414] ? rcu_idle_exit+0x8c/0x90 > > [ 10.948091] do_idle+0x116/0x1c0 > > [ 10.948797] cpu_startup_entry+0x1d/0x20 > > [ 10.949569] start_secondary+0xfa/0x100 > > [ 10.950335] secondary_startup_64+0x9f/0x9f > > [ 10.951182] > > > > I attached full log and kconfig. I can reproduce it with just running > > following script. > > > > ---- > > cd tools/testing/selftests/ftrace > > while true; do > > ./ftracetest test.d/ftrace/fgraph-filter-stack.tc > > done > > ---- > > > > Thank you, > > > -- Masami Hiramatsu