INFO: task rcuc/0:7 blocked for more than 120 seconds.

INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Sasha Levin]

Hi Paul,

I've recently got the following panic which was caused by khungtask:

[ 1921.589512] INFO: task rcuc/0:7 blocked for more than 120 seconds.
[ 1921.590370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1921.597103] rcuc/0          D ffff880012f61630  4400     7      2 0x00000000
[ 1921.598646]  ffff880012f6b980 0000000000000086 ffff880012f6bfd8 00000000001d4740
[ 1921.600289]  ffff880012f6bfd8 ffff880012f61630 ffff880012f6bfd8 ffff880012f6a000
[ 1921.601707]  00000000001d4800 ffff880012f6a000 ffff880012f6bfd8 00000000001d4800
[ 1921.603258] Call Trace:
[ 1921.603703]  [<ffffffff8255eefa>] schedule+0x3a/0x50
[ 1921.605462]  [<ffffffff8255cd65>] schedule_timeout+0x255/0x4d0
[ 1921.606540]  [<ffffffff8112a25e>] ? mark_held_locks+0x6e/0x130
[ 1921.607633]  [<ffffffff811277b2>] ? lock_release_holdtime+0xb2/0x160
[ 1921.608798]  [<ffffffff825602bb>] ? _raw_spin_unlock_irq+0x2b/0x70
[ 1921.610154]  [<ffffffff8255f630>] wait_for_common+0x120/0x170
[ 1921.617878]  [<ffffffff81104f30>] ? try_to_wake_up+0x2f0/0x2f0
[ 1921.618949]  [<ffffffff811754d0>] ? __call_rcu+0x3c0/0x3c0
[ 1921.621405]  [<ffffffff8255f728>] wait_for_completion+0x18/0x20
[ 1921.623622]  [<ffffffff810ee0b9>] wait_rcu_gp+0x59/0x80
[ 1921.626789]  [<ffffffff810ec0c0>] ? perf_trace_rcu_batch_end+0x120/0x120
[ 1921.629440]  [<ffffffff8255f554>] ? wait_for_common+0x44/0x170
[ 1921.632445]  [<ffffffff81179d3c>] synchronize_rcu+0x1c/0x20
[ 1921.635455]  [<ffffffff810f8980>] atomic_notifier_chain_unregister+0x60/0x80
[ 1921.638550]  [<ffffffff8111bab3>] task_handoff_unregister+0x13/0x20
[ 1921.641271]  [<ffffffff8211342f>] task_notify_func+0x2f/0x40
[ 1921.643894]  [<ffffffff810f8817>] notifier_call_chain+0x67/0x110
[ 1921.646580]  [<ffffffff810f8a14>] __atomic_notifier_call_chain+0x74/0x110
[ 1921.654064]  [<ffffffff810f89d9>] ? __atomic_notifier_call_chain+0x39/0x110
[ 1921.656034]  [<ffffffff810c1a30>] ? __put_task_struct+0xc0/0x120
[ 1921.658625]  [<ffffffff810c71a0>] ? will_become_orphaned_pgrp+0x100/0x100
[ 1921.661527]  [<ffffffff810f8ac1>] atomic_notifier_call_chain+0x11/0x20
[ 1921.664295]  [<ffffffff8111ba55>] profile_handoff_task+0x15/0x20
[ 1921.666885]  [<ffffffff810c19eb>] __put_task_struct+0x7b/0x120
[ 1921.669492]  [<ffffffff810c71d5>] delayed_put_task_struct+0x35/0x140
[ 1921.672129]  [<ffffffff81175994>] rcu_do_batch.clone.12+0x224/0xab0
[ 1921.674697]  [<ffffffff8255ea62>] ? __schedule+0x432/0x890
[ 1921.677028]  [<ffffffff811783fa>] rcu_cpu_kthread+0x48a/0xa40
[ 1921.682719]  [<ffffffff82560245>] ? _raw_spin_unlock_irqrestore+0x55/0xa0
[ 1921.684913]  [<ffffffff81177f70>] ? rcu_idle_enter+0xb0/0xb0
[ 1921.686641]  [<ffffffff810f11f6>] kthread+0xb6/0xc0
[ 1921.689956]  [<ffffffff82562cf4>] kernel_thread_helper+0x4/0x10
[ 1921.692815]  [<ffffffff810fe170>] ? finish_task_switch+0x80/0x110
[ 1921.695613]  [<ffffffff82561038>] ? retint_restore_args+0x13/0x13
[ 1921.698409]  [<ffffffff810f1140>] ? kthread_flush_work_fn+0x10/0x10
[ 1921.701199]  [<ffffffff82562cf0>] ? gs_change+0x13/0x13
[ 1921.703680] 1 lock held by rcuc/0/7:
[ 1921.705325]  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffff810f89d9>] __atomic_notifier_call_chain+0x39/0x110
[ 1921.710297] Kernel panic - not syncing: hung_task: blocked tasks
[ 1921.715383] Rebooting in 1 seconds..

This is the RCU related .config:

# cat .config | grep RCU
# RCU Subsystem
CONFIG_TREE_PREEMPT_RCU=y
CONFIG_PREEMPT_RCU=y
CONFIG_RCU_TRACE=y
CONFIG_RCU_FANOUT=64
# CONFIG_RCU_FANOUT_EXACT is not set
CONFIG_RCU_FAST_NO_HZ=y
CONFIG_TREE_RCU_TRACE=y
CONFIG_RCU_BOOST=y
CONFIG_RCU_BOOST_PRIO=1
CONFIG_RCU_BOOST_DELAY=500
CONFIG_DEBUG_OBJECTS_RCU_HEAD=y
CONFIG_PROVE_RCU=y
CONFIG_PROVE_RCU_REPEATEDLY=y
CONFIG_SPARSE_RCU_POINTER=y
# CONFIG_RCU_TORTURE_TEST is not set
CONFIG_RCU_CPU_STALL_TIMEOUT=60
CONFIG_RCU_CPU_STALL_VERBOSE=y

Please let me know if I can help with anything else.

-- 

Sasha.

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Paul E. McKenney]

On Mon, Dec 26, 2011 at 02:16:43PM +0200, Sasha Levin wrote:
> Hi Paul,
> 
> I've recently got the following panic which was caused by khungtask:
> 
> [ 1921.589512] INFO: task rcuc/0:7 blocked for more than 120 seconds.
> [ 1921.590370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 1921.597103] rcuc/0          D ffff880012f61630  4400     7      2 0x00000000
> [ 1921.598646]  ffff880012f6b980 0000000000000086 ffff880012f6bfd8 00000000001d4740
> [ 1921.600289]  ffff880012f6bfd8 ffff880012f61630 ffff880012f6bfd8 ffff880012f6a000
> [ 1921.601707]  00000000001d4800 ffff880012f6a000 ffff880012f6bfd8 00000000001d4800
> [ 1921.603258] Call Trace:
> [ 1921.603703]  [<ffffffff8255eefa>] schedule+0x3a/0x50
> [ 1921.605462]  [<ffffffff8255cd65>] schedule_timeout+0x255/0x4d0
> [ 1921.606540]  [<ffffffff8112a25e>] ? mark_held_locks+0x6e/0x130
> [ 1921.607633]  [<ffffffff811277b2>] ? lock_release_holdtime+0xb2/0x160
> [ 1921.608798]  [<ffffffff825602bb>] ? _raw_spin_unlock_irq+0x2b/0x70
> [ 1921.610154]  [<ffffffff8255f630>] wait_for_common+0x120/0x170
> [ 1921.617878]  [<ffffffff81104f30>] ? try_to_wake_up+0x2f0/0x2f0
> [ 1921.618949]  [<ffffffff811754d0>] ? __call_rcu+0x3c0/0x3c0
> [ 1921.621405]  [<ffffffff8255f728>] wait_for_completion+0x18/0x20
> [ 1921.623622]  [<ffffffff810ee0b9>] wait_rcu_gp+0x59/0x80
> [ 1921.626789]  [<ffffffff810ec0c0>] ? perf_trace_rcu_batch_end+0x120/0x120
> [ 1921.629440]  [<ffffffff8255f554>] ? wait_for_common+0x44/0x170
> [ 1921.632445]  [<ffffffff81179d3c>] synchronize_rcu+0x1c/0x20
> [ 1921.635455]  [<ffffffff810f8980>] atomic_notifier_chain_unregister+0x60/0x80

This called synchronize_rcu().

