Skip to contentSkip to conversation

RCU_USER_QS traces.

DISCUSSION Dave Jones 3 participants 4 messages Oct 4, 2012 – Oct 5, 2012

lore
Share & tools
lore

Dave Jones

author
#0 lore raw
Quoted 4 lines

We have CONFIG_RCU_USER_QS that is a specific case. It's an intermediate state before we implement a true CONFIG_NO_HZ_FULL. But the option is useless on its own for users. Worse, it introduces a real overhead. OTOH we want it to be upstream to make the development of full tickless feature more incremental.

I couldn't resist trying it.. Did these get reported yet ?

WARNING: at kernel/rcutree.c:377 rcu_eqs_enter+0x93/0xa0()
Pid: 0, comm: swapper/1 Not tainted 3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a383>] rcu_eqs_enter+0x93/0xa0
 [<ffffffff8111af0b>] rcu_idle_enter+0x2b/0x70
 [<ffffffff8102460f>] cpu_idle+0xbf/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

WARNING: at kernel/rcutree.c:352 rcu_eqs_enter_common.isra.37+0x1c6/0x1e0()
Pid: 0, comm: swapper/1 Tainted: G        W    3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a2d6>] rcu_eqs_enter_common.isra.37+0x1c6/0x1e0
 [<ffffffff8111a355>] rcu_eqs_enter+0x65/0xa0
 [<ffffffff8111af0b>] rcu_idle_enter+0x2b/0x70
 [<ffffffff8102460f>] cpu_idle+0xbf/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

WARNING: at kernel/rcutree.c:539 rcu_eqs_exit+0x99/0xb0()
Pid: 0, comm: swapper/1 Tainted: G        W    3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a0f9>] rcu_eqs_exit+0x99/0xb0
 [<ffffffff8111ae9b>] rcu_idle_exit+0x2b/0x70
 [<ffffffff8102461e>] cpu_idle+0xce/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

WARNING: at kernel/rcutree.c:513 rcu_eqs_exit_common.isra.35+0xd4/0xe0()
Pid: 0, comm: swapper/1 Tainted: G        W    3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a054>] rcu_eqs_exit_common.isra.35+0xd4/0xe0
 [<ffffffff8111a0bc>] rcu_eqs_exit+0x5c/0xb0
 [<ffffffff8111ae9b>] rcu_idle_exit+0x2b/0x70
 [<ffffffff8102461e>] cpu_idle+0xce/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

Dave

#1 lore raw
Quoted 6 lines · Dave Jones
Quoted 4 lines

We have CONFIG_RCU_USER_QS that is a specific case. It's an intermediate state before we implement a true CONFIG_NO_HZ_FULL. But the option is useless on its own for users. Worse, it introduces a real overhead. OTOH we want it to be upstream to make the development of full tickless feature more incremental.

I couldn't resist trying it.. Did these get reported yet ?

News to me... Thank you for the testing!

And yes, please do not enable CONFIG_RCU_USER_QS in your distro. ;-)

Thanx, Paul

Quoted 44 lines
WARNING: at kernel/rcutree.c:377 rcu_eqs_enter+0x93/0xa0()
Pid: 0, comm: swapper/1 Not tainted 3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a383>] rcu_eqs_enter+0x93/0xa0
 [<ffffffff8111af0b>] rcu_idle_enter+0x2b/0x70
 [<ffffffff8102460f>] cpu_idle+0xbf/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

WARNING: at kernel/rcutree.c:352 rcu_eqs_enter_common.isra.37+0x1c6/0x1e0()
Pid: 0, comm: swapper/1 Tainted: G        W    3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a2d6>] rcu_eqs_enter_common.isra.37+0x1c6/0x1e0
 [<ffffffff8111a355>] rcu_eqs_enter+0x65/0xa0
 [<ffffffff8111af0b>] rcu_idle_enter+0x2b/0x70
 [<ffffffff8102460f>] cpu_idle+0xbf/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

WARNING: at kernel/rcutree.c:539 rcu_eqs_exit+0x99/0xb0()
Pid: 0, comm: swapper/1 Tainted: G        W    3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a0f9>] rcu_eqs_exit+0x99/0xb0
 [<ffffffff8111ae9b>] rcu_idle_exit+0x2b/0x70
 [<ffffffff8102461e>] cpu_idle+0xce/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

