Re: [PATCH 0/9] TRACE_IRQFLAGS wreckage

From: peterz@infradead.org
To: Steven Rostedt <rostedt@goodmis.org>
Cc: linux-kernel@vger.kernel.org, mingo@kernel.org, will@kernel.org,
	npiggin@gmail.com, elver@google.com, jgross@suse.com,
	paulmck@kernel.org, rjw@rjwysocki.net, joel@joelfernandes.org,
	svens@linux.ibm.com, tglx@linutronix.de
Subject: Re: [PATCH 0/9] TRACE_IRQFLAGS wreckage
Date: Thu, 20 Aug 2020 16:58:21 +0200	[thread overview]
Message-ID: <20200820145821.GA1362448@hirez.programming.kicks-ass.net> (raw)
In-Reply-To: <20200820103643.1b9abe88@oasis.local.home>

On Thu, Aug 20, 2020 at 10:36:43AM -0400, Steven Rostedt wrote:
> 
> I tested this series on top of tip/master and triggered the below
> warning when running the irqsoff tracer boot up test (config attached).
> 
> -- Steve
> 
>  Testing tracer irqsoff: 
>  
>  =============================
>  WARNING: suspicious RCU usage
>  5.9.0-rc1-test+ #92 Not tainted
>  -----------------------------
>  include/trace/events/lock.h:13 suspicious rcu_dereference_check() usage!
>  
>  other info that might help us debug this:
>  
>  
>  rcu_scheduler_active = 2, debug_locks = 1
>  RCU used illegally from extended quiescent state!
>  no locks held by swapper/2/0.
>  
>  stack backtrace:
>  CPU: 2 PID: 0 Comm: swapper/2 Not tainted 5.9.0-rc1-test+ #92
>  Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
>  Call Trace:
>   dump_stack+0x8d/0xc0
>   lock_acquire.cold+0x23/0x2c
>   ? default_idle_call+0x4d/0x210
>   _raw_spin_lock_irqsave+0x50/0xa0
>   ? check_critical_timing+0x69/0x160
>   check_critical_timing+0x69/0x160
>   ? default_idle_call+0x4d/0x210
>   stop_critical_timings+0xdd/0xf0
>   default_idle_call+0x4d/0x210
>   do_idle+0x1f6/0x260
>   cpu_startup_entry+0x19/0x20
>   start_secondary+0x110/0x140
>   secondary_startup_64+0xb6/0xc0

Shiny, I think that wants something like the below, but let me go frob
my config and test it.

---

--- a/drivers/cpuidle/cpuidle.c
+++ b/drivers/cpuidle/cpuidle.c
@@ -151,8 +151,8 @@ static void enter_s2idle_proper(struct c
 	 * cpuidle mechanism enables interrupts and doing that with timekeeping
 	 * suspended is generally unsafe.
 	 */
-	rcu_idle_enter();
 	stop_critical_timings();
+	rcu_idle_enter();
 	drv->states[index].enter_s2idle(dev, drv, index);
 	if (WARN_ON_ONCE(!irqs_disabled()))
 		local_irq_disable();
@@ -164,8 +164,8 @@ static void enter_s2idle_proper(struct c
 	 * FIXME, order against rcu_idle_exit ?
 	 */
 	RCU_NONIDLE(tick_unfreeze());
-	start_critical_timings();
 	rcu_idle_exit();
+	start_critical_timings();
 
 	time_end = ns_to_ktime(local_clock());
 
@@ -236,11 +236,11 @@ int cpuidle_enter_state(struct cpuidle_d
 	trace_cpu_idle(index, dev->cpu);
 	time_start = ns_to_ktime(local_clock());
 
-	rcu_idle_enter();
 	stop_critical_timings();
+	rcu_idle_enter();
 	entered_state = target_state->enter(dev, drv, index);
-	start_critical_timings();
 	rcu_idle_exit();
+	start_critical_timings();
 
 	sched_clock_idle_wakeup_event();
 	time_end = ns_to_ktime(local_clock());
--- a/kernel/sched/idle.c
+++ b/kernel/sched/idle.c
@@ -55,16 +55,16 @@ __setup("hlt", cpu_idle_nopoll_setup);
 static noinline int __cpuidle cpu_idle_poll(void)
 {
 	trace_cpu_idle(0, smp_processor_id());
+	stop_critical_timings();
 	rcu_idle_enter();
 	local_irq_enable();
-	stop_critical_timings();
 
 	while (!tif_need_resched() &&
 	       (cpu_idle_force_poll || tick_check_broadcast_expired()))
 		cpu_relax();
 
-	start_critical_timings();
 	rcu_idle_exit();
+	start_critical_timings();
 	trace_cpu_idle(PWR_EVENT_EXIT, smp_processor_id());
 
 	return 1;
@@ -91,11 +91,11 @@ void __cpuidle default_idle_call(void)
 	if (current_clr_polling_and_test()) {
 		local_irq_enable();
 	} else {
-		rcu_idle_enter();
 		stop_critical_timings();
+		rcu_idle_enter();
 		arch_cpu_idle();
-		start_critical_timings();
 		rcu_idle_exit();
+		start_critical_timings();
 	}
 }
 