> [ 1921.638550]  [<ffffffff8111bab3>] task_handoff_unregister+0x13/0x20
> [ 1921.641271]  [<ffffffff8211342f>] task_notify_func+0x2f/0x40
> [ 1921.643894]  [<ffffffff810f8817>] notifier_call_chain+0x67/0x110
> [ 1921.646580]  [<ffffffff810f8a14>] __atomic_notifier_call_chain+0x74/0x110

This called rcu_read_lock().

Now, calling synchronize_rcu() from within an RCU read-side critical
section is grossly illegal.  This will result in either deadlock (for
preemptible RCU) or premature grace-period end and memory corruption
(for non-preemptible RCU).  So let's take a look at task_notify_func().

Except that when I try looking for task_notify_func() in current mainline,
I get nothing.

Where is task_notify_func() coming from?

Regardless, my advice is to change task_notify_func() as follows:

1.	Make a flag (either global or per-CPU, depending on the logic)
	that tracks whether task_notify_func() is trying to unregister
	itself.  Initialize the flag to zero (in other words, don't bother
	explicitly initializing it).

2.	One entry to task_notify_func(), check the flag.  If set, return
	immediately -- in other words, pretend it never got called.

3.	At the point where task_notify_func() currently calls
	task_handoff_unregister(), set the flag and hand off to a
	work queue (or some similar mechanism).

4.	When the work queue finally does invoke task_handoff_unregister(),
	clear the flag.

5.	If you need to invoke task_handoff_unregister() when the flag
	is set, block until the flag clears.  Perhaps use wait_event()
	on the flag, in which case wake_up() should be used after
	invoking task_handoff_unregister().

Make sense?

							Thanx, Paul

> [ 1921.654064]  [<ffffffff810f89d9>] ? __atomic_notifier_call_chain+0x39/0x110
> [ 1921.656034]  [<ffffffff810c1a30>] ? __put_task_struct+0xc0/0x120
> [ 1921.658625]  [<ffffffff810c71a0>] ? will_become_orphaned_pgrp+0x100/0x100
> [ 1921.661527]  [<ffffffff810f8ac1>] atomic_notifier_call_chain+0x11/0x20
> [ 1921.664295]  [<ffffffff8111ba55>] profile_handoff_task+0x15/0x20
> [ 1921.666885]  [<ffffffff810c19eb>] __put_task_struct+0x7b/0x120
> [ 1921.669492]  [<ffffffff810c71d5>] delayed_put_task_struct+0x35/0x140
> [ 1921.672129]  [<ffffffff81175994>] rcu_do_batch.clone.12+0x224/0xab0
> [ 1921.674697]  [<ffffffff8255ea62>] ? __schedule+0x432/0x890
> [ 1921.677028]  [<ffffffff811783fa>] rcu_cpu_kthread+0x48a/0xa40
> [ 1921.682719]  [<ffffffff82560245>] ? _raw_spin_unlock_irqrestore+0x55/0xa0
> [ 1921.684913]  [<ffffffff81177f70>] ? rcu_idle_enter+0xb0/0xb0
> [ 1921.686641]  [<ffffffff810f11f6>] kthread+0xb6/0xc0
> [ 1921.689956]  [<ffffffff82562cf4>] kernel_thread_helper+0x4/0x10
> [ 1921.692815]  [<ffffffff810fe170>] ? finish_task_switch+0x80/0x110
> [ 1921.695613]  [<ffffffff82561038>] ? retint_restore_args+0x13/0x13
> [ 1921.698409]  [<ffffffff810f1140>] ? kthread_flush_work_fn+0x10/0x10
> [ 1921.701199]  [<ffffffff82562cf0>] ? gs_change+0x13/0x13
> [ 1921.703680] 1 lock held by rcuc/0/7:
> [ 1921.705325]  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffff810f89d9>] __atomic_notifier_call_chain+0x39/0x110
> [ 1921.710297] Kernel panic - not syncing: hung_task: blocked tasks
> [ 1921.715383] Rebooting in 1 seconds..
> 
> This is the RCU related .config:
> 
> # cat .config | grep RCU
> # RCU Subsystem
> CONFIG_TREE_PREEMPT_RCU=y
> CONFIG_PREEMPT_RCU=y
> CONFIG_RCU_TRACE=y
> CONFIG_RCU_FANOUT=64
> # CONFIG_RCU_FANOUT_EXACT is not set
> CONFIG_RCU_FAST_NO_HZ=y
> CONFIG_TREE_RCU_TRACE=y
> CONFIG_RCU_BOOST=y
> CONFIG_RCU_BOOST_PRIO=1
> CONFIG_RCU_BOOST_DELAY=500
> CONFIG_DEBUG_OBJECTS_RCU_HEAD=y
> CONFIG_PROVE_RCU=y
> CONFIG_PROVE_RCU_REPEATEDLY=y
> CONFIG_SPARSE_RCU_POINTER=y
> # CONFIG_RCU_TORTURE_TEST is not set
> CONFIG_RCU_CPU_STALL_TIMEOUT=60
> CONFIG_RCU_CPU_STALL_VERBOSE=y
> 
> Please let me know if I can help with anything else.
> 
> -- 
> 
> Sasha.
> 

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Frederic Weisbecker]

On Mon, Dec 26, 2011 at 08:31:48AM -0800, Paul E. McKenney wrote:
> On Mon, Dec 26, 2011 at 02:16:43PM +0200, Sasha Levin wrote:
> > Hi Paul,
> > 
> > I've recently got the following panic which was caused by khungtask:
> > 
> > [ 1921.589512] INFO: task rcuc/0:7 blocked for more than 120 seconds.
> > [ 1921.590370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > [ 1921.597103] rcuc/0          D ffff880012f61630  4400     7      2 0x00000000
> > [ 1921.598646]  ffff880012f6b980 0000000000000086 ffff880012f6bfd8 00000000001d4740
> > [ 1921.600289]  ffff880012f6bfd8 ffff880012f61630 ffff880012f6bfd8 ffff880012f6a000
> > [ 1921.601707]  00000000001d4800 ffff880012f6a000 ffff880012f6bfd8 00000000001d4800
> > [ 1921.603258] Call Trace:
> > [ 1921.603703]  [<ffffffff8255eefa>] schedule+0x3a/0x50
> > [ 1921.605462]  [<ffffffff8255cd65>] schedule_timeout+0x255/0x4d0
> > [ 1921.606540]  [<ffffffff8112a25e>] ? mark_held_locks+0x6e/0x130
> > [ 1921.607633]  [<ffffffff811277b2>] ? lock_release_holdtime+0xb2/0x160
> > [ 1921.608798]  [<ffffffff825602bb>] ? _raw_spin_unlock_irq+0x2b/0x70
> > [ 1921.610154]  [<ffffffff8255f630>] wait_for_common+0x120/0x170
> > [ 1921.617878]  [<ffffffff81104f30>] ? try_to_wake_up+0x2f0/0x2f0
> > [ 1921.618949]  [<ffffffff811754d0>] ? __call_rcu+0x3c0/0x3c0
> > [ 1921.621405]  [<ffffffff8255f728>] wait_for_completion+0x18/0x20
> > [ 1921.623622]  [<ffffffff810ee0b9>] wait_rcu_gp+0x59/0x80
> > [ 1921.626789]  [<ffffffff810ec0c0>] ? perf_trace_rcu_batch_end+0x120/0x120
> > [ 1921.629440]  [<ffffffff8255f554>] ? wait_for_common+0x44/0x170
> > [ 1921.632445]  [<ffffffff81179d3c>] synchronize_rcu+0x1c/0x20
> > [ 1921.635455]  [<ffffffff810f8980>] atomic_notifier_chain_unregister+0x60/0x80
> 
> This called synchronize_rcu().
> 
> > [ 1921.638550]  [<ffffffff8111bab3>] task_handoff_unregister+0x13/0x20
> > [ 1921.641271]  [<ffffffff8211342f>] task_notify_func+0x2f/0x40
> > [ 1921.643894]  [<ffffffff810f8817>] notifier_call_chain+0x67/0x110
> > [ 1921.646580]  [<ffffffff810f8a14>] __atomic_notifier_call_chain+0x74/0x110
> 
> This called rcu_read_lock().
> 
> Now, calling synchronize_rcu() from within an RCU read-side critical
> section is grossly illegal.  This will result in either deadlock (for
> preemptible RCU) or premature grace-period end and memory corruption
> (for non-preemptible RCU).

Don't we have debugging checks for that? I can't seem to find any.
May be worth having a WARN_ON_ONCE(rcu_read_lock_held()) in
synchronize_rcu().

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Paul E. McKenney]

