rcu: eqs related warnings in linux-next

rcu: eqs related warnings in linux-next

[Sasha Levin]

Hi all,

While fuzzing with trinity inside a KVM tools guest with the latest linux-next kernel, I've stumbled on the following during boot:

[  199.224369] WARNING: at kernel/rcutree.c:513 rcu_eqs_exit_common+0x4a/0x3a0()
[  199.225307] Pid: 1, comm: init Tainted: G        W    3.6.0-rc7-next-20120928-sasha-00001-g8b2d05d-dirty #13
[  199.226611] Call Trace:
[  199.226951]  [<ffffffff811c8d1a>] ? rcu_eqs_exit_common+0x4a/0x3a0
[  199.227773]  [<ffffffff81108e36>] warn_slowpath_common+0x86/0xb0
[  199.228572]  [<ffffffff81108f25>] warn_slowpath_null+0x15/0x20
[  199.229348]  [<ffffffff811c8d1a>] rcu_eqs_exit_common+0x4a/0x3a0
[  199.230037]  [<ffffffff8117f267>] ? __lock_acquire+0x1c37/0x1ca0
[  199.230037]  [<ffffffff811c936c>] rcu_eqs_exit+0x9c/0xb0
[  199.230037]  [<ffffffff811c940c>] rcu_user_exit+0x8c/0xf0
[  199.230037]  [<ffffffff810a98bb>] do_page_fault+0x1b/0x40
[  199.230037]  [<ffffffff810a2a90>] do_async_page_fault+0x30/0xa0
[  199.230037]  [<ffffffff83a3eea8>] async_page_fault+0x28/0x30
[  199.230037]  [<ffffffff819f357b>] ? debug_object_activate+0x6b/0x1b0
[  199.230037]  [<ffffffff819f3586>] ? debug_object_activate+0x76/0x1b0
[  199.230037]  [<ffffffff8111af13>] ? lock_timer_base.isra.19+0x33/0x70
[  199.230037]  [<ffffffff8111d45f>] mod_timer_pinned+0x9f/0x260
[  199.230037]  [<ffffffff811c5ff4>] rcu_eqs_enter_common+0x894/0x970
[  199.230037]  [<ffffffff839dc2ac>] ? init_post+0x75/0xc8
[  199.230037]  [<ffffffff85abfed5>] ? kernel_init+0x1e1/0x1e1
[  199.230037]  [<ffffffff811c63df>] rcu_eqs_enter+0xaf/0xc0
[  199.230037]  [<ffffffff811c64c5>] rcu_user_enter+0xd5/0x140
[  199.230037]  [<ffffffff8107d0fd>] syscall_trace_leave+0xfd/0x150
[  199.230037]  [<ffffffff83a3f7af>] int_check_syscall_exit_work+0x34/0x3d
[  199.230037] ---[ end trace a582c3a264d5bd1a ]---
[  199.230037]
[  199.230037] =============================================
[  199.230037] [ INFO: possible recursive locking detected ]
[  199.230037] 3.6.0-rc7-next-20120928-sasha-00001-g8b2d05d-dirty #13 Tainted: G        W
[  199.230037] ---------------------------------------------
[  199.230037] init/1 is trying to acquire lock:
[  199.230037]  (&obj_hash[i].lock){-.-.-.}, at: [<ffffffff819f3ad2>] debug_object_assert_init+0x42/0x110
[  199.230037]
[  199.230037] but task is already holding lock:
[  199.230037]  (&obj_hash[i].lock){-.-.-.}, at: [<ffffffff819f357b>] debug_object_activate+0x6b/0x1b0
[  199.230037]
[  199.230037] other info that might help us debug this:
[  199.230037]  Possible unsafe locking scenario:
[  199.230037]
[  199.230037]        CPU0
[  199.230037]        ----
[  199.230037]   lock(&obj_hash[i].lock);
[  199.230037]   lock(&obj_hash[i].lock);
[  199.230037]
[  199.230037]  *** DEADLOCK ***
[  199.230037]
[  199.230037]  May be due to missing lock nesting notation
[  199.230037]
[  199.230037] 2 locks held by init/1:
[  199.230037]  #0:  (&(&base->lock)->rlock){..-.-.}, at: [<ffffffff8111af13>] lock_timer_base.isra.19+0x33/0x70
[  199.230037]  #1:  (&obj_hash[i].lock){-.-.-.}, at: [<ffffffff819f357b>] debug_object_activate+0x6b/0x1b0
[  199.230037]
[  199.230037] stack backtrace:
[  199.230037] Pid: 1, comm: init Tainted: G        W    3.6.0-rc7-next-20120928-sasha-00001-g8b2d05d-dirty #13
[  199.230037] Call Trace:
[  199.230037]  [<ffffffff8117e229>] __lock_acquire+0xbf9/0x1ca0
[  199.230037]  [<ffffffff811400a1>] ? up+0x11/0x50
[  199.230037]  [<ffffffff8110ae3c>] ? console_unlock+0x3cc/0x480
[  199.230037]  [<ffffffff819f0cd8>] ? do_raw_spin_unlock+0xc8/0xe0
[  199.230037]  [<ffffffff811818da>] lock_acquire+0x1aa/0x240
[  199.230037]  [<ffffffff819f3ad2>] ? debug_object_assert_init+0x42/0x110
[  199.230037]  [<ffffffff83a3d9ac>] _raw_spin_lock_irqsave+0x7c/0xc0
[  199.230037]  [<ffffffff819f3ad2>] ? debug_object_assert_init+0x42/0x110
[  199.230037]  [<ffffffff819f3ad2>] debug_object_assert_init+0x42/0x110
[  199.230037]  [<ffffffff8111d866>] del_timer+0x26/0x80
[  199.230037]  [<ffffffff81108e43>] ? warn_slowpath_common+0x93/0xb0
[  199.230037]  [<ffffffff811c6a53>] rcu_cleanup_after_idle+0x23/0x170
[  199.230037]  [<ffffffff811c8d34>] rcu_eqs_exit_common+0x64/0x3a0
[  199.230037]  [<ffffffff8117f267>] ? __lock_acquire+0x1c37/0x1ca0
[  199.230037]  [<ffffffff811c936c>] rcu_eqs_exit+0x9c/0xb0
[  199.230037]  [<ffffffff811c940c>] rcu_user_exit+0x8c/0xf0
[  199.230037]  [<ffffffff810a98bb>] do_page_fault+0x1b/0x40
[  199.230037]  [<ffffffff810a2a90>] do_async_page_fault+0x30/0xa0
[  199.230037]  [<ffffffff83a3eea8>] async_page_fault+0x28/0x30
[  199.230037]  [<ffffffff819f357b>] ? debug_object_activate+0x6b/0x1b0
[  199.230037]  [<ffffffff819f3586>] ? debug_object_activate+0x76/0x1b0
[  199.230037]  [<ffffffff8111af13>] ? lock_timer_base.isra.19+0x33/0x70
[  199.230037]  [<ffffffff8111d45f>] mod_timer_pinned+0x9f/0x260
[  199.230037]  [<ffffffff811c5ff4>] rcu_eqs_enter_common+0x894/0x970
[  199.230037]  [<ffffffff839dc2ac>] ? init_post+0x75/0xc8
[  199.230037]  [<ffffffff85abfed5>] ? kernel_init+0x1e1/0x1e1
[  199.230037]  [<ffffffff811c63df>] rcu_eqs_enter+0xaf/0xc0
[  199.230037]  [<ffffffff811c64c5>] rcu_user_enter+0xd5/0x140
[  199.230037]  [<ffffffff8107d0fd>] syscall_trace_leave+0xfd/0x150
[  199.230037]  [<ffffffff83a3f7af>] int_check_syscall_exit_work+0x34/0x3d