WARNING: at kernel/rcutree.c:513 rcu_eqs_exit_common.isra.35+0xd4/0xe0()
Pid: 0, comm: swapper/1 Tainted: G        W    3.6.0+ #24
Call Trace:
 [<ffffffff810678af>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8106790a>] warn_slowpath_null+0x1a/0x20
 [<ffffffff8111a054>] rcu_eqs_exit_common.isra.35+0xd4/0xe0
 [<ffffffff8111a0bc>] rcu_eqs_exit+0x5c/0xb0
 [<ffffffff8111ae9b>] rcu_idle_exit+0x2b/0x70
 [<ffffffff8102461e>] cpu_idle+0xce/0x140
 [<ffffffff816ad18d>] start_secondary+0x252/0x254

Dave

#2 lore raw
In reply to Dave Jones
Quoted 6 lines · Dave Jones
Quoted 4 lines

We have CONFIG_RCU_USER_QS that is a specific case. It's an intermediate state before we implement a true CONFIG_NO_HZ_FULL. But the option is useless on its own for users. Worse, it introduces a real overhead. OTOH we want it to be upstream to make the development of full tickless feature more incremental.

I couldn't resist trying it.. Did these get reported yet ?

Hi Dave,

Thanks for this report. I need to find the source of the issue.

If you don't mind, could you please apply the following patch? You'll also need to enable:

- CONFIG_EVENT_TRACING and CONFIG_RCU_TRACE

And you also need this boot parameter:

- trace_event=rcu_dyntick

Thanks a lot!

---

Quoted 1 line

From 824f2ef855597d6dd263bb363727e4585db88ca3 Mon Sep 17 00:00:00 2001

From: Frederic Weisbecker <[email protected]>
Date: Thu, 4 Oct 2012 17:30:36 +0200
Subject: [PATCH] rcu: Dump rcu traces and stacktraces on dynticks warnings

Temp patch for debugging.

Signed-off-by Frederic Weisbecker <[email protected]>
---
 kernel/rcutree.c |   38 ++++++++++++++++++++++++--------------
 1 files changed, 24 insertions(+), 14 deletions(-)
kernel/rcutree.c +24 -14
index 4fb2376..1bc96fd 100644
@@ -59,6 +59,12 @@
 
 #include "rcu.h"
 
+#define trace_rcu_dyntick_stacktrace(...) {	\
+	trace_rcu_dyntick(__VA_ARGS__);	   \
+	trace_dump_stack();\
+}
+
+
 /* Data structures. */
 
 static struct lock_class_key rcu_node_class[RCU_NUM_LVLS];