On Mon, Dec 26, 2011 at 05:37:36PM +0100, Frederic Weisbecker wrote:
> On Mon, Dec 26, 2011 at 08:31:48AM -0800, Paul E. McKenney wrote:
> > On Mon, Dec 26, 2011 at 02:16:43PM +0200, Sasha Levin wrote:
> > > Hi Paul,
> > > 
> > > I've recently got the following panic which was caused by khungtask:
> > > 
> > > [ 1921.589512] INFO: task rcuc/0:7 blocked for more than 120 seconds.
> > > [ 1921.590370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > [ 1921.597103] rcuc/0          D ffff880012f61630  4400     7      2 0x00000000
> > > [ 1921.598646]  ffff880012f6b980 0000000000000086 ffff880012f6bfd8 00000000001d4740
> > > [ 1921.600289]  ffff880012f6bfd8 ffff880012f61630 ffff880012f6bfd8 ffff880012f6a000
> > > [ 1921.601707]  00000000001d4800 ffff880012f6a000 ffff880012f6bfd8 00000000001d4800
> > > [ 1921.603258] Call Trace:
> > > [ 1921.603703]  [<ffffffff8255eefa>] schedule+0x3a/0x50
> > > [ 1921.605462]  [<ffffffff8255cd65>] schedule_timeout+0x255/0x4d0
> > > [ 1921.606540]  [<ffffffff8112a25e>] ? mark_held_locks+0x6e/0x130
> > > [ 1921.607633]  [<ffffffff811277b2>] ? lock_release_holdtime+0xb2/0x160
> > > [ 1921.608798]  [<ffffffff825602bb>] ? _raw_spin_unlock_irq+0x2b/0x70
> > > [ 1921.610154]  [<ffffffff8255f630>] wait_for_common+0x120/0x170
> > > [ 1921.617878]  [<ffffffff81104f30>] ? try_to_wake_up+0x2f0/0x2f0
> > > [ 1921.618949]  [<ffffffff811754d0>] ? __call_rcu+0x3c0/0x3c0
> > > [ 1921.621405]  [<ffffffff8255f728>] wait_for_completion+0x18/0x20
> > > [ 1921.623622]  [<ffffffff810ee0b9>] wait_rcu_gp+0x59/0x80
> > > [ 1921.626789]  [<ffffffff810ec0c0>] ? perf_trace_rcu_batch_end+0x120/0x120
> > > [ 1921.629440]  [<ffffffff8255f554>] ? wait_for_common+0x44/0x170
> > > [ 1921.632445]  [<ffffffff81179d3c>] synchronize_rcu+0x1c/0x20
> > > [ 1921.635455]  [<ffffffff810f8980>] atomic_notifier_chain_unregister+0x60/0x80
> > 
> > This called synchronize_rcu().
> > 
> > > [ 1921.638550]  [<ffffffff8111bab3>] task_handoff_unregister+0x13/0x20
> > > [ 1921.641271]  [<ffffffff8211342f>] task_notify_func+0x2f/0x40
> > > [ 1921.643894]  [<ffffffff810f8817>] notifier_call_chain+0x67/0x110
> > > [ 1921.646580]  [<ffffffff810f8a14>] __atomic_notifier_call_chain+0x74/0x110
> > 
> > This called rcu_read_lock().
> > 
> > Now, calling synchronize_rcu() from within an RCU read-side critical
> > section is grossly illegal.  This will result in either deadlock (for
> > preemptible RCU) or premature grace-period end and memory corruption
> > (for non-preemptible RCU).
> 
> Don't we have debugging checks for that? I can't seem to find any.
> May be worth having a WARN_ON_ONCE(rcu_read_lock_held()) in
> synchronize_rcu().

Indeed, my bad.  It should be possible to make lockdep do this.  The
potential advantage is that this would also detect more elaborate
scenarios, including:

	T1:
	i = srcu_read_lock(&myfirstsrcu);
	synchronize_srcu(&mysecondsrcu);
	srcu_read_unlock(&myfirstsrcu, i);

	T2:
	i = srcu_read_lock(&mysecondsrcu);
	synchronize_srcu(&myfirstsrcu);
	srcu_read_unlock(&mysecondsrcu, i);

Perhaps I should try telling lockdep that the RCU "locks" were
write-acquired and then immediately released in synchronize_rcu()
and friends.

Thoughts?

							Thanx, Paul

[PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side

[Frederic Weisbecker]

On Mon, Dec 26, 2011 at 11:56:57AM -0800, Paul E. McKenney wrote:
> On Mon, Dec 26, 2011 at 05:37:36PM +0100, Frederic Weisbecker wrote:
> > On Mon, Dec 26, 2011 at 08:31:48AM -0800, Paul E. McKenney wrote:
> > > On Mon, Dec 26, 2011 at 02:16:43PM +0200, Sasha Levin wrote:
> > > > Hi Paul,
> > > > 
> > > > I've recently got the following panic which was caused by khungtask:
> > > > 
> > > > [ 1921.589512] INFO: task rcuc/0:7 blocked for more than 120 seconds.
> > > > [ 1921.590370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > > [ 1921.597103] rcuc/0          D ffff880012f61630  4400     7      2 0x00000000
> > > > [ 1921.598646]  ffff880012f6b980 0000000000000086 ffff880012f6bfd8 00000000001d4740
> > > > [ 1921.600289]  ffff880012f6bfd8 ffff880012f61630 ffff880012f6bfd8 ffff880012f6a000
> > > > [ 1921.601707]  00000000001d4800 ffff880012f6a000 ffff880012f6bfd8 00000000001d4800
> > > > [ 1921.603258] Call Trace:
> > > > [ 1921.603703]  [<ffffffff8255eefa>] schedule+0x3a/0x50
> > > > [ 1921.605462]  [<ffffffff8255cd65>] schedule_timeout+0x255/0x4d0
> > > > [ 1921.606540]  [<ffffffff8112a25e>] ? mark_held_locks+0x6e/0x130
> > > > [ 1921.607633]  [<ffffffff811277b2>] ? lock_release_holdtime+0xb2/0x160
> > > > [ 1921.608798]  [<ffffffff825602bb>] ? _raw_spin_unlock_irq+0x2b/0x70
> > > > [ 1921.610154]  [<ffffffff8255f630>] wait_for_common+0x120/0x170
> > > > [ 1921.617878]  [<ffffffff81104f30>] ? try_to_wake_up+0x2f0/0x2f0
> > > > [ 1921.618949]  [<ffffffff811754d0>] ? __call_rcu+0x3c0/0x3c0
> > > > [ 1921.621405]  [<ffffffff8255f728>] wait_for_completion+0x18/0x20
> > > > [ 1921.623622]  [<ffffffff810ee0b9>] wait_rcu_gp+0x59/0x80
> > > > [ 1921.626789]  [<ffffffff810ec0c0>] ? perf_trace_rcu_batch_end+0x120/0x120
> > > > [ 1921.629440]  [<ffffffff8255f554>] ? wait_for_common+0x44/0x170
> > > > [ 1921.632445]  [<ffffffff81179d3c>] synchronize_rcu+0x1c/0x20
> > > > [ 1921.635455]  [<ffffffff810f8980>] atomic_notifier_chain_unregister+0x60/0x80
> > > 
> > > This called synchronize_rcu().
> > > 
> > > > [ 1921.638550]  [<ffffffff8111bab3>] task_handoff_unregister+0x13/0x20
> > > > [ 1921.641271]  [<ffffffff8211342f>] task_notify_func+0x2f/0x40
> > > > [ 1921.643894]  [<ffffffff810f8817>] notifier_call_chain+0x67/0x110
> > > > [ 1921.646580]  [<ffffffff810f8a14>] __atomic_notifier_call_chain+0x74/0x110
> > > 
> > > This called rcu_read_lock().
> > > 
> > > Now, calling synchronize_rcu() from within an RCU read-side critical
> > > section is grossly illegal.  This will result in either deadlock (for
> > > preemptible RCU) or premature grace-period end and memory corruption
> > > (for non-preemptible RCU).
> > 
> > Don't we have debugging checks for that? I can't seem to find any.
> > May be worth having a WARN_ON_ONCE(rcu_read_lock_held()) in
> > synchronize_rcu().
> 
> Indeed, my bad.  It should be possible to make lockdep do this.

Actually for the case of RCU, the wait_for_completion() called by synchronize_rcu()
has a might_sleep() call that triggers a warning in this case.

But in the case of SMP with 1 online CPU, the rcu_blocking_is_gp()
checks returns right away on rcutree. So probably we need this?

rcutiny seems to be fine with the cond_resched() call, but srcu needs
a special treatment.

---
>From 27b99308e034046df86bab9d57be082815d77762 Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Wed, 4 Jan 2012 19:20:58 +0100
Subject: [PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side

In RCU tree, synchronize_{rcu,sched,rcu_bh} can detect illegal call from
RCU read side critical section with might_sleep() called before waiting
for the grace period completion.

But in RCU tree, the calls to synchronize_sched() and synchronize_rcu_bh()
return immediately if only one CPU is running. In this case we are missing
the checks for calls of these APIs from atomic sections (including RCU read
side).

To cover every cases, put a might_sleep() call in the beginning of those
two functions.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/rcutree.c |   12 ++++++++++++
 1 files changed, 12 insertions(+), 0 deletions(-)

diff --git a/kernel/rcutree.c b/kernel/rcutree.c
index 6c4a672..68cded7 100644
--- a/kernel/rcutree.c
+++ b/kernel/rcutree.c
@@ -1816,6 +1816,12 @@ EXPORT_SYMBOL_GPL(call_rcu_bh);
  */
 void synchronize_sched(void)
 {
+	/*
+	 * Detect we are not calling this while in RCU
+	 * read side critical section, even with 1 online
+	 * CPU.
+	 */
+	might_sleep();
 	if (rcu_blocking_is_gp())
 		return;
 	wait_rcu_gp(call_rcu_sched);
@@ -1833,6 +1839,12 @@ EXPORT_SYMBOL_GPL(synchronize_sched);
  */
 void synchronize_rcu_bh(void)
 {
+	/*
+	 * Detect we are not calling this while in RCU
+	 * read side critical section, even with 1 online
+	 * CPU.
+	 */
+	might_sleep();
 	if (rcu_blocking_is_gp())
 		return;
 	wait_rcu_gp(call_rcu_bh);
-- 
1.7.0.4

Re: [PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side

[Paul E. McKenney]

On Wed, Jan 04, 2012 at 08:03:39PM +0100, Frederic Weisbecker wrote:
> On Mon, Dec 26, 2011 at 11:56:57AM -0800, Paul E. McKenney wrote:
> > On Mon, Dec 26, 2011 at 05:37:36PM +0100, Frederic Weisbecker wrote:
> > > On Mon, Dec 26, 2011 at 08:31:48AM -0800, Paul E. McKenney wrote:
> > > > On Mon, Dec 26, 2011 at 02:16:43PM +0200, Sasha Levin wrote:
> > > > > Hi Paul,
> > > > > 
> > > > > I've recently got the following panic which was caused by khungtask:
> > > > > 
> > > > > [ 1921.589512] INFO: task rcuc/0:7 blocked for more than 120 seconds.
> > > > > [ 1921.590370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > > > [ 1921.597103] rcuc/0          D ffff880012f61630  4400     7      2 0x00000000
> > > > > [ 1921.598646]  ffff880012f6b980 0000000000000086 ffff880012f6bfd8 00000000001d4740
> > > > > [ 1921.600289]  ffff880012f6bfd8 ffff880012f61630 ffff880012f6bfd8 ffff880012f6a000
> > > > > [ 1921.601707]  00000000001d4800 ffff880012f6a000 ffff880012f6bfd8 00000000001d4800
> > > > > [ 1921.603258] Call Trace:
> > > > > [ 1921.603703]  [<ffffffff8255eefa>] schedule+0x3a/0x50
> > > > > [ 1921.605462]  [<ffffffff8255cd65>] schedule_timeout+0x255/0x4d0
> > > > > [ 1921.606540]  [<ffffffff8112a25e>] ? mark_held_locks+0x6e/0x130
> > > > > [ 1921.607633]  [<ffffffff811277b2>] ? lock_release_holdtime+0xb2/0x160
> > > > > [ 1921.608798]  [<ffffffff825602bb>] ? _raw_spin_unlock_irq+0x2b/0x70
> > > > > [ 1921.610154]  [<ffffffff8255f630>] wait_for_common+0x120/0x170
> > > > > [ 1921.617878]  [<ffffffff81104f30>] ? try_to_wake_up+0x2f0/0x2f0
> > > > > [ 1921.618949]  [<ffffffff811754d0>] ? __call_rcu+0x3c0/0x3c0
> > > > > [ 1921.621405]  [<ffffffff8255f728>] wait_for_completion+0x18/0x20
> > > > > [ 1921.623622]  [<ffffffff810ee0b9>] wait_rcu_gp+0x59/0x80
> > > > > [ 1921.626789]  [<ffffffff810ec0c0>] ? perf_trace_rcu_batch_end+0x120/0x120
> > > > > [ 1921.629440]  [<ffffffff8255f554>] ? wait_for_common+0x44/0x170
> > > > > [ 1921.632445]  [<ffffffff81179d3c>] synchronize_rcu+0x1c/0x20
> > > > > [ 1921.635455]  [<ffffffff810f8980>] atomic_notifier_chain_unregister+0x60/0x80
> > > > 
> > > > This called synchronize_rcu().
> > > > 
> > > > > [ 1921.638550]  [<ffffffff8111bab3>] task_handoff_unregister+0x13/0x20
> > > > > [ 1921.641271]  [<ffffffff8211342f>] task_notify_func+0x2f/0x40
> > > > > [ 1921.643894]  [<ffffffff810f8817>] notifier_call_chain+0x67/0x110
> > > > > [ 1921.646580]  [<ffffffff810f8a14>] __atomic_notifier_call_chain+0x74/0x110
> > > > 
> > > > This called rcu_read_lock().
> > > > 
> > > > Now, calling synchronize_rcu() from within an RCU read-side critical
> > > > section is grossly illegal.  This will result in either deadlock (for
> > > > preemptible RCU) or premature grace-period end and memory corruption
> > > > (for non-preemptible RCU).
> > > 
> > > Don't we have debugging checks for that? I can't seem to find any.
> > > May be worth having a WARN_ON_ONCE(rcu_read_lock_held()) in
> > > synchronize_rcu().
> > 
> > Indeed, my bad.  It should be possible to make lockdep do this.
> 
> Actually for the case of RCU, the wait_for_completion() called by synchronize_rcu()
> has a might_sleep() call that triggers a warning in this case.
> 
> But in the case of SMP with 1 online CPU, the rcu_blocking_is_gp()
> checks returns right away on rcutree. So probably we need this?

I modified this to push the might_sleep() down into the
rcu_blocking_is_gp() function, queued the result, and retained your
Signed-off-by.  (Please let me know if there is any problem with this.)

This does work for TREE_PREEMPT_RCU and for synchronize_rcu_bh() in
TREE_RCU, but not for synchronize_sched() in TREE_RCU.  This is because
rcu_read_lock() and rcu_read_unlock() are no-ops in the TREE_RCU case.

So I queued up a separate patch using rcu_lockdep_assert() to check for
illegal RCU grace period within the same-type RCU read-side critical
section, including for SRCU.  This is also a partial solution, as it
does not handle things like this:

	void foo(void)
	{
		mutex_lock(&my_mutex);
		. . .
		synchronize_srcu(&my_srcu);
		. . .
		mutex_unlock(&my_mutex);
	}

	void bar(void)
	{
		int idx;

		idx = rcu_read_lock(&m_srcu);
		. . .
		mutex_lock(&my_mutex);
		. . .
		mutex_unlock(&my_mutex);
		. . .
		srcu_read_unlock(&m_srcu, idx);
	}

This can be extended into a chain of locks and a chain of SRCU instances.
For an example of the latter, consider an SRCU-A read-side critical
section containing an SRCU-B grace period, an SRCU-B read-side critical
section containing an SRCU-C grace period, and so on, with the SRCU-Z
read-side critical section containing an RCU-A grace period.  But it
is OK to hold a mutex across one SRCU read-side critical section while
acquiring that same mutex within another same-flavor SRCU read-side
critical section.  So the analogy with reader-writer locking only goes
so far.

At the moment, a full solution seems to require some surgery on lockdep
itself, but perhaps there is a better way.

> rcutiny seems to be fine with the cond_resched() call, but srcu needs
> a special treatment.

For the moment, I just applied rcu_lockdep_assert() everywhere -- zero
cost on non-lockdep kernels, and fully handles all of the RCU simple
self-deadlock cases.

							Thanx, Paul

> ---
> >From 27b99308e034046df86bab9d57be082815d77762 Mon Sep 17 00:00:00 2001
> From: Frederic Weisbecker <fweisbec@gmail.com>
> Date: Wed, 4 Jan 2012 19:20:58 +0100
> Subject: [PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side
> 
> In RCU tree, synchronize_{rcu,sched,rcu_bh} can detect illegal call from
> RCU read side critical section with might_sleep() called before waiting
> for the grace period completion.
> 
> But in RCU tree, the calls to synchronize_sched() and synchronize_rcu_bh()
> return immediately if only one CPU is running. In this case we are missing
> the checks for calls of these APIs from atomic sections (including RCU read
> side).
> 
> To cover every cases, put a might_sleep() call in the beginning of those
> two functions.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/rcutree.c |   12 ++++++++++++
>  1 files changed, 12 insertions(+), 0 deletions(-)
> 
> diff --git a/kernel/rcutree.c b/kernel/rcutree.c
> index 6c4a672..68cded7 100644
> --- a/kernel/rcutree.c
> +++ b/kernel/rcutree.c
> @@ -1816,6 +1816,12 @@ EXPORT_SYMBOL_GPL(call_rcu_bh);
>   */
>  void synchronize_sched(void)
>  {
> +	/*
> +	 * Detect we are not calling this while in RCU
> +	 * read side critical section, even with 1 online
> +	 * CPU.
> +	 */
> +	might_sleep();
>  	if (rcu_blocking_is_gp())
>  		return;
>  	wait_rcu_gp(call_rcu_sched);
> @@ -1833,6 +1839,12 @@ EXPORT_SYMBOL_GPL(synchronize_sched);
>   */
>  void synchronize_rcu_bh(void)
>  {
> +	/*
> +	 * Detect we are not calling this while in RCU
> +	 * read side critical section, even with 1 online
> +	 * CPU.
> +	 */
> +	might_sleep();
>  	if (rcu_blocking_is_gp())
>  		return;
>  	wait_rcu_gp(call_rcu_bh);
> -- 
> 1.7.0.4
> 

Re: [PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side

[Frederic Weisbecker]

On Wed, Jan 04, 2012 at 01:30:35PM -0800, Paul E. McKenney wrote:
> On Wed, Jan 04, 2012 at 08:03:39PM +0100, Frederic Weisbecker wrote:
> > Actually for the case of RCU, the wait_for_completion() called by synchronize_rcu()
> > has a might_sleep() call that triggers a warning in this case.
> > 
> > But in the case of SMP with 1 online CPU, the rcu_blocking_is_gp()
> > checks returns right away on rcutree. So probably we need this?
> 
> I modified this to push the might_sleep() down into the
> rcu_blocking_is_gp() function, queued the result, and retained your
> Signed-off-by.  (Please let me know if there is any problem with this.)
> 
> This does work for TREE_PREEMPT_RCU and for synchronize_rcu_bh() in
> TREE_RCU, but not for synchronize_sched() in TREE_RCU.  This is because
> rcu_read_lock() and rcu_read_unlock() are no-ops in the TREE_RCU case.

Not sure about that. This calls preempt_disable() which, in any case with
CONFIG_DEBUG_ATOMIC_SLEEP, handles the preempt count. And that even if
!CONFIG_PREEMPT.

> 
> So I queued up a separate patch using rcu_lockdep_assert() to check for
> illegal RCU grace period within the same-type RCU read-side critical
> section, including for SRCU.  This is also a partial solution, as it
> does not handle things like this:
> 
> 	void foo(void)
> 	{
> 		mutex_lock(&my_mutex);
> 		. . .
> 		synchronize_srcu(&my_srcu);
> 		. . .
> 		mutex_unlock(&my_mutex);
> 	}
> 
> 	void bar(void)
> 	{
> 		int idx;
> 
> 		idx = rcu_read_lock(&m_srcu);
> 		. . .
> 		mutex_lock(&my_mutex);
> 		. . .
> 		mutex_unlock(&my_mutex);
> 		. . .
> 		srcu_read_unlock(&m_srcu, idx);
> 	}
> 
> This can be extended into a chain of locks and a chain of SRCU instances.
> For an example of the latter, consider an SRCU-A read-side critical
> section containing an SRCU-B grace period, an SRCU-B read-side critical
> section containing an SRCU-C grace period, and so on, with the SRCU-Z
> read-side critical section containing an RCU-A grace period.

Heh! Indeed...

> But it
> is OK to hold a mutex across one SRCU read-side critical section while
> acquiring that same mutex within another same-flavor SRCU read-side
> critical section.  So the analogy with reader-writer locking only goes
> so far.
> 
> At the moment, a full solution seems to require some surgery on lockdep
> itself, but perhaps there is a better way.

Ok.

> 
> > rcutiny seems to be fine with the cond_resched() call, but srcu needs
> > a special treatment.
> 
> For the moment, I just applied rcu_lockdep_assert() everywhere -- zero
> cost on non-lockdep kernels, and fully handles all of the RCU simple
> self-deadlock cases.

So, for RCU I'm not sure this is useful given the might_sleep() things.
But for srcu it is.

Thanks.

Re: [PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side

[Paul E. McKenney]

On Thu, Jan 05, 2012 at 02:45:20AM +0100, Frederic Weisbecker wrote:
> On Wed, Jan 04, 2012 at 01:30:35PM -0800, Paul E. McKenney wrote:
> > On Wed, Jan 04, 2012 at 08:03:39PM +0100, Frederic Weisbecker wrote:
> > > Actually for the case of RCU, the wait_for_completion() called by synchronize_rcu()
> > > has a might_sleep() call that triggers a warning in this case.
> > > 
> > > But in the case of SMP with 1 online CPU, the rcu_blocking_is_gp()
> > > checks returns right away on rcutree. So probably we need this?
> > 
> > I modified this to push the might_sleep() down into the
> > rcu_blocking_is_gp() function, queued the result, and retained your
> > Signed-off-by.  (Please let me know if there is any problem with this.)
> > 
> > This does work for TREE_PREEMPT_RCU and for synchronize_rcu_bh() in
> > TREE_RCU, but not for synchronize_sched() in TREE_RCU.  This is because
> > rcu_read_lock() and rcu_read_unlock() are no-ops in the TREE_RCU case.
> 
> Not sure about that. This calls preempt_disable() which, in any case with
> CONFIG_DEBUG_ATOMIC_SLEEP, handles the preempt count. And that even if
> !CONFIG_PREEMPT.

Ah, of course!  I keep forgetting that CONFIG_DEBUG_ATOMIC_SLEEP selects
CONFIG_PREEMPT_COUNT.

> > So I queued up a separate patch using rcu_lockdep_assert() to check for
> > illegal RCU grace period within the same-type RCU read-side critical
> > section, including for SRCU.  This is also a partial solution, as it
> > does not handle things like this:
> > 
> > 	void foo(void)
> > 	{
> > 		mutex_lock(&my_mutex);
> > 		. . .
> > 		synchronize_srcu(&my_srcu);
> > 		. . .
> > 		mutex_unlock(&my_mutex);
> > 	}
> > 
> > 	void bar(void)
> > 	{
> > 		int idx;
> > 
> > 		idx = rcu_read_lock(&m_srcu);
> > 		. . .
> > 		mutex_lock(&my_mutex);
> > 		. . .
> > 		mutex_unlock(&my_mutex);
> > 		. . .
> > 		srcu_read_unlock(&m_srcu, idx);
> > 	}
> > 
> > This can be extended into a chain of locks and a chain of SRCU instances.
> > For an example of the latter, consider an SRCU-A read-side critical
> > section containing an SRCU-B grace period, an SRCU-B read-side critical
> > section containing an SRCU-C grace period, and so on, with the SRCU-Z
> > read-side critical section containing an RCU-A grace period.
> 
> Heh! Indeed...
> 
> > But it
> > is OK to hold a mutex across one SRCU read-side critical section while
> > acquiring that same mutex within another same-flavor SRCU read-side
> > critical section.  So the analogy with reader-writer locking only goes
> > so far.
> > 
> > At the moment, a full solution seems to require some surgery on lockdep
> > itself, but perhaps there is a better way.
> 
> Ok.
> 
> > 
> > > rcutiny seems to be fine with the cond_resched() call, but srcu needs
> > > a special treatment.
> > 
> > For the moment, I just applied rcu_lockdep_assert() everywhere -- zero
> > cost on non-lockdep kernels, and fully handles all of the RCU simple
> > self-deadlock cases.
> 
> So, for RCU I'm not sure this is useful given the might_sleep() things.
> But for srcu it is.

One nice thing about the lockdep approach is that it tracks where the
conflicting RCU read-side critical section started.  But I am planning
for these to be 3.4 material, so we do have some time to refine them.

							Thanx, Paul

Re: [PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side

[Frederic Weisbecker]

On Wed, Jan 04, 2012 at 06:01:08PM -0800, Paul E. McKenney wrote:
> On Thu, Jan 05, 2012 at 02:45:20AM +0100, Frederic Weisbecker wrote:
> > On Wed, Jan 04, 2012 at 01:30:35PM -0800, Paul E. McKenney wrote:
> > > On Wed, Jan 04, 2012 at 08:03:39PM +0100, Frederic Weisbecker wrote:
> > > > Actually for the case of RCU, the wait_for_completion() called by synchronize_rcu()
> > > > has a might_sleep() call that triggers a warning in this case.
> > > > 
> > > > But in the case of SMP with 1 online CPU, the rcu_blocking_is_gp()
> > > > checks returns right away on rcutree. So probably we need this?
> > > 
> > > I modified this to push the might_sleep() down into the
> > > rcu_blocking_is_gp() function, queued the result, and retained your
> > > Signed-off-by.  (Please let me know if there is any problem with this.)
> > > 
> > > This does work for TREE_PREEMPT_RCU and for synchronize_rcu_bh() in
> > > TREE_RCU, but not for synchronize_sched() in TREE_RCU.  This is because
> > > rcu_read_lock() and rcu_read_unlock() are no-ops in the TREE_RCU case.
> > 
> > Not sure about that. This calls preempt_disable() which, in any case with
> > CONFIG_DEBUG_ATOMIC_SLEEP, handles the preempt count. And that even if
> > !CONFIG_PREEMPT.
> 
> Ah, of course!  I keep forgetting that CONFIG_DEBUG_ATOMIC_SLEEP selects
> CONFIG_PREEMPT_COUNT.
> 
> > > So I queued up a separate patch using rcu_lockdep_assert() to check for
> > > illegal RCU grace period within the same-type RCU read-side critical
> > > section, including for SRCU.  This is also a partial solution, as it
> > > does not handle things like this:
> > > 
> > > 	void foo(void)
> > > 	{
> > > 		mutex_lock(&my_mutex);
> > > 		. . .
> > > 		synchronize_srcu(&my_srcu);
> > > 		. . .
> > > 		mutex_unlock(&my_mutex);
> > > 	}
> > > 
> > > 	void bar(void)
> > > 	{
> > > 		int idx;
> > > 
> > > 		idx = rcu_read_lock(&m_srcu);
> > > 		. . .
> > > 		mutex_lock(&my_mutex);
> > > 		. . .
> > > 		mutex_unlock(&my_mutex);
> > > 		. . .
> > > 		srcu_read_unlock(&m_srcu, idx);
> > > 	}
> > > 
> > > This can be extended into a chain of locks and a chain of SRCU instances.
> > > For an example of the latter, consider an SRCU-A read-side critical
> > > section containing an SRCU-B grace period, an SRCU-B read-side critical
> > > section containing an SRCU-C grace period, and so on, with the SRCU-Z
> > > read-side critical section containing an RCU-A grace period.
> > 
> > Heh! Indeed...
> > 
> > > But it
> > > is OK to hold a mutex across one SRCU read-side critical section while
> > > acquiring that same mutex within another same-flavor SRCU read-side
> > > critical section.  So the analogy with reader-writer locking only goes
> > > so far.
> > > 
> > > At the moment, a full solution seems to require some surgery on lockdep
> > > itself, but perhaps there is a better way.
> > 
> > Ok.
> > 
> > > 
> > > > rcutiny seems to be fine with the cond_resched() call, but srcu needs
> > > > a special treatment.
> > > 
> > > For the moment, I just applied rcu_lockdep_assert() everywhere -- zero
> > > cost on non-lockdep kernels, and fully handles all of the RCU simple
> > > self-deadlock cases.
> > 
> > So, for RCU I'm not sure this is useful given the might_sleep() things.
> > But for srcu it is.
> 
> One nice thing about the lockdep approach is that it tracks where the
> conflicting RCU read-side critical section started.  But I am planning
> for these to be 3.4 material, so we do have some time to refine them.

Yeah sure. And in any case it's still good to keep might_sleep() early
to spot other sources of illegal atomic sections (irqs disabled and co)

Re: [PATCH] rcu: Improve detection of illegal synchronize_rcu() call from RCU read side

[Paul E. McKenney]

On Thu, Jan 05, 2012 at 03:06:03AM +0100, Frederic Weisbecker wrote:
> On Wed, Jan 04, 2012 at 06:01:08PM -0800, Paul E. McKenney wrote:
> > On Thu, Jan 05, 2012 at 02:45:20AM +0100, Frederic Weisbecker wrote:
> > > On Wed, Jan 04, 2012 at 01:30:35PM -0800, Paul E. McKenney wrote:
> > > > On Wed, Jan 04, 2012 at 08:03:39PM +0100, Frederic Weisbecker wrote:
> > > > > Actually for the case of RCU, the wait_for_completion() called by synchronize_rcu()

[ . . . ]

> > > > > rcutiny seems to be fine with the cond_resched() call, but srcu needs
> > > > > a special treatment.
> > > > 
> > > > For the moment, I just applied rcu_lockdep_assert() everywhere -- zero
> > > > cost on non-lockdep kernels, and fully handles all of the RCU simple
> > > > self-deadlock cases.
> > > 
> > > So, for RCU I'm not sure this is useful given the might_sleep() things.
> > > But for srcu it is.
> > 
> > One nice thing about the lockdep approach is that it tracks where the
> > conflicting RCU read-side critical section started.  But I am planning
> > for these to be 3.4 material, so we do have some time to refine them.
> 
> Yeah sure. And in any case it's still good to keep might_sleep() early
> to spot other sources of illegal atomic sections (irqs disabled and co)

Agreed!

							Thanx, Paul

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Sasha Levin]

On Mon, 2011-12-26 at 08:31 -0800, Paul E. McKenney wrote:
> Except that when I try looking for task_notify_func() in current mainline,
> I get nothing.
> 
> Where is task_notify_func() coming from? 

I was testing linux-next, it actually comes from the android tree:
drivers/staging/android/lowmemorykiller.c

-- 

Sasha.

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Paul E. McKenney]

On Tue, Dec 27, 2011 at 11:13:23AM +0200, Sasha Levin wrote:
> On Mon, 2011-12-26 at 08:31 -0800, Paul E. McKenney wrote:
> > Except that when I try looking for task_notify_func() in current mainline,
> > I get nothing.
> > 
> > Where is task_notify_func() coming from? 
> 
> I was testing linux-next, it actually comes from the android tree:
> drivers/staging/android/lowmemorykiller.c

That does sound familiar...  I wonder if the stuff in staging is current
Android or historical stuff.

							Thanx, Paul

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Paul E. McKenney]

On Tue, Dec 27, 2011 at 08:29:59PM -0800, Paul E. McKenney wrote:
> On Tue, Dec 27, 2011 at 11:13:23AM +0200, Sasha Levin wrote:
> > On Mon, 2011-12-26 at 08:31 -0800, Paul E. McKenney wrote:
> > > Except that when I try looking for task_notify_func() in current mainline,
> > > I get nothing.
> > > 
> > > Where is task_notify_func() coming from? 
> > 
> > I was testing linux-next, it actually comes from the android tree:
> > drivers/staging/android/lowmemorykiller.c
> 
> That does sound familiar...  I wonder if the stuff in staging is current
> Android or historical stuff.

And memory did serve for once.  ;-)

Current Android has the following for task_notify_func():

static int
task_notify_func(struct notifier_block *self, unsigned long val, void *data)
{
	struct task_struct *task = data;

	if (task == lowmem_deathpending)
		lowmem_deathpending = NULL;

	return NOTIFY_OK;
}

This is from https://android.googlesource.com/kernel/common.git.

Commit 5545554aac04918ece318270d63cbfcb015577a9 fixed this problem.
The commit is shown below, FYI.

Greg, would it be possible to pull in the current Android code?  There
have been a few fixes.  ;-)

							Thanx, Paul

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

commit 5545554aac04918ece318270d63cbfcb015577a9
Author: Rabin Vincent <rabin.vincent@stericsson.com>
Date:   Thu Sep 9 10:48:21 2010 +0530

    lowmemorykiller: don't unregister notifier from atomic context
    
    The lowmemorykiller registers an atomic notifier for notfication of when
    the task is freed.  From this atomic notifier callback, it removes the
    atomic notifier via task_free_unregister().  This is incorrect because
    atomic_notifier_chain_unregister() calls syncronize_rcu(), which can
    sleep, which shouldn't be done from an atomic notifier.
    
    Fix this by registering the notifier during init, and only unregister it
    if the lowmemorykiller is unloaded.
    
    Change-Id: I1577b04e617bc2b2e39dcb490fcfc9ce660eb7ec
    Signed-off-by: Rabin Vincent <rabin.vincent@stericsson.com>
    Signed-off-by: Christian Bejram <christian.bejram@stericsson.com>

diff --git a/drivers/staging/android/lowmemorykiller.c b/drivers/staging/android/lowmemorykiller.c
index 8b67ac0..efbe556 100644
--- a/drivers/staging/android/lowmemorykiller.c
+++ b/drivers/staging/android/lowmemorykiller.c
@@ -71,10 +71,10 @@ static int
 task_notify_func(struct notifier_block *self, unsigned long val, void *data)
 {
 	struct task_struct *task = data;
-	if (task == lowmem_deathpending) {
+
+	if (task == lowmem_deathpending)
 		lowmem_deathpending = NULL;
-		task_free_unregister(&task_nb);
-	}
+
 	return NOTIFY_OK;
 }
 
@@ -168,7 +168,6 @@ static int lowmem_shrink(struct shrinker *s, int nr_to_scan, gfp_t gfp_mask)
 			     selected->pid, selected->comm,
 			     selected_oom_adj, selected_tasksize);
 		lowmem_deathpending = selected;
-		task_free_register(&task_nb);
 		force_sig(SIGKILL, selected);
 		rem -= selected_tasksize;
 	}
@@ -185,6 +184,7 @@ static struct shrinker lowmem_shrinker = {
 
 static int __init lowmem_init(void)
 {
+	task_free_register(&task_nb);
 	register_shrinker(&lowmem_shrinker);
 	return 0;
 }
@@ -192,6 +192,7 @@ static int __init lowmem_init(void)
 static void __exit lowmem_exit(void)
 {
 	unregister_shrinker(&lowmem_shrinker);
+	task_free_unregister(&task_nb);
 }
 
 module_param_named(cost, lowmem_shrinker.seeks, int, S_IRUGO | S_IWUSR);

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Greg KH]

On Tue, Jan 03, 2012 at 12:27:16PM -0800, Paul E. McKenney wrote:
> On Tue, Dec 27, 2011 at 08:29:59PM -0800, Paul E. McKenney wrote:
> > On Tue, Dec 27, 2011 at 11:13:23AM +0200, Sasha Levin wrote:
> > > On Mon, 2011-12-26 at 08:31 -0800, Paul E. McKenney wrote:
> > > > Except that when I try looking for task_notify_func() in current mainline,
> > > > I get nothing.
> > > > 
> > > > Where is task_notify_func() coming from? 
> > > 
> > > I was testing linux-next, it actually comes from the android tree:
> > > drivers/staging/android/lowmemorykiller.c
> > 
> > That does sound familiar...  I wonder if the stuff in staging is current
> > Android or historical stuff.
> 
> And memory did serve for once.  ;-)
> 
> Current Android has the following for task_notify_func():
> 
> static int
> task_notify_func(struct notifier_block *self, unsigned long val, void *data)
> {
> 	struct task_struct *task = data;
> 
> 	if (task == lowmem_deathpending)
> 		lowmem_deathpending = NULL;
> 
> 	return NOTIFY_OK;
> }
> 
> This is from https://android.googlesource.com/kernel/common.git.
> 
> Commit 5545554aac04918ece318270d63cbfcb015577a9 fixed this problem.
> The commit is shown below, FYI.
> 
> Greg, would it be possible to pull in the current Android code?  There
> have been a few fixes.  ;-)

I did base the stuff in staging on the common.git tree, but for some
reason this patch wasn't applied, odd, I'll go apply it now...

Ah, I see, it didn't apply for various reasons:

patching file drivers/staging/android/lowmemorykiller.c
Hunk #1 FAILED at 71.
Hunk #2 FAILED at 168.
Hunk #3 succeeded at 196 (offset 11 lines).
Hunk #4 succeeded at 204 (offset 11 lines).

Care to rebase this patch and send it to me so that I can apply it?  I
don't have the time to do it myself at the moment, sorry, lots of higher
priority items to get done this week, sorry.

greg k-h

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Paul E. McKenney]

On Tue, Jan 03, 2012 at 12:37:17PM -0800, Greg KH wrote:
> On Tue, Jan 03, 2012 at 12:27:16PM -0800, Paul E. McKenney wrote:
> > On Tue, Dec 27, 2011 at 08:29:59PM -0800, Paul E. McKenney wrote:
> > > On Tue, Dec 27, 2011 at 11:13:23AM +0200, Sasha Levin wrote:
> > > > On Mon, 2011-12-26 at 08:31 -0800, Paul E. McKenney wrote:
> > > > > Except that when I try looking for task_notify_func() in current mainline,
> > > > > I get nothing.
> > > > > 
> > > > > Where is task_notify_func() coming from? 
> > > > 
> > > > I was testing linux-next, it actually comes from the android tree:
> > > > drivers/staging/android/lowmemorykiller.c
> > > 
> > > That does sound familiar...  I wonder if the stuff in staging is current
> > > Android or historical stuff.
> > 
> > And memory did serve for once.  ;-)
> > 
> > Current Android has the following for task_notify_func():
> > 
> > static int
> > task_notify_func(struct notifier_block *self, unsigned long val, void *data)
> > {
> > 	struct task_struct *task = data;
> > 
> > 	if (task == lowmem_deathpending)
> > 		lowmem_deathpending = NULL;
> > 
> > 	return NOTIFY_OK;
> > }
> > 
> > This is from https://android.googlesource.com/kernel/common.git.
> > 
> > Commit 5545554aac04918ece318270d63cbfcb015577a9 fixed this problem.
> > The commit is shown below, FYI.
> > 
> > Greg, would it be possible to pull in the current Android code?  There
> > have been a few fixes.  ;-)
> 
> I did base the stuff in staging on the common.git tree, but for some
> reason this patch wasn't applied, odd, I'll go apply it now...
> 
> Ah, I see, it didn't apply for various reasons:
> 
> patching file drivers/staging/android/lowmemorykiller.c
> Hunk #1 FAILED at 71.
> Hunk #2 FAILED at 168.
> Hunk #3 succeeded at 196 (offset 11 lines).
> Hunk #4 succeeded at 204 (offset 11 lines).
> 
> Care to rebase this patch and send it to me so that I can apply it?  I
> don't have the time to do it myself at the moment, sorry, lots of higher
> priority items to get done this week, sorry.

I will give it a shot.  Working with linux-next -- if some other tree
would be better for you, please let me know.

							Thanx, Paul

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Greg KH]

On Tue, Jan 03, 2012 at 01:38:30PM -0800, Paul E. McKenney wrote:
> On Tue, Jan 03, 2012 at 12:37:17PM -0800, Greg KH wrote:
> > On Tue, Jan 03, 2012 at 12:27:16PM -0800, Paul E. McKenney wrote:
> > > On Tue, Dec 27, 2011 at 08:29:59PM -0800, Paul E. McKenney wrote:
> > > > On Tue, Dec 27, 2011 at 11:13:23AM +0200, Sasha Levin wrote:
> > > > > On Mon, 2011-12-26 at 08:31 -0800, Paul E. McKenney wrote:
> > > > > > Except that when I try looking for task_notify_func() in current mainline,
> > > > > > I get nothing.
> > > > > > 
> > > > > > Where is task_notify_func() coming from? 
> > > > > 
> > > > > I was testing linux-next, it actually comes from the android tree:
> > > > > drivers/staging/android/lowmemorykiller.c
> > > > 
> > > > That does sound familiar...  I wonder if the stuff in staging is current
> > > > Android or historical stuff.
> > > 
> > > And memory did serve for once.  ;-)
> > > 
> > > Current Android has the following for task_notify_func():
> > > 
> > > static int
> > > task_notify_func(struct notifier_block *self, unsigned long val, void *data)
> > > {
> > > 	struct task_struct *task = data;
> > > 
> > > 	if (task == lowmem_deathpending)
> > > 		lowmem_deathpending = NULL;
> > > 
> > > 	return NOTIFY_OK;
> > > }
> > > 
> > > This is from https://android.googlesource.com/kernel/common.git.
> > > 
> > > Commit 5545554aac04918ece318270d63cbfcb015577a9 fixed this problem.
> > > The commit is shown below, FYI.
> > > 
> > > Greg, would it be possible to pull in the current Android code?  There
> > > have been a few fixes.  ;-)
> > 
> > I did base the stuff in staging on the common.git tree, but for some
> > reason this patch wasn't applied, odd, I'll go apply it now...
> > 
> > Ah, I see, it didn't apply for various reasons:
> > 
> > patching file drivers/staging/android/lowmemorykiller.c
> > Hunk #1 FAILED at 71.
> > Hunk #2 FAILED at 168.
> > Hunk #3 succeeded at 196 (offset 11 lines).
> > Hunk #4 succeeded at 204 (offset 11 lines).
> > 
> > Care to rebase this patch and send it to me so that I can apply it?  I
> > don't have the time to do it myself at the moment, sorry, lots of higher
> > priority items to get done this week, sorry.
> 
> I will give it a shot.  Working with linux-next -- if some other tree
> would be better for you, please let me know.