The warning in question is:

	static void rcu_eqs_exit_common(struct rcu_dynticks *rdtp, long long oldval,
	                               int user)
	{
	        smp_mb__before_atomic_inc();  /* Force ordering w/previous sojourn. */
	        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)); <--- This one
	        rcu_cleanup_after_idle(smp_processor_id());
	        trace_rcu_dyntick("End", oldval, rdtp->dynticks_nesting);



Thanks,
Sasha

Re: rcu: eqs related warnings in linux-next

[Frederic Weisbecker]

On Fri, Sep 28, 2012 at 02:51:03PM +0200, Sasha Levin wrote:
> Hi all,
> 
> While fuzzing with trinity inside a KVM tools guest with the latest linux-next kernel, I've stumbled on the following during boot:
> 
> [  199.224369] WARNING: at kernel/rcutree.c:513 rcu_eqs_exit_common+0x4a/0x3a0()
> [  199.225307] Pid: 1, comm: init Tainted: G        W    3.6.0-rc7-next-20120928-sasha-00001-g8b2d05d-dirty #13
> [  199.226611] Call Trace:
> [  199.226951]  [<ffffffff811c8d1a>] ? rcu_eqs_exit_common+0x4a/0x3a0
> [  199.227773]  [<ffffffff81108e36>] warn_slowpath_common+0x86/0xb0
> [  199.228572]  [<ffffffff81108f25>] warn_slowpath_null+0x15/0x20
> [  199.229348]  [<ffffffff811c8d1a>] rcu_eqs_exit_common+0x4a/0x3a0
> [  199.230037]  [<ffffffff8117f267>] ? __lock_acquire+0x1c37/0x1ca0
> [  199.230037]  [<ffffffff811c936c>] rcu_eqs_exit+0x9c/0xb0
> [  199.230037]  [<ffffffff811c940c>] rcu_user_exit+0x8c/0xf0
> [  199.230037]  [<ffffffff810a98bb>] do_page_fault+0x1b/0x40
> [  199.230037]  [<ffffffff810a2a90>] do_async_page_fault+0x30/0xa0
> [  199.230037]  [<ffffffff83a3eea8>] async_page_fault+0x28/0x30
> [  199.230037]  [<ffffffff819f357b>] ? debug_object_activate+0x6b/0x1b0
> [  199.230037]  [<ffffffff819f3586>] ? debug_object_activate+0x76/0x1b0
> [  199.230037]  [<ffffffff8111af13>] ? lock_timer_base.isra.19+0x33/0x70
> [  199.230037]  [<ffffffff8111d45f>] mod_timer_pinned+0x9f/0x260
> [  199.230037]  [<ffffffff811c5ff4>] rcu_eqs_enter_common+0x894/0x970
> [  199.230037]  [<ffffffff839dc2ac>] ? init_post+0x75/0xc8
> [  199.230037]  [<ffffffff85abfed5>] ? kernel_init+0x1e1/0x1e1
> [  199.230037]  [<ffffffff811c63df>] rcu_eqs_enter+0xaf/0xc0
> [  199.230037]  [<ffffffff811c64c5>] rcu_user_enter+0xd5/0x140
> [  199.230037]  [<ffffffff8107d0fd>] syscall_trace_leave+0xfd/0x150
> [  199.230037]  [<ffffffff83a3f7af>] int_check_syscall_exit_work+0x34/0x3d
> [  199.230037] ---[ end trace a582c3a264d5bd1a ]---