@@ -334,11 +340,11 @@ static struct rcu_node *rcu_get_root(struct rcu_state *rsp)
 static void rcu_eqs_enter_common(struct rcu_dynticks *rdtp, long long oldval,
 				bool user)
 {
-	trace_rcu_dyntick("Start", oldval, 0);
+	trace_rcu_dyntick_stacktrace("Start", oldval, 0);
 	if (!user && !is_idle_task(current)) {
 		struct task_struct *idle = idle_task(smp_processor_id());
 
-		trace_rcu_dyntick("Error on entry: not idle task", oldval, 0);
+		trace_rcu_dyntick_stacktrace("Error on entry: not idle task", oldval, 0);
 		ftrace_dump(DUMP_ORIG);
 		WARN_ONCE(1, "Current pid: %d comm: %s / Idle pid: %d comm: %s",
 			  current->pid, current->comm,

@@ -349,7 +355,8 @@ static void rcu_eqs_enter_common(struct rcu_dynticks *rdtp, long long oldval,
 	smp_mb__before_atomic_inc();  /* See above. */
 	atomic_inc(&rdtp->dynticks);
 	smp_mb__after_atomic_inc();  /* Force ordering with next sojourn. */
-	WARN_ON_ONCE(atomic_read(&rdtp->dynticks) & 0x1);
+	if (WARN_ON_ONCE(atomic_read(&rdtp->dynticks) & 0x1))
+		ftrace_dump(DUMP_ORIG);
 
 	/*
 	 * It is illegal to enter an extended quiescent state while

@@ -374,7 +381,8 @@ static void rcu_eqs_enter(bool user)
 
 	rdtp = &__get_cpu_var(rcu_dynticks);
 	oldval = rdtp->dynticks_nesting;
-	WARN_ON_ONCE((oldval & DYNTICK_TASK_NEST_MASK) == 0);
+	if (WARN_ON_ONCE((oldval & DYNTICK_TASK_NEST_MASK) == 0))
+		ftrace_dump(DUMP_ORIG);
 	if ((oldval & DYNTICK_TASK_NEST_MASK) == DYNTICK_TASK_NEST_VALUE)
 		rdtp->dynticks_nesting = 0;
 	else

@@ -489,9 +497,9 @@ void rcu_irq_exit(void)
 	oldval = rdtp->dynticks_nesting;
 	rdtp->dynticks_nesting--;
 	WARN_ON_ONCE(rdtp->dynticks_nesting < 0);
-	if (rdtp->dynticks_nesting)
-		trace_rcu_dyntick("--=", oldval, rdtp->dynticks_nesting);
-	else
+	if (rdtp->dynticks_nesting) {
+		trace_rcu_dyntick_stacktrace("--=", oldval, rdtp->dynticks_nesting);
+	} else
 		rcu_eqs_enter_common(rdtp, oldval, true);
 	local_irq_restore(flags);
 }

@@ -510,13 +518,14 @@ static void rcu_eqs_exit_common(struct rcu_dynticks *rdtp, long long oldval,
 	atomic_inc(&rdtp->dynticks);
 	/* CPUs seeing atomic_inc() must see later RCU read-side crit sects */
 	smp_mb__after_atomic_inc();  /* See above. */
-	WARN_ON_ONCE(!(atomic_read(&rdtp->dynticks) & 0x1));
+	if (WARN_ON_ONCE(!(atomic_read(&rdtp->dynticks) & 0x1)))
+		ftrace_dump(DUMP_ORIG);
 	rcu_cleanup_after_idle(smp_processor_id());
-	trace_rcu_dyntick("End", oldval, rdtp->dynticks_nesting);
+	trace_rcu_dyntick_stacktrace("End", oldval, rdtp->dynticks_nesting);
 	if (!user && !is_idle_task(current)) {
 		struct task_struct *idle = idle_task(smp_processor_id());
 
-		trace_rcu_dyntick("Error on exit: not idle task",
+		trace_rcu_dyntick_stacktrace("Error on exit: not idle task",
 				  oldval, rdtp->dynticks_nesting);
 		ftrace_dump(DUMP_ORIG);
 		WARN_ONCE(1, "Current pid: %d comm: %s / Idle pid: %d comm: %s",

@@ -536,7 +545,8 @@ static void rcu_eqs_exit(bool user)
 
 	rdtp = &__get_cpu_var(rcu_dynticks);
 	oldval = rdtp->dynticks_nesting;
-	WARN_ON_ONCE(oldval < 0);
+	if (WARN_ON_ONCE(oldval < 0))
+		ftrace_dump(DUMP_ORIG);
 	if (oldval & DYNTICK_TASK_NEST_MASK)
 		rdtp->dynticks_nesting += DYNTICK_TASK_NEST_VALUE;
 	else

@@ -650,9 +660,9 @@ void rcu_irq_enter(void)
 	oldval = rdtp->dynticks_nesting;
 	rdtp->dynticks_nesting++;
 	WARN_ON_ONCE(rdtp->dynticks_nesting == 0);
-	if (oldval)
-		trace_rcu_dyntick("++=", oldval, rdtp->dynticks_nesting);
-	else
+	if (oldval) {
+		trace_rcu_dyntick_stacktrace("++=", oldval, rdtp->dynticks_nesting);
+	} else
 		rcu_eqs_exit_common(rdtp, oldval, true);
 	local_irq_restore(flags);
 }
Signature · 1 line
1.7.1
author
#3 lore raw
Quoted 15 lines · Frederic Weisbecker
Quoted 6 lines · Dave Jones
Quoted 4 lines

We have CONFIG_RCU_USER_QS that is a specific case. It's an intermediate state before we implement a true CONFIG_NO_HZ_FULL. But the option is useless on its own for users. Worse, it introduces a real overhead. OTOH we want it to be upstream to make the development of full tickless feature more incremental.

I couldn't resist trying it.. Did these get reported yet ?

Hi Dave,

Thanks for this report. I need to find the source of the issue.

If you don't mind, could you please apply the following patch? You'll also need to enable:

Quoted 7 lines

- CONFIG_EVENT_TRACING and CONFIG_RCU_TRACE

And you also need this boot parameter:

- trace_event=rcu_dyntick

Thanks a lot!

Hrmph, it seems to have gone into hiding. I can't reproduce it any more. If it shows about again, I'll get back to you.

Dave