linux-next is great, thanks.

greg k-h

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Paul E. McKenney]

On Tue, Jan 03, 2012 at 01:50:36PM -0800, Greg KH wrote:
> On Tue, Jan 03, 2012 at 01:38:30PM -0800, Paul E. McKenney wrote:

[ . . . ]

> > > > Greg, would it be possible to pull in the current Android code?  There
> > > > have been a few fixes.  ;-)
> > > 
> > > I did base the stuff in staging on the common.git tree, but for some
> > > reason this patch wasn't applied, odd, I'll go apply it now...
> > > 
> > > Ah, I see, it didn't apply for various reasons:
> > > 
> > > patching file drivers/staging/android/lowmemorykiller.c
> > > Hunk #1 FAILED at 71.
> > > Hunk #2 FAILED at 168.
> > > Hunk #3 succeeded at 196 (offset 11 lines).
> > > Hunk #4 succeeded at 204 (offset 11 lines).
> > > 
> > > Care to rebase this patch and send it to me so that I can apply it?  I
> > > don't have the time to do it myself at the moment, sorry, lots of higher
> > > priority items to get done this week, sorry.
> > 
> > I will give it a shot.  Working with linux-next -- if some other tree
> > would be better for you, please let me know.
> 
> linux-next is great, thanks.