We are faulting in the middle of rcu_user_enter() and thus we call rcu_user_exit()
while the whole transition state in rcu_user_enter() is not yet finished (rdtp->dynticks
not incremented).

Not sure how to solve this...

Re: rcu: eqs related warnings in linux-next

[Frederic Weisbecker]

On Fri, Sep 28, 2012 at 02:51:03PM +0200, Sasha Levin wrote:
> Hi all,
> 
> While fuzzing with trinity inside a KVM tools guest with the latest linux-next kernel, I've stumbled on the following during boot:
> 
> [  199.224369] WARNING: at kernel/rcutree.c:513 rcu_eqs_exit_common+0x4a/0x3a0()
> [  199.225307] Pid: 1, comm: init Tainted: G        W    3.6.0-rc7-next-20120928-sasha-00001-g8b2d05d-dirty #13
> [  199.226611] Call Trace:
> [  199.226951]  [<ffffffff811c8d1a>] ? rcu_eqs_exit_common+0x4a/0x3a0
> [  199.227773]  [<ffffffff81108e36>] warn_slowpath_common+0x86/0xb0
> [  199.228572]  [<ffffffff81108f25>] warn_slowpath_null+0x15/0x20
> [  199.229348]  [<ffffffff811c8d1a>] rcu_eqs_exit_common+0x4a/0x3a0
> [  199.230037]  [<ffffffff8117f267>] ? __lock_acquire+0x1c37/0x1ca0
> [  199.230037]  [<ffffffff811c936c>] rcu_eqs_exit+0x9c/0xb0
> [  199.230037]  [<ffffffff811c940c>] rcu_user_exit+0x8c/0xf0
> [  199.230037]  [<ffffffff810a98bb>] do_page_fault+0x1b/0x40
> [  199.230037]  [<ffffffff810a2a90>] do_async_page_fault+0x30/0xa0
> [  199.230037]  [<ffffffff83a3eea8>] async_page_fault+0x28/0x30
> [  199.230037]  [<ffffffff819f357b>] ? debug_object_activate+0x6b/0x1b0
> [  199.230037]  [<ffffffff819f3586>] ? debug_object_activate+0x76/0x1b0
> [  199.230037]  [<ffffffff8111af13>] ? lock_timer_base.isra.19+0x33/0x70
> [  199.230037]  [<ffffffff8111d45f>] mod_timer_pinned+0x9f/0x260
> [  199.230037]  [<ffffffff811c5ff4>] rcu_eqs_enter_common+0x894/0x970
> [  199.230037]  [<ffffffff839dc2ac>] ? init_post+0x75/0xc8
> [  199.230037]  [<ffffffff85abfed5>] ? kernel_init+0x1e1/0x1e1
> [  199.230037]  [<ffffffff811c63df>] rcu_eqs_enter+0xaf/0xc0
> [  199.230037]  [<ffffffff811c64c5>] rcu_user_enter+0xd5/0x140
> [  199.230037]  [<ffffffff8107d0fd>] syscall_trace_leave+0xfd/0x150
> [  199.230037]  [<ffffffff83a3f7af>] int_check_syscall_exit_work+0x34/0x3d
> [  199.230037] ---[ end trace a582c3a264d5bd1a ]---

Ok, we can't decently protect against any kind of exception messing up everything
in the middle of RCU APIs anyway. The only solution is to find out what cause this
page fault in mod_timer_pinned() and work around that.

Anybody, an idea?

Re: rcu: eqs related warnings in linux-next

[Paul E. McKenney]