Sasha, does the following patch against -next fix this problem for you?

							Thanx, Paul

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

lowmemorykiller: don't unregister notifier from atomic context

The lowmemorykiller registers an atomic notifier for notfication of when
the task is freed.  From this atomic notifier callback, it removes the
atomic notifier via task_free_unregister().  This is incorrect because
atomic_notifier_chain_unregister() calls syncronize_rcu(), which can
sleep, which shouldn't be done from an atomic notifier.

Fix this by registering the notifier during init, and only unregister it
if the lowmemorykiller is unloaded.

Rebased to -next by Paul E. McKenney.

Change-Id: I1577b04e617bc2b2e39dcb490fcfc9ce660eb7ec
Signed-off-by: Rabin Vincent <rabin.vincent@stericsson.com>
Signed-off-by: Christian Bejram <christian.bejram@stericsson.com>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/drivers/staging/android/lowmemorykiller.c b/drivers/staging/android/lowmemorykiller.c
index 2d8d2b7..30076f7 100644
--- a/drivers/staging/android/lowmemorykiller.c
+++ b/drivers/staging/android/lowmemorykiller.c
@@ -72,10 +72,9 @@ static int
 task_notify_func(struct notifier_block *self, unsigned long val, void *data)
 {
 	struct task_struct *task = data;
-	if (task == lowmem_deathpending) {
+	if (task == lowmem_deathpending)
 		lowmem_deathpending = NULL;
-		task_handoff_unregister(&task_nb);
-	}
+
 	return NOTIFY_OK;
 }
 
@@ -172,13 +171,11 @@ static int lowmem_shrink(struct shrinker *s, struct shrink_control *sc)
 			     selected->pid, selected->comm,
 			     selected_oom_adj, selected_tasksize);
 		/*
-		 * If CONFIG_PROFILING is off, then task_handoff_register()
-		 * is a nop. In that case we don't want to stall the killer
-		 * by setting lowmem_deathpending.
+		 * If CONFIG_PROFILING is off, then we don't want to stall
+		 * the killer by setting lowmem_deathpending.
 		 */
 #ifdef CONFIG_PROFILING
 		lowmem_deathpending = selected;
-		task_handoff_register(&task_nb);
 #endif
 		force_sig(SIGKILL, selected);
 		rem -= selected_tasksize;

Re: INFO: task rcuc/0:7 blocked for more than 120 seconds.

[Paul E. McKenney]

On Tue, Jan 03, 2012 at 02:26:05PM -0800, Paul E. McKenney wrote:
> On Tue, Jan 03, 2012 at 01:50:36PM -0800, Greg KH wrote:
> > On Tue, Jan 03, 2012 at 01:38:30PM -0800, Paul E. McKenney wrote:
> 
> [ . . . ]
> 
> > > > > Greg, would it be possible to pull in the current Android code?  There
> > > > > have been a few fixes.  ;-)
> > > > 
> > > > I did base the stuff in staging on the common.git tree, but for some
> > > > reason this patch wasn't applied, odd, I'll go apply it now...
> > > > 
> > > > Ah, I see, it didn't apply for various reasons:
> > > > 
> > > > patching file drivers/staging/android/lowmemorykiller.c
> > > > Hunk #1 FAILED at 71.
> > > > Hunk #2 FAILED at 168.
> > > > Hunk #3 succeeded at 196 (offset 11 lines).
> > > > Hunk #4 succeeded at 204 (offset 11 lines).
> > > > 
> > > > Care to rebase this patch and send it to me so that I can apply it?  I
> > > > don't have the time to do it myself at the moment, sorry, lots of higher
> > > > priority items to get done this week, sorry.
> > > 
> > > I will give it a shot.  Working with linux-next -- if some other tree
> > > would be better for you, please let me know.
> > 
> > linux-next is great, thanks.
> 
> Sasha, does the following patch against -next fix this problem for you?