On Fri, Sep 28, 2012 at 03:36:43PM +0200, Frederic Weisbecker wrote:
> On Fri, Sep 28, 2012 at 02:51:03PM +0200, Sasha Levin wrote:
> > Hi all,
> > 
> > While fuzzing with trinity inside a KVM tools guest with the latest linux-next kernel, I've stumbled on the following during boot:
> > 
> > [  199.224369] WARNING: at kernel/rcutree.c:513 rcu_eqs_exit_common+0x4a/0x3a0()
> > [  199.225307] Pid: 1, comm: init Tainted: G        W    3.6.0-rc7-next-20120928-sasha-00001-g8b2d05d-dirty #13
> > [  199.226611] Call Trace:
> > [  199.226951]  [<ffffffff811c8d1a>] ? rcu_eqs_exit_common+0x4a/0x3a0
> > [  199.227773]  [<ffffffff81108e36>] warn_slowpath_common+0x86/0xb0
> > [  199.228572]  [<ffffffff81108f25>] warn_slowpath_null+0x15/0x20
> > [  199.229348]  [<ffffffff811c8d1a>] rcu_eqs_exit_common+0x4a/0x3a0
> > [  199.230037]  [<ffffffff8117f267>] ? __lock_acquire+0x1c37/0x1ca0
> > [  199.230037]  [<ffffffff811c936c>] rcu_eqs_exit+0x9c/0xb0
> > [  199.230037]  [<ffffffff811c940c>] rcu_user_exit+0x8c/0xf0
> > [  199.230037]  [<ffffffff810a98bb>] do_page_fault+0x1b/0x40
> > [  199.230037]  [<ffffffff810a2a90>] do_async_page_fault+0x30/0xa0
> > [  199.230037]  [<ffffffff83a3eea8>] async_page_fault+0x28/0x30
> > [  199.230037]  [<ffffffff819f357b>] ? debug_object_activate+0x6b/0x1b0
> > [  199.230037]  [<ffffffff819f3586>] ? debug_object_activate+0x76/0x1b0
> > [  199.230037]  [<ffffffff8111af13>] ? lock_timer_base.isra.19+0x33/0x70
> > [  199.230037]  [<ffffffff8111d45f>] mod_timer_pinned+0x9f/0x260
> > [  199.230037]  [<ffffffff811c5ff4>] rcu_eqs_enter_common+0x894/0x970
> > [  199.230037]  [<ffffffff839dc2ac>] ? init_post+0x75/0xc8
> > [  199.230037]  [<ffffffff85abfed5>] ? kernel_init+0x1e1/0x1e1
> > [  199.230037]  [<ffffffff811c63df>] rcu_eqs_enter+0xaf/0xc0
> > [  199.230037]  [<ffffffff811c64c5>] rcu_user_enter+0xd5/0x140
> > [  199.230037]  [<ffffffff8107d0fd>] syscall_trace_leave+0xfd/0x150
> > [  199.230037]  [<ffffffff83a3f7af>] int_check_syscall_exit_work+0x34/0x3d
> > [  199.230037] ---[ end trace a582c3a264d5bd1a ]---
> 
> Ok, we can't decently protect against any kind of exception messing up everything
> in the middle of RCU APIs anyway. The only solution is to find out what cause this
> page fault in mod_timer_pinned() and work around that.
> 
> Anybody, an idea?

Wow...  So I pass mod_timer_pinned() the address of a per-CPU timer while
running on that CPU, with interrupts disabled, no less.  I initialize
this timer at CPU_UP_PREPARE time.  So why the page fault?

Please see below for a severe diagnostic patch.

							Thanx, Paul

------------------------------------------------------------------------

rcu: Exploratory surgery, not for inclusion

Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/kernel/rcutree.h b/kernel/rcutree.h
index 5faf05d..e062d13 100644
--- a/kernel/rcutree.h
+++ b/kernel/rcutree.h
@@ -328,7 +328,7 @@ struct rcu_data {
 #define RCU_FORCE_QS		3	/* Need to force quiescent state. */
 #define RCU_SIGNAL_INIT		RCU_SAVE_DYNTICK
 
-#define RCU_JIFFIES_TILL_FORCE_QS	 3	/* for rsp->jiffies_force_qs */
+#define RCU_JIFFIES_TILL_FORCE_QS	 30	/* for rsp->jiffies_force_qs */
 
 #ifdef CONFIG_PROVE_RCU
 #define RCU_STALL_DELAY_DELTA	       (5 * HZ)
diff --git a/kernel/rcutree_plugin.h b/kernel/rcutree_plugin.h
index f921154..80dfcec 100644
--- a/kernel/rcutree_plugin.h
+++ b/kernel/rcutree_plugin.h
@@ -1742,7 +1742,6 @@ static void rcu_cleanup_after_idle(int cpu)
  */
 static void rcu_prepare_for_idle(int cpu)
 {
-	struct timer_list *tp;
 	struct rcu_dynticks *rdtp = &per_cpu(rcu_dynticks, cpu);
 	int tne;
 
@@ -1772,8 +1771,6 @@ static void rcu_prepare_for_idle(int cpu)
 		} else {
 			return;
 		}
-		tp = &rdtp->idle_gp_timer;
-		mod_timer_pinned(tp, rdtp->idle_gp_timer_expires);
 		return;
 	}
 
@@ -1786,13 +1783,8 @@ static void rcu_prepare_for_idle(int cpu)
 	 * pending.
 	 */
 	if (!rdtp->idle_first_pass &&
-	    (rdtp->nonlazy_posted == rdtp->nonlazy_posted_snap)) {
-		if (rcu_cpu_has_callbacks(cpu)) {
-			tp = &rdtp->idle_gp_timer;
-			mod_timer_pinned(tp, rdtp->idle_gp_timer_expires);
-		}
+	    (rdtp->nonlazy_posted == rdtp->nonlazy_posted_snap))
 		return;
-	}
 	rdtp->idle_first_pass = 0;
 	rdtp->nonlazy_posted_snap = rdtp->nonlazy_posted - 1;
 
@@ -1836,8 +1828,6 @@ static void rcu_prepare_for_idle(int cpu)
 				round_jiffies(jiffies + RCU_IDLE_LAZY_GP_DELAY);
 			trace_rcu_prep_idle("Dyntick with lazy callbacks");
 		}