Sigh!  This time with the full patch...  :-/

							Thanx, Paul

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

lowmemorykiller: don't unregister notifier from atomic context

The lowmemorykiller registers an atomic notifier for notfication of when
the task is freed.  From this atomic notifier callback, it removes the
atomic notifier via task_free_unregister().  This is incorrect because
atomic_notifier_chain_unregister() calls syncronize_rcu(), which can
sleep, which shouldn't be done from an atomic notifier.

Fix this by registering the notifier during init, and only unregister it
if the lowmemorykiller is unloaded.

Rebased to -next by Paul E. McKenney.

Change-Id: I1577b04e617bc2b2e39dcb490fcfc9ce660eb7ec
Signed-off-by: Rabin Vincent <rabin.vincent@stericsson.com>
Signed-off-by: Christian Bejram <christian.bejram@stericsson.com>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/drivers/staging/android/lowmemorykiller.c b/drivers/staging/android/lowmemorykiller.c
index 2d8d2b7..edb2d09 100644
--- a/drivers/staging/android/lowmemorykiller.c
+++ b/drivers/staging/android/lowmemorykiller.c
@@ -72,10 +72,9 @@ static int
 task_notify_func(struct notifier_block *self, unsigned long val, void *data)
 {
 	struct task_struct *task = data;
-	if (task == lowmem_deathpending) {
+	if (task == lowmem_deathpending)
 		lowmem_deathpending = NULL;
-		task_handoff_unregister(&task_nb);
-	}
+
 	return NOTIFY_OK;
 }
 
@@ -172,13 +171,11 @@ static int lowmem_shrink(struct shrinker *s, struct shrink_control *sc)
 			     selected->pid, selected->comm,
 			     selected_oom_adj, selected_tasksize);
 		/*
-		 * If CONFIG_PROFILING is off, then task_handoff_register()
-		 * is a nop. In that case we don't want to stall the killer
-		 * by setting lowmem_deathpending.
+		 * If CONFIG_PROFILING is off, then we don't want to stall
+		 * the killer by setting lowmem_deathpending.
 		 */
 #ifdef CONFIG_PROFILING
 		lowmem_deathpending = selected;
-		task_handoff_register(&task_nb);
 #endif
 		force_sig(SIGKILL, selected);
 		rem -= selected_tasksize;
@@ -196,6 +193,7 @@ static struct shrinker lowmem_shrinker = {
 
 static int __init lowmem_init(void)
 {
+	task_handoff_register(&task_nb);
 	register_shrinker(&lowmem_shrinker);
 	return 0;
 }
@@ -203,6 +201,7 @@ static int __init lowmem_init(void)
 static void __exit lowmem_exit(void)
 {
 	unregister_shrinker(&lowmem_shrinker);
+	task_handoff_unregister(&task_nb);
 }
 
 module_param_named(cost, lowmem_shrinker.seeks, int, S_IRUGO | S_IWUSR);