-		tp = &rdtp->idle_gp_timer;
-		mod_timer_pinned(tp, rdtp->idle_gp_timer_expires);
 		rdtp->nonlazy_posted_snap = rdtp->nonlazy_posted;
 		return; /* Nothing more to do immediately. */
 	} else if (--(rdtp->dyntick_drain) <= 0) {

Re: rcu: eqs related warnings in linux-next

[Sasha Levin]

On 09/28/2012 07:31 PM, Paul E. McKenney wrote:
> On Fri, Sep 28, 2012 at 03:36:43PM +0200, Frederic Weisbecker wrote:
>> > On Fri, Sep 28, 2012 at 02:51:03PM +0200, Sasha Levin wrote:
>>> > > Hi all,
>>> > > 
>>> > > While fuzzing with trinity inside a KVM tools guest with the latest linux-next kernel, I've stumbled on the following during boot:
>>> > > 
>>> > > [  199.224369] WARNING: at kernel/rcutree.c:513 rcu_eqs_exit_common+0x4a/0x3a0()
>>> > > [  199.225307] Pid: 1, comm: init Tainted: G        W    3.6.0-rc7-next-20120928-sasha-00001-g8b2d05d-dirty #13
>>> > > [  199.226611] Call Trace:
>>> > > [  199.226951]  [<ffffffff811c8d1a>] ? rcu_eqs_exit_common+0x4a/0x3a0
>>> > > [  199.227773]  [<ffffffff81108e36>] warn_slowpath_common+0x86/0xb0
>>> > > [  199.228572]  [<ffffffff81108f25>] warn_slowpath_null+0x15/0x20
>>> > > [  199.229348]  [<ffffffff811c8d1a>] rcu_eqs_exit_common+0x4a/0x3a0
>>> > > [  199.230037]  [<ffffffff8117f267>] ? __lock_acquire+0x1c37/0x1ca0
>>> > > [  199.230037]  [<ffffffff811c936c>] rcu_eqs_exit+0x9c/0xb0
>>> > > [  199.230037]  [<ffffffff811c940c>] rcu_user_exit+0x8c/0xf0
>>> > > [  199.230037]  [<ffffffff810a98bb>] do_page_fault+0x1b/0x40
>>> > > [  199.230037]  [<ffffffff810a2a90>] do_async_page_fault+0x30/0xa0
>>> > > [  199.230037]  [<ffffffff83a3eea8>] async_page_fault+0x28/0x30
>>> > > [  199.230037]  [<ffffffff819f357b>] ? debug_object_activate+0x6b/0x1b0
>>> > > [  199.230037]  [<ffffffff819f3586>] ? debug_object_activate+0x76/0x1b0
>>> > > [  199.230037]  [<ffffffff8111af13>] ? lock_timer_base.isra.19+0x33/0x70
>>> > > [  199.230037]  [<ffffffff8111d45f>] mod_timer_pinned+0x9f/0x260
>>> > > [  199.230037]  [<ffffffff811c5ff4>] rcu_eqs_enter_common+0x894/0x970
>>> > > [  199.230037]  [<ffffffff839dc2ac>] ? init_post+0x75/0xc8
>>> > > [  199.230037]  [<ffffffff85abfed5>] ? kernel_init+0x1e1/0x1e1
>>> > > [  199.230037]  [<ffffffff811c63df>] rcu_eqs_enter+0xaf/0xc0
>>> > > [  199.230037]  [<ffffffff811c64c5>] rcu_user_enter+0xd5/0x140
>>> > > [  199.230037]  [<ffffffff8107d0fd>] syscall_trace_leave+0xfd/0x150
>>> > > [  199.230037]  [<ffffffff83a3f7af>] int_check_syscall_exit_work+0x34/0x3d
>>> > > [  199.230037] ---[ end trace a582c3a264d5bd1a ]---
>> > 
>> > Ok, we can't decently protect against any kind of exception messing up everything
>> > in the middle of RCU APIs anyway. The only solution is to find out what cause this
>> > page fault in mod_timer_pinned() and work around that.
>> > 
>> > Anybody, an idea?
> Wow...  So I pass mod_timer_pinned() the address of a per-CPU timer while
> running on that CPU, with interrupts disabled, no less.  I initialize
> this timer at CPU_UP_PREPARE time.  So why the page fault?
> 
> Please see below for a severe diagnostic patch.

Maybe I could help here a bit.

lappy linux # addr2line -i -e vmlinux ffffffff8111d45f
/usr/src/linux/kernel/timer.c:549
/usr/src/linux/include/linux/jump_label.h:101
/usr/src/linux/include/trace/events/timer.h:44
/usr/src/linux/kernel/timer.c:601
/usr/src/linux/kernel/timer.c:734
/usr/src/linux/kernel/timer.c:886

Which means that it was about to:

	debug_object_activate(timer, &timer_debug_descr);


Thanks,
Sasha

Re: rcu: eqs related warnings in linux-next

[Frederic Weisbecker]

2012/9/29 Sasha Levin <levinsasha928@gmail.com>:
> Maybe I could help here a bit.
>
> lappy linux # addr2line -i -e vmlinux ffffffff8111d45f
> /usr/src/linux/kernel/timer.c:549
> /usr/src/linux/include/linux/jump_label.h:101
> /usr/src/linux/include/trace/events/timer.h:44
> /usr/src/linux/kernel/timer.c:601
> /usr/src/linux/kernel/timer.c:734
> /usr/src/linux/kernel/timer.c:886
>
> Which means that it was about to:
>
>         debug_object_activate(timer, &timer_debug_descr);

I can't find anything in the debug object code that might fault.
I was suspecting some per cpu allocated memory: per cpu allocation
sometimes use vmalloc
which uses lazy paging using faults. But I can't find such thing there.

May be there is some faulting specific to KVM...

Re: rcu: eqs related warnings in linux-next

[Paul E. McKenney]

On Sat, Sep 29, 2012 at 02:25:04PM +0200, Frederic Weisbecker wrote:
> 2012/9/29 Sasha Levin <levinsasha928@gmail.com>:
> > Maybe I could help here a bit.
> >
> > lappy linux # addr2line -i -e vmlinux ffffffff8111d45f
> > /usr/src/linux/kernel/timer.c:549
> > /usr/src/linux/include/linux/jump_label.h:101
> > /usr/src/linux/include/trace/events/timer.h:44
> > /usr/src/linux/kernel/timer.c:601
> > /usr/src/linux/kernel/timer.c:734
> > /usr/src/linux/kernel/timer.c:886
> >
> > Which means that it was about to:
> >
> >         debug_object_activate(timer, &timer_debug_descr);

Understood and agreed, hence my severe diagnostic patch.

> I can't find anything in the debug object code that might fault.
> I was suspecting some per cpu allocated memory: per cpu allocation
> sometimes use vmalloc
> which uses lazy paging using faults. But I can't find such thing there.
> 
> May be there is some faulting specific to KVM...

Sasha, is the easily reproducible?  If so, could you please try the
previous patch?  It will likely give us more information on where
this bug really lives.  (Yes, it might totally obscure the bug, but
in that case we will just need to try some other perturbation.)

							Thanx, Paul

Re: rcu: eqs related warnings in linux-next

[Frederic Weisbecker]

On Sat, Sep 29, 2012 at 06:37:37AM -0700, Paul E. McKenney wrote:
> On Sat, Sep 29, 2012 at 02:25:04PM +0200, Frederic Weisbecker wrote:
> > 2012/9/29 Sasha Levin <levinsasha928@gmail.com>:
> > > Maybe I could help here a bit.
> > >
> > > lappy linux # addr2line -i -e vmlinux ffffffff8111d45f
> > > /usr/src/linux/kernel/timer.c:549
> > > /usr/src/linux/include/linux/jump_label.h:101
> > > /usr/src/linux/include/trace/events/timer.h:44
> > > /usr/src/linux/kernel/timer.c:601
> > > /usr/src/linux/kernel/timer.c:734
> > > /usr/src/linux/kernel/timer.c:886
> > >
> > > Which means that it was about to:
> > >
> > >         debug_object_activate(timer, &timer_debug_descr);
> 
> Understood and agreed, hence my severe diagnostic patch.
> 
> > I can't find anything in the debug object code that might fault.
> > I was suspecting some per cpu allocated memory: per cpu allocation
> > sometimes use vmalloc
> > which uses lazy paging using faults. But I can't find such thing there.
> > 
> > May be there is some faulting specific to KVM...
> 
> Sasha, is the easily reproducible?  If so, could you please try the
> previous patch?  It will likely give us more information on where
> this bug really lives.  (Yes, it might totally obscure the bug, but
> in that case we will just need to try some other perturbation.)

Isn't your patch actually removing the timer? But if so, we won't fault
anymore, or may be you want to check if we fault also outside the timer?

Just in case, I'm posting a second patch that dumps the regs when we
fault in the middle of an RCU user mode API. This way we can find
the precise rip where we fault:

---
>From db4ef9708e606754ac8a3f83b9f293383d263108 Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Sat, 29 Sep 2012 14:16:09 +0200
Subject: [PATCH] rcu: Debug nasty rcu user mode API recursion

Add some debug code to chase down the origin of the fault.

Not-Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 arch/x86/mm/fault.c      |    1 +
 include/linux/rcupdate.h |    1 +
 kernel/rcutree.c         |   32 ++++++++++++++++++++++++++++++++
 kernel/rcutree.h         |    1 +
 4 files changed, 35 insertions(+)

diff --git a/arch/x86/mm/fault.c b/arch/x86/mm/fault.c
index a530b23..a5f0eb5 100644
--- a/arch/x86/mm/fault.c
+++ b/arch/x86/mm/fault.c
@@ -1232,6 +1232,7 @@ good_area:
 dotraplinkage void __kprobes
 do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
+	rcu_check_user_recursion(regs);
 	exception_enter(regs);
 	__do_page_fault(regs, error_code);
 	exception_exit(regs);
diff --git a/include/linux/rcupdate.h b/include/linux/rcupdate.h
index 7c968e4..14ba908 100644
--- a/include/linux/rcupdate.h
+++ b/include/linux/rcupdate.h
@@ -199,6 +199,7 @@ extern void rcu_user_enter_after_irq(void);
 extern void rcu_user_exit_after_irq(void);
 extern void rcu_user_hooks_switch(struct task_struct *prev,
 				  struct task_struct *next);
+extern void rcu_check_user_recursion(struct pt_regs *regs);
 #else
 static inline void rcu_user_enter(void) { }
 static inline void rcu_user_exit(void) { }
diff --git a/kernel/rcutree.c b/kernel/rcutree.c
index 4fb2376..63b84f5 100644
--- a/kernel/rcutree.c
+++ b/kernel/rcutree.c
@@ -405,6 +405,20 @@ void rcu_idle_enter(void)
 EXPORT_SYMBOL_GPL(rcu_idle_enter);
 
 #ifdef CONFIG_RCU_USER_QS
+void rcu_check_user_recursion(struct pt_regs *regs)
+{
+	unsigned long flags;
+	static int printed;
+
+	local_irq_save(flags);
+	if (__this_cpu_read(rcu_dynticks.recursion) && !printed) {
+		printed = 1;
+		printk("Found recursion\n");
+		show_regs(regs);
+	}
+	local_irq_restore(flags);
+}
+
 /**
  * rcu_user_enter - inform RCU that we are resuming userspace.
  *
@@ -433,10 +447,20 @@ void rcu_user_enter(void)
 
 	local_irq_save(flags);
 	rdtp = &__get_cpu_var(rcu_dynticks);
+	if (WARN_ON_ONCE(rdtp->recursion)) {
+		local_irq_restore(flags);
+		return;
+	}
+
+	rdtp->recursion = true;
+	barrier();
+
 	if (!rdtp->ignore_user_qs && !rdtp->in_user) {
 		rdtp->in_user = true;
 		rcu_eqs_enter(true);
 	}
+	rdtp->recursion = false;
+
 	local_irq_restore(flags);
 }
 
@@ -590,10 +614,18 @@ void rcu_user_exit(void)
 
 	local_irq_save(flags);
 	rdtp = &__get_cpu_var(rcu_dynticks);
+	if (WARN_ON_ONCE(rdtp->recursion)) {
+		local_irq_restore(flags);
+		return;
+	}
+
+	rdtp->recursion = true;
+	barrier();
 	if (rdtp->in_user) {
 		rdtp->in_user = false;
 		rcu_eqs_exit(true);
 	}
+	rdtp->recursion = false;
 	local_irq_restore(flags);
 }
 
diff --git a/kernel/rcutree.h b/kernel/rcutree.h
index 5faf05d..1bde9d5 100644
--- a/kernel/rcutree.h
+++ b/kernel/rcutree.h
@@ -103,6 +103,7 @@ struct rcu_dynticks {
 	int tick_nohz_enabled_snap; /* Previously seen value from sysfs. */
 #endif /* #ifdef CONFIG_RCU_FAST_NO_HZ */
 #ifdef CONFIG_RCU_USER_QS
+	bool recursion;
 	bool ignore_user_qs;	    /* Treat userspace as extended QS or not */
 	bool in_user;		    /* Is the CPU in userland from RCU POV? */
 #endif
-- 
1.7.9.5

Re: rcu: eqs related warnings in linux-next

[Paul E. McKenney]

On Sat, Sep 29, 2012 at 03:50:07PM +0200, Frederic Weisbecker wrote:
> On Sat, Sep 29, 2012 at 06:37:37AM -0700, Paul E. McKenney wrote:
> > On Sat, Sep 29, 2012 at 02:25:04PM +0200, Frederic Weisbecker wrote:
> > > 2012/9/29 Sasha Levin <levinsasha928@gmail.com>:
> > > > Maybe I could help here a bit.
> > > >
> > > > lappy linux # addr2line -i -e vmlinux ffffffff8111d45f
> > > > /usr/src/linux/kernel/timer.c:549
> > > > /usr/src/linux/include/linux/jump_label.h:101
> > > > /usr/src/linux/include/trace/events/timer.h:44
> > > > /usr/src/linux/kernel/timer.c:601
> > > > /usr/src/linux/kernel/timer.c:734
> > > > /usr/src/linux/kernel/timer.c:886
> > > >
> > > > Which means that it was about to:
> > > >
> > > >         debug_object_activate(timer, &timer_debug_descr);
> > 
> > Understood and agreed, hence my severe diagnostic patch.
> > 
> > > I can't find anything in the debug object code that might fault.
> > > I was suspecting some per cpu allocated memory: per cpu allocation
> > > sometimes use vmalloc
> > > which uses lazy paging using faults. But I can't find such thing there.
> > > 
> > > May be there is some faulting specific to KVM...
> > 
> > Sasha, is the easily reproducible?  If so, could you please try the
> > previous patch?  It will likely give us more information on where
> > this bug really lives.  (Yes, it might totally obscure the bug, but
> > in that case we will just need to try some other perturbation.)
> 
> Isn't your patch actually removing the timer? But if so, we won't fault
> anymore, or may be you want to check if we fault also outside the timer?

Yep, mainly to see if we are getting hammered by something else.

The other motivation for this patch is a theory I have that the timer is
actually superfluous -- the hrtimer that the dyntick-idle code programs
actually does the work.  So I might be using the code either way.

> Just in case, I'm posting a second patch that dumps the regs when we
> fault in the middle of an RCU user mode API. This way we can find
> the precise rip where we fault:

This looks like a good thing to try as well.

							Thanx, Paul

> ---
> >From db4ef9708e606754ac8a3f83b9f293383d263108 Mon Sep 17 00:00:00 2001
> From: Frederic Weisbecker <fweisbec@gmail.com>
> Date: Sat, 29 Sep 2012 14:16:09 +0200
> Subject: [PATCH] rcu: Debug nasty rcu user mode API recursion
> 
> Add some debug code to chase down the origin of the fault.
> 
> Not-Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  arch/x86/mm/fault.c      |    1 +
>  include/linux/rcupdate.h |    1 +
>  kernel/rcutree.c         |   32 ++++++++++++++++++++++++++++++++
>  kernel/rcutree.h         |    1 +
>  4 files changed, 35 insertions(+)
> 
> diff --git a/arch/x86/mm/fault.c b/arch/x86/mm/fault.c
> index a530b23..a5f0eb5 100644
> --- a/arch/x86/mm/fault.c
> +++ b/arch/x86/mm/fault.c
> @@ -1232,6 +1232,7 @@ good_area:
>  dotraplinkage void __kprobes
>  do_page_fault(struct pt_regs *regs, unsigned long error_code)
>  {
> +	rcu_check_user_recursion(regs);
>  	exception_enter(regs);
>  	__do_page_fault(regs, error_code);
>  	exception_exit(regs);
> diff --git a/include/linux/rcupdate.h b/include/linux/rcupdate.h
> index 7c968e4..14ba908 100644
> --- a/include/linux/rcupdate.h
> +++ b/include/linux/rcupdate.h
> @@ -199,6 +199,7 @@ extern void rcu_user_enter_after_irq(void);
>  extern void rcu_user_exit_after_irq(void);
>  extern void rcu_user_hooks_switch(struct task_struct *prev,
>  				  struct task_struct *next);
> +extern void rcu_check_user_recursion(struct pt_regs *regs);
>  #else
>  static inline void rcu_user_enter(void) { }
>  static inline void rcu_user_exit(void) { }
> diff --git a/kernel/rcutree.c b/kernel/rcutree.c
> index 4fb2376..63b84f5 100644
> --- a/kernel/rcutree.c
> +++ b/kernel/rcutree.c
> @@ -405,6 +405,20 @@ void rcu_idle_enter(void)
>  EXPORT_SYMBOL_GPL(rcu_idle_enter);
> 
>  #ifdef CONFIG_RCU_USER_QS
> +void rcu_check_user_recursion(struct pt_regs *regs)
> +{
> +	unsigned long flags;
> +	static int printed;
> +
> +	local_irq_save(flags);
> +	if (__this_cpu_read(rcu_dynticks.recursion) && !printed) {
> +		printed = 1;
> +		printk("Found recursion\n");
> +		show_regs(regs);
> +	}
> +	local_irq_restore(flags);
> +}
> +
>  /**
>   * rcu_user_enter - inform RCU that we are resuming userspace.
>   *
> @@ -433,10 +447,20 @@ void rcu_user_enter(void)
> 
>  	local_irq_save(flags);
>  	rdtp = &__get_cpu_var(rcu_dynticks);
> +	if (WARN_ON_ONCE(rdtp->recursion)) {
> +		local_irq_restore(flags);
> +		return;
> +	}
> +
> +	rdtp->recursion = true;
> +	barrier();
> +
>  	if (!rdtp->ignore_user_qs && !rdtp->in_user) {
>  		rdtp->in_user = true;
>  		rcu_eqs_enter(true);
>  	}
> +	rdtp->recursion = false;
> +
>  	local_irq_restore(flags);
>  }
> 
> @@ -590,10 +614,18 @@ void rcu_user_exit(void)
> 
>  	local_irq_save(flags);
>  	rdtp = &__get_cpu_var(rcu_dynticks);
> +	if (WARN_ON_ONCE(rdtp->recursion)) {
> +		local_irq_restore(flags);
> +		return;
> +	}
> +
> +	rdtp->recursion = true;
> +	barrier();
>  	if (rdtp->in_user) {
>  		rdtp->in_user = false;
>  		rcu_eqs_exit(true);
>  	}
> +	rdtp->recursion = false;
>  	local_irq_restore(flags);
>  }
> 
> diff --git a/kernel/rcutree.h b/kernel/rcutree.h
> index 5faf05d..1bde9d5 100644
> --- a/kernel/rcutree.h
> +++ b/kernel/rcutree.h
> @@ -103,6 +103,7 @@ struct rcu_dynticks {
>  	int tick_nohz_enabled_snap; /* Previously seen value from sysfs. */
>  #endif /* #ifdef CONFIG_RCU_FAST_NO_HZ */
>  #ifdef CONFIG_RCU_USER_QS
> +	bool recursion;
>  	bool ignore_user_qs;	    /* Treat userspace as extended QS or not */
>  	bool in_user;		    /* Is the CPU in userland from RCU POV? */
>  #endif
> -- 
> 1.7.9.5
> 

Re: rcu: eqs related warnings in linux-next

[Sasha Levin]

On 09/29/2012 03:37 PM, Paul E. McKenney wrote:
> Sasha, is the easily reproducible?  If so, could you please try the
> previous patch?  It will likely give us more information on where
> this bug really lives.  (Yes, it might totally obscure the bug, but
> in that case we will just need to try some other perturbation.)

Unlike the last issue, this one is *very* non-reproducible. In fact, I've only hit it once so far.


Thanks,
Sasha

Re: rcu: eqs related warnings in linux-next

[Paul E. McKenney]

On Sat, Sep 29, 2012 at 06:49:51PM +0200, Sasha Levin wrote:
> On 09/29/2012 03:37 PM, Paul E. McKenney wrote:
> > Sasha, is the easily reproducible?  If so, could you please try the
> > previous patch?  It will likely give us more information on where
> > this bug really lives.  (Yes, it might totally obscure the bug, but
> > in that case we will just need to try some other perturbation.)
> 
> Unlike the last issue, this one is *very* non-reproducible. In fact, I've only hit it once so far.

Wouldn't want it to be too easy, I guess...  ;-)

							Thanx, Paul