rcu_preempt detected stalls.

oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

Quoted 6 lines · Dave Jones

oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context) on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

Quoted 11 lines · Sasha Levin

Quoted 6 lines · Dave Jones

oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context) on -next. I guess whatever causing them made it into Linus's tree?

Quoted 1 line

https://lkml.org/lkml/2014/10/11/64

And on that one, I must confess that I don't see where the RCU read-side critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere. Can you reproduce this with CONFIG_PROVE_RCU=y?

Quoted 14 lines · Paul E. McKenney

Quoted 12 lines · Sasha Levin

Quoted 6 lines · Dave Jones

oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context) on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

Quoted 5 lines

And on that one, I must confess that I don't see where the RCU read-side critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere. Can you reproduce this with CONFIG_PROVE_RCU=y?

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU set and nothing else is showing up before/after that.

Quoted 18 lines · Sasha Levin

Quoted 18 lines · Paul E. McKenney

Quoted 17 lines

Quoted 17 lines · Sasha Levin

Quoted 8 lines

Quoted 8 lines · Dave Jones

Quoted 6 lines

Quoted 6 lines

oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

Quoted 4 lines

Quoted 4 lines

I've complained about RCU stalls couple days ago (in a different context) on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

And on that one, I must confess that I don't see where the RCU read-side critical section might be.

Quoted 5 lines

Quoted 5 lines

Quoted 2 lines

Quoted 2 lines

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere. Can you reproduce this with CONFIG_PROVE_RCU=y?

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU set and nothing else is showing up before/after that.

Indeed it was directed to you. ;-)

Does the following crude diagnostic patch turn up anything?

Quoted 22 lines · Paul E. McKenney

Quoted 21 lines · Sasha Levin

Quoted 21 lines · Paul E. McKenney

Quoted 19 lines

Quoted 19 lines · Sasha Levin

Quoted 8 lines

Quoted 8 lines · Dave Jones

Quoted 6 lines

Quoted 6 lines

oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

Quoted 4 lines

Quoted 4 lines

I've complained about RCU stalls couple days ago (in a different context) on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

And on that one, I must confess that I don't see where the RCU read-side critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere. Can you reproduce this with CONFIG_PROVE_RCU=y?

Quoted 5 lines

Quoted 2 lines

Quoted 2 lines

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU set and nothing else is showing up before/after that.

Indeed it was directed to you. ;-)

Does the following crude diagnostic patch turn up anything?

Nope, seeing stalls but not seeing that pr_err() you added.

[ 5107.395916] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 5107.395916]  0: (776 ticks this GP) idle=a8d/140000000000002/0 softirq=16356/16356 last_accelerate: f5b7/55e5, nonlazy_posted: 24252, ..
[ 5107.395916]  (detected by 1, t=20502 jiffies, g=13949, c=13948, q=0)
[ 5107.395916] Task dump for CPU 0:
[ 5107.395916] trinity-c0      R  running task    12848 20357   9041 0x0008000e
[ 5107.395916]  0000000000000000 ffff88006bfd76c0 ffff88065722b988 ffffffffa10af964
[ 5107.395916]  ffff88065722b998 ffffffffa106ad23 ffff88065722b9c8 ffffffffa119dce5
[ 5107.395916]  00000000001d76c0 ffff88006bfd76c0 00000000001d76c0 ffff8806473cbd10
[ 5107.395916] Call Trace:
[ 5107.395916]  [<ffffffffa10af964>] ? kvm_clock_read+0x24/0x40
[ 5107.395916]  [<ffffffffa106ad23>] ? sched_clock+0x13/0x30
[ 5107.395916]  [<ffffffffa119dce5>] ? sched_clock_local+0x25/0x90
[ 5107.395916]  [<ffffffffa1303dfb>] ? __slab_free+0xbb/0x3a0
[ 5107.395916]  [<ffffffffa1b71167>] ? debug_smp_processor_id+0x17/0x20
[ 5107.395916]  [<ffffffffa451cb64>] ? _raw_spin_unlock_irqrestore+0x64/0xa0
[ 5107.395916]  [<ffffffffa1303dfb>] ? __slab_free+0xbb/0x3a0
[ 5107.395916]  [<ffffffffa1b71bce>] ? __debug_check_no_obj_freed+0x10e/0x210
[ 5107.395916]  [<ffffffffa1305871>] ? kmem_cache_free+0xb1/0x4f0
[ 5107.395916]  [<ffffffffa1305883>] ? kmem_cache_free+0xc3/0x4f0
[ 5107.395916]  [<ffffffffa1305bb2>] ? kmem_cache_free+0x3f2/0x4f0
[ 5107.395916]  [<ffffffffa12e0cbe>] ? unlink_anon_vmas+0x10e/0x180
[ 5107.395916]  [<ffffffffa12e0cbe>] ? unlink_anon_vmas+0x10e/0x180
[ 5107.395916]  [<ffffffffa12cfbdf>] ? free_pgtables+0x3f/0x130
[ 5107.395916]  [<ffffffffa12dc1a4>] ? exit_mmap+0xc4/0x180
[ 5107.395916]  [<ffffffffa13143fe>] ? __khugepaged_exit+0xbe/0x120
[ 5107.395916]  [<ffffffffa115bbb3>] ? mmput+0x73/0x110
[ 5107.395916]  [<ffffffffa1162eb7>] ? do_exit+0x2c7/0xd30
[ 5107.395916]  [<ffffffffa1173fb9>] ? get_signal+0x3c9/0xaf0
[ 5107.395916]  [<ffffffffa1b71167>] ? debug_smp_processor_id+0x17/0x20
[ 5107.395916]  [<ffffffffa11bccbe>] ? put_lock_stats.isra.13+0xe/0x30
[ 5107.395916]  [<ffffffffa451c810>] ? _raw_spin_unlock_irq+0x30/0x70
[ 5107.395916]  [<ffffffffa11639c2>] ? do_group_exit+0x52/0xe0
[ 5107.395916]  [<ffffffffa1173ef6>] ? get_signal+0x306/0xaf0
[ 5107.395916]  [<ffffffffa119dce5>] ? sched_clock_local+0x25/0x90
[ 5107.395916]  [<ffffffffa105f2f0>] ? do_signal+0x20/0x130
[ 5107.395916]  [<ffffffffa1298558>] ? context_tracking_user_exit+0x78/0x2d0
[ 5107.395916]  [<ffffffffa1b71183>] ? __this_cpu_preempt_check+0x13/0x20
[ 5107.395916]  [<ffffffffa11c04cb>] ? trace_hardirqs_on_caller+0xfb/0x280
[ 5107.395916]  [<ffffffffa11c065d>] ? trace_hardirqs_on+0xd/0x10
[ 5107.395916]  [<ffffffffa105f469>] ? do_notify_resume+0x69/0xb0
[ 5107.395916]  [<ffffffffa451d74f>] ? int_signal+0x12/0x17

Thanks,
Sasha

Quoted 25 lines · Sasha Levin

Quoted 25 lines · Paul E. McKenney

Quoted 24 lines

Quoted 24 lines · Sasha Levin

Quoted 23 lines

Quoted 23 lines

Quoted 23 lines

Quoted 23 lines · Paul E. McKenney

Quoted 12 lines

Quoted 12 lines

Quoted 12 lines

Quoted 12 lines · Sasha Levin

On 10/13/2014 01:35 PM, Dave Jones wrote:
oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context)
on -next. I guess whatever causing them made it into Linus's tree?

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

Quoted 7 lines

https://lkml.org/lkml/2014/10/11/64

And on that one, I must confess that I don't see where the RCU read-side
critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere.
Can you reproduce this with CONFIG_PROVE_RCU=y?

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU set and nothing else is showing up before/after that.

Quoted 5 lines

Quoted 5 lines

Quoted 3 lines

Quoted 3 lines

Indeed it was directed to you. ;-)

Does the following crude diagnostic patch turn up anything?

Nope, seeing stalls but not seeing that pr_err() you added.

OK, color me confused. Could you please send me the full dmesg or a pointer to it?

Quoted 28 lines · Paul E. McKenney

Quoted 27 lines · Sasha Levin

Quoted 27 lines · Paul E. McKenney

Quoted 26 lines

Quoted 26 lines · Sasha Levin

Quoted 15 lines

Quoted 15 lines

Quoted 15 lines

Quoted 15 lines · Paul E. McKenney

Quoted 14 lines

Quoted 14 lines

Quoted 14 lines

On Tue, Oct 14, 2014 at 10:35:10PM -0400, Sasha Levin wrote:
On 10/13/2014 01:35 PM, Dave Jones wrote:
oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context)
on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

Quoted 8 lines

Quoted 8 lines

Quoted 8 lines

Quoted 8 lines

Quoted 5 lines

Quoted 5 lines

Quoted 5 lines

And on that one, I must confess that I don't see where the RCU read-side
critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere.
Can you reproduce this with CONFIG_PROVE_RCU=y?

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU set and nothing else is showing up before/after that.

Indeed it was directed to you. ;-)

Quoted 5 lines

Quoted 3 lines

Quoted 3 lines

Quoted 1 line

Quoted 1 line

Does the following crude diagnostic patch turn up anything?

Nope, seeing stalls but not seeing that pr_err() you added.

OK, color me confused. Could you please send me the full dmesg or a pointer to it?

Attached.

Quoted 35 lines · Sasha Levin

Quoted 33 lines · Paul E. McKenney

Quoted 23 lines · Sasha Levin

Quoted 23 lines · Paul E. McKenney

Quoted 22 lines

Quoted 22 lines · Sasha Levin

Quoted 21 lines

Quoted 21 lines

Quoted 21 lines

Quoted 21 lines · Paul E. McKenney

Quoted 19 lines

Quoted 19 lines

On Tue, Oct 14, 2014 at 10:35:10PM -0400, Sasha Levin wrote:
On 10/13/2014 01:35 PM, Dave Jones wrote:
oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context)
on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

And on that one, I must confess that I don't see where the RCU read-side
critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere.
Can you reproduce this with CONFIG_PROVE_RCU=y?

Quoted 7 lines

Quoted 7 lines

Quoted 5 lines

Quoted 5 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU set and nothing else is showing up before/after that.

Indeed it was directed to you. ;-)

Does the following crude diagnostic patch turn up anything?

Nope, seeing stalls but not seeing that pr_err() you added.

OK, color me confused. Could you please send me the full dmesg or a pointer to it?

Quoted 1 line

Attached.

Thank you! I would complain about the FAULT_INJECTION messages, but they don't appear to be happening all that frequently.

The stack dumps do look different here. I suspect that this is a real issue in the VM code.

Quoted 36 lines · Paul E. McKenney

Quoted 35 lines · Sasha Levin

Quoted 33 lines · Paul E. McKenney

Quoted 23 lines · Sasha Levin

Quoted 23 lines · Paul E. McKenney

Quoted 22 lines

Quoted 22 lines · Sasha Levin

Quoted 21 lines

Quoted 21 lines

Quoted 21 lines

Quoted 21 lines · Paul E. McKenney

Quoted 19 lines

On Tue, Oct 14, 2014 at 10:35:10PM -0400, Sasha Levin wrote:
On 10/13/2014 01:35 PM, Dave Jones wrote:
oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context)
on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

And on that one, I must confess that I don't see where the RCU read-side
critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere.
Can you reproduce this with CONFIG_PROVE_RCU=y?

Quoted 7 lines

Quoted 7 lines

Quoted 5 lines

Quoted 5 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Quoted 2 lines

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU set and nothing else is showing up before/after that.

Indeed it was directed to you. ;-)

Does the following crude diagnostic patch turn up anything?

Nope, seeing stalls but not seeing that pr_err() you added.

OK, color me confused. Could you please send me the full dmesg or a pointer to it?

Quoted 7 lines

Quoted 1 line

Attached.

Thank you! I would complain about the FAULT_INJECTION messages, but they don't appear to be happening all that frequently.

The stack dumps do look different here. I suspect that this is a real issue in the VM code.

And to that end... The filemap_map_pages() function does have loop over a list of pages. I wonder if the rcu_read_lock() should be moved into the radix_tree_for_each_slot() loop. CCing linux-mm for their thoughts, though it looks to me like the current radix_tree_for_each_slot() wants to be under RCU protection. But I am not seeing anything that requires all iterations of the loop to be under the same RCU read-side critical section. Maybe something like the following patch?

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

mm: Attempted fix for RCU CPU stall warning

It appears that filemap_map_pages() can stay in a single RCU read-side critical section for a very long time if given a large area to map. This could result in RCU CPU stall warnings. This commit therefore breaks the read-side critical section into per-iteration critical sections, taking care to make sure that the radix_tree_for_each_slot() call itself remains in an RCU read-side critical section, as required.

Reported-by Sasha Levin <[email protected]>

Signed-off-by Paul E. McKenney <[email protected]>

mm/filemap.c +0 -0

index 14b4642279f1..f78f144fb41f 100644

Quoted 45 lines · Paul E. McKenney

Quoted 45 lines · Paul E. McKenney

Quoted 43 lines

Quoted 43 lines · Sasha Levin

Quoted 29 lines

Quoted 29 lines · Paul E. McKenney

Quoted 28 lines

Quoted 28 lines · Sasha Levin

Quoted 27 lines

Quoted 27 lines

Quoted 27 lines

Quoted 27 lines · Paul E. McKenney

On Thu, Oct 23, 2014 at 02:55:43PM -0400, Sasha Levin wrote:
On 10/23/2014 02:39 PM, Paul E. McKenney wrote:
On Tue, Oct 14, 2014 at 10:35:10PM -0400, Sasha Levin wrote:
On 10/13/2014 01:35 PM, Dave Jones wrote:
oday in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

I've complained about RCU stalls couple days ago (in a different context)
on -next. I guess whatever causing them made it into Linus's tree?

https://lkml.org/lkml/2014/10/11/64

And on that one, I must confess that I don't see where the RCU read-side
critical section might be.

Hmmm... Maybe someone forgot to put an rcu_read_unlock() somewhere.
Can you reproduce this with CONFIG_PROVE_RCU=y?

Paul, if that was directed to me - Yes, I see stalls with CONFIG_PROVE_RCU
set and nothing else is showing up before/after that.
Indeed it was directed to you. ;-)

Quoted 7 lines

Quoted 7 lines

Quoted 5 lines

Quoted 5 lines

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

Does the following crude diagnostic patch turn up anything?

Nope, seeing stalls but not seeing that pr_err() you added.

OK, color me confused. Could you please send me the full dmesg or a pointer to it?

Attached.

Thank you! I would complain about the FAULT_INJECTION messages, but they don't appear to be happening all that frequently.

The stack dumps do look different here. I suspect that this is a real issue in the VM code.

Quoted 7 lines

Quoted 7 lines

And to that end... The filemap_map_pages() function does have loop over a list of pages. I wonder if the rcu_read_lock() should be moved into the radix_tree_for_each_slot() loop. CCing linux-mm for their thoughts, though it looks to me like the current radix_tree_for_each_slot() wants to be under RCU protection. But I am not seeing anything that requires all iterations of the loop to be under the same RCU read-side critical section. Maybe something like the following patch?

Just following up, did the patch below help?

Thank you! I would complain about the FAULT_INJECTION messages, but they don't appear to be happening all that frequently.

The stack dumps do look different here. I suspect that this is a real issue in the VM code.

Today in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

trinity-c342 R running task 13384 766 32295 0x00000000
ffff880068943d58 0000000000000002 0000000000000002 ffff880193c8c680 00000000001d4100 0000000000000000 ffff880068943fd8 00000000001d4100 ffff88024302c680 ffff880193c8c680 ffff880068943fd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff880d9424>] ? lock_acquire+0xd4/0x2b0
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d4d5>] kill_pid_info+0x45/0x130
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d6d2>] SYSC_kill+0xf2/0x2f0
 [<ffffffff8808d67b>] ? SYSC_kill+0x9b/0x2f0
 [<ffffffff8819c2b7>] ? context_tracking_user_exit+0x57/0x280
 [<ffffffff880136bd>] ? syscall_trace_enter+0x13d/0x310
 [<ffffffff8808fd9e>] SyS_kill+0xe/0x10
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

trinity-c225 R running task 13448 646 32295 0x00000000
ffff880161ccfb28 0000000000000002 ffff880161ccfe10 ffff88000bf85e00 00000000001d4100 0000000000000003 ffff880161ccffd8 00000000001d4100 ffff880030124680 ffff88000bf85e00 ffff880161ccffd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff88233d41>] ? __d_lookup_rcu+0xd1/0x1e0
 [<ffffffff88233dd6>] ? __d_lookup_rcu+0x166/0x1e0
 [<ffffffff88222f9f>] lookup_fast+0x4f/0x3d0
 [<ffffffff88224857>] link_path_walk+0x1a7/0x8a0
 [<ffffffff88224f95>] ? path_lookupat+0x45/0x7b0
 [<ffffffff88224fb7>] path_lookupat+0x67/0x7b0
 [<ffffffff880d385d>] ? trace_hardirqs_off+0xd/0x10
 [<ffffffff8883dda4>] ? retint_restore_args+0xe/0xe
 [<ffffffff8822572b>] filename_lookup+0x2b/0xc0
 [<ffffffff88229c77>] user_path_at_empty+0x67/0xc0

 [<ffffffff880d3dbe>] ? put_lock_stats.isra.27+0xe/0x30
 [<ffffffff880d42a6>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffff880b15ad>] ? get_parent_ip+0xd/0x50
 [<ffffffff88229ce1>] user_path_at+0x11/0x20
 [<ffffffff8824fac1>] do_utimes+0xd1/0x180
 [<ffffffff8824fbef>] SyS_utime+0x7f/0xc0
 [<ffffffff8883d345>] ? tracesys+0x7e/0xe2
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

trinity-c342 R running task 13384 766 32295 0x00000000
ffff880068943d58 0000000000000002 0000000000000002 ffff880193c8c680 00000000001d4100 0000000000000000 ffff880068943fd8 00000000001d4100 ffff88024302c680 ffff880193c8c680 ffff880068943fd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff880d9424>] ? lock_acquire+0xd4/0x2b0
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d4d5>] kill_pid_info+0x45/0x130
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d6d2>] SYSC_kill+0xf2/0x2f0
 [<ffffffff8808d67b>] ? SYSC_kill+0x9b/0x2f0
 [<ffffffff8819c2b7>] ? context_tracking_user_exit+0x57/0x280
 [<ffffffff880136bd>] ? syscall_trace_enter+0x13d/0x310
 [<ffffffff8808fd9e>] SyS_kill+0xe/0x10
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

trinity-c225 R running task 13448 646 32295 0x00000000
ffff880161ccfb28 0000000000000002 ffff880161ccfe10 ffff88000bf85e00 00000000001d4100 0000000000000003 ffff880161ccffd8 00000000001d4100 ffff880030124680 ffff88000bf85e00 ffff880161ccffd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff88233d41>] ? __d_lookup_rcu+0xd1/0x1e0
 [<ffffffff88233dd6>] ? __d_lookup_rcu+0x166/0x1e0
 [<ffffffff88222f9f>] lookup_fast+0x4f/0x3d0
 [<ffffffff88224857>] link_path_walk+0x1a7/0x8a0
 [<ffffffff88224f95>] ? path_lookupat+0x45/0x7b0
 [<ffffffff88224fb7>] path_lookupat+0x67/0x7b0
 [<ffffffff880d385d>] ? trace_hardirqs_off+0xd/0x10
 [<ffffffff8883dda4>] ? retint_restore_args+0xe/0xe
 [<ffffffff8822572b>] filename_lookup+0x2b/0xc0
 [<ffffffff88229c77>] user_path_at_empty+0x67/0xc0
 [<ffffffff880d3dbe>] ? put_lock_stats.isra.27+0xe/0x30
 [<ffffffff880d42a6>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffff880b15ad>] ? get_parent_ip+0xd/0x50
 [<ffffffff88229ce1>] user_path_at+0x11/0x20
 [<ffffffff8824fac1>] do_utimes+0xd1/0x180
 [<ffffffff8824fbef>] SyS_utime+0x7f/0xc0
 [<ffffffff8883d345>] ? tracesys+0x7e/0xe2
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2
INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 3, t=26007 jiffies, g=75434, c=75433, q=0)

trinity-c342 R running task 13384 766 32295 0x00000000
ffff880068943d98 0000000000000002 0000000000000000 ffff880193c8c680 00000000001d4100 0000000000000000 ffff880068943fd8 00000000001d4100 ffff88000188af00 ffff880193c8c680 ffff880068943fd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff8809f767>] ? pid_task+0x47/0xa0
 [<ffffffff8809f73d>] ? pid_task+0x1d/0xa0
 [<ffffffff8808d4f1>] kill_pid_info+0x61/0x130
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d6d2>] SYSC_kill+0xf2/0x2f0
 [<ffffffff8808d67b>] ? SYSC_kill+0x9b/0x2f0
 [<ffffffff8819c2b7>] ? context_tracking_user_exit+0x57/0x280
 [<ffffffff880136bd>] ? syscall_trace_enter+0x13d/0x310
 [<ffffffff8808fd9e>] SyS_kill+0xe/0x10
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

trinity-c225 R running task 13448 646 32295 0x00000000
ffff880161ccfb78 0000000000000002 ffffffff88c993ed ffff88000bf85e00 00000000001d4100 0000000000000003 ffff880161ccffd8 00000000001d4100 ffff88005ea89780 ffff88000bf85e00 ffff880161ccffd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff8822303a>] ? lookup_fast+0xea/0x3d0
 [<ffffffff88223025>] ? lookup_fast+0xd5/0x3d0
 [<ffffffff88224857>] link_path_walk+0x1a7/0x8a0
 [<ffffffff88224f95>] ? path_lookupat+0x45/0x7b0
 [<ffffffff88224fb7>] path_lookupat+0x67/0x7b0
 [<ffffffff880d385d>] ? trace_hardirqs_off+0xd/0x10
 [<ffffffff8883dda4>] ? retint_restore_args+0xe/0xe
 [<ffffffff8822572b>] filename_lookup+0x2b/0xc0
 [<ffffffff88229c77>] user_path_at_empty+0x67/0xc0
 [<ffffffff880d3dbe>] ? put_lock_stats.isra.27+0xe/0x30
 [<ffffffff880d42a6>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffff880b15ad>] ? get_parent_ip+0xd/0x50
 [<ffffffff88229ce1>] user_path_at+0x11/0x20
 [<ffffffff8824fac1>] do_utimes+0xd1/0x180
 [<ffffffff8824fbef>] SyS_utime+0x7f/0xc0
 [<ffffffff8883d345>] ? tracesys+0x7e/0xe2
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

trinity-c342 R running task 13384 766 32295 0x00000000
ffff880068943d98 0000000000000002 0000000000000000 ffff880193c8c680 00000000001d4100 0000000000000000 ffff880068943fd8 00000000001d4100 ffff88000188af00 ffff880193c8c680 ffff880068943fd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff8809f767>] ? pid_task+0x47/0xa0
 [<ffffffff8809f73d>] ? pid_task+0x1d/0xa0
 [<ffffffff8808d4f1>] kill_pid_info+0x61/0x130
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d6d2>] SYSC_kill+0xf2/0x2f0
 [<ffffffff8808d67b>] ? SYSC_kill+0x9b/0x2f0
 [<ffffffff8819c2b7>] ? context_tracking_user_exit+0x57/0x280
 [<ffffffff880136bd>] ? syscall_trace_enter+0x13d/0x310
 [<ffffffff8808fd9e>] SyS_kill+0xe/0x10
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

trinity-c225 R running task 13448 646 32295 0x00000000
ffff880161ccfb78 0000000000000002 ffffffff88c993ed ffff88000bf85e00 00000000001d4100 0000000000000003 ffff880161ccffd8 00000000001d4100 ffff88005ea89780 ffff88000bf85e00 ffff880161ccffd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff8822303a>] ? lookup_fast+0xea/0x3d0
 [<ffffffff88223025>] ? lookup_fast+0xd5/0x3d0
 [<ffffffff88224857>] link_path_walk+0x1a7/0x8a0
 [<ffffffff88224f95>] ? path_lookupat+0x45/0x7b0
 [<ffffffff88224fb7>] path_lookupat+0x67/0x7b0
 [<ffffffff880d385d>] ? trace_hardirqs_off+0xd/0x10
 [<ffffffff8883dda4>] ? retint_restore_args+0xe/0xe
 [<ffffffff8822572b>] filename_lookup+0x2b/0xc0
 [<ffffffff88229c77>] user_path_at_empty+0x67/0xc0
 [<ffffffff880d3dbe>] ? put_lock_stats.isra.27+0xe/0x30
 [<ffffffff880d42a6>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffff880b15ad>] ? get_parent_ip+0xd/0x50
 [<ffffffff88229ce1>] user_path_at+0x11/0x20
 [<ffffffff8824fac1>] do_utimes+0xd1/0x180
 [<ffffffff8824fbef>] SyS_utime+0x7f/0xc0
 [<ffffffff8883d345>] ? tracesys+0x7e/0xe2
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

This is on Linus' current tree, with the new CONFIG_TASKS_RCU unset.

Quoted 17 lines

trinity-c225 R running task 13448 646 32295 0x00000000
ffff880161ccfb28 0000000000000002 ffff880161ccfe10 ffff88000bf85e00 00000000001d4100 0000000000000003 ffff880161ccffd8 00000000001d4100 ffff880030124680 ffff88000bf85e00 ffff880161ccffd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff88233d41>] ? __d_lookup_rcu+0xd1/0x1e0
 [<ffffffff88233dd6>] ? __d_lookup_rcu+0x166/0x1e0
 [<ffffffff88222f9f>] lookup_fast+0x4f/0x3d0
 [<ffffffff88224857>] link_path_walk+0x1a7/0x8a0
 [<ffffffff88224f95>] ? path_lookupat+0x45/0x7b0
 [<ffffffff88224fb7>] path_lookupat+0x67/0x7b0
 [<ffffffff880d385d>] ? trace_hardirqs_off+0xd/0x10
 [<ffffffff8883dda4>] ? retint_restore_args+0xe/0xe
 [<ffffffff8822572b>] filename_lookup+0x2b/0xc0
 [<ffffffff88229c77>] user_path_at_empty+0x67/0xc0

Quoted 8 lines

 [<ffffffff880d3dbe>] ? put_lock_stats.isra.27+0xe/0x30
 [<ffffffff880d42a6>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffff880b15ad>] ? get_parent_ip+0xd/0x50
 [<ffffffff88229ce1>] user_path_at+0x11/0x20
 [<ffffffff8824fac1>] do_utimes+0xd1/0x180
 [<ffffffff8824fbef>] SyS_utime+0x7f/0xc0
 [<ffffffff8883d345>] ? tracesys+0x7e/0xe2
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

This one will require more looking. But did you do something like create a pair of mutually recursive symlinks or something? ;-)

Quoted 26 lines · Paul E. McKenney

Quoted 25 lines

trinity-c225 R running task 13448 646 32295 0x00000000
ffff880161ccfb28 0000000000000002 ffff880161ccfe10 ffff88000bf85e00 00000000001d4100 0000000000000003 ffff880161ccffd8 00000000001d4100 ffff880030124680 ffff88000bf85e00 ffff880161ccffd8 0000000000000000

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff88233d41>] ? __d_lookup_rcu+0xd1/0x1e0
 [<ffffffff88233dd6>] ? __d_lookup_rcu+0x166/0x1e0
 [<ffffffff88222f9f>] lookup_fast+0x4f/0x3d0
 [<ffffffff88224857>] link_path_walk+0x1a7/0x8a0
 [<ffffffff88224f95>] ? path_lookupat+0x45/0x7b0
 [<ffffffff88224fb7>] path_lookupat+0x67/0x7b0
 [<ffffffff880d385d>] ? trace_hardirqs_off+0xd/0x10
 [<ffffffff8883dda4>] ? retint_restore_args+0xe/0xe
 [<ffffffff8822572b>] filename_lookup+0x2b/0xc0
 [<ffffffff88229c77>] user_path_at_empty+0x67/0xc0
 [<ffffffff880d3dbe>] ? put_lock_stats.isra.27+0xe/0x30
 [<ffffffff880d42a6>] ? lock_release_holdtime.part.28+0xe6/0x160
 [<ffffffff880b15ad>] ? get_parent_ip+0xd/0x50
 [<ffffffff88229ce1>] user_path_at+0x11/0x20
 [<ffffffff8824fac1>] do_utimes+0xd1/0x180
 [<ffffffff8824fbef>] SyS_utime+0x7f/0xc0
 [<ffffffff8883d345>] ? tracesys+0x7e/0xe2
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

Quoted 2 lines

This one will require more looking. But did you do something like create a pair of mutually recursive symlinks or something? ;-)

I'm not 100% sure, but this may have been on a box that I was running tests on NFS. So maybe the server had disappeared with the mount still active..

Just a guess tbh.

Quoted 7 lines

Quoted 2 lines

This one will require more looking. But did you do something like create a pair of mutually recursive symlinks or something? ;-)

I'm not 100% sure, but this may have been on a box that I was running tests on NFS. So maybe the server had disappeared with the mount still active..

Quoted 1 line

Just a guess tbh.

Another possibility might be that the box was so overloaded that tasks were getting preempted for 21 seconds as a matter of course, and sometimes within RCU read-side critical sections. Or did the box have ample idle time?

Quoted 9 lines · Paul E. McKenney

Quoted 8 lines

Quoted 2 lines

This one will require more looking. But did you do something like create a pair of mutually recursive symlinks or something? ;-)

I'm not 100% sure, but this may have been on a box that I was running tests on NFS. So maybe the server had disappeared with the mount still active..

Just a guess tbh.

Quoted 4 lines

Another possibility might be that the box was so overloaded that tasks were getting preempted for 21 seconds as a matter of course, and sometimes within RCU read-side critical sections. Or did the box have ample idle time?

I fairly recently upped the number of child processes I typically run with, so it being overloaded does sound highly likely.

Quoted 16 lines · Dave Jones

Quoted 13 lines · Paul E. McKenney

Quoted 8 lines

Quoted 2 lines

This one will require more looking. But did you do something like create a pair of mutually recursive symlinks or something? ;-)

I'm not 100% sure, but this may have been on a box that I was running tests on NFS. So maybe the server had disappeared with the mount still active..

Just a guess tbh.

Another possibility might be that the box was so overloaded that tasks were getting preempted for 21 seconds as a matter of course, and sometimes within RCU read-side critical sections. Or did the box have ample idle time?

Quoted 2 lines

I fairly recently upped the number of child processes I typically run with, so it being overloaded does sound highly likely.

Ah, that could do it! One way to test extreme loads and not trigger RCU CPU stall warnings might be to make all of your child processes all sleep during a given interval of a few hundred milliseconds during each ten-second interval. Would that work for you?

Quoted 17 lines · Paul E. McKenney

Quoted 16 lines · Dave Jones

Quoted 13 lines · Paul E. McKenney

Quoted 8 lines

Quoted 2 lines

This one will require more looking. But did you do something like create a pair of mutually recursive symlinks or something? ;-)

I'm not 100% sure, but this may have been on a box that I was running tests on NFS. So maybe the server had disappeared with the mount still active..

Just a guess tbh.

Another possibility might be that the box was so overloaded that tasks were getting preempted for 21 seconds as a matter of course, and sometimes within RCU read-side critical sections. Or did the box have ample idle time?

Quoted 7 lines

Quoted 2 lines

I fairly recently upped the number of child processes I typically run with, so it being overloaded does sound highly likely.

Ah, that could do it! One way to test extreme loads and not trigger RCU CPU stall warnings might be to make all of your child processes all sleep during a given interval of a few hundred milliseconds during each ten-second interval. Would that work for you?

This feels like hiding from the problem rather than fixing it. I'm not sure it even makes sense to add sleeps to the fuzzer, other than to slow things down, and if I were to do that, I may as well just run it with fewer threads instead.

While the fuzzer is doing pretty crazy stuff, what's different about it from any other application that overcommits the CPU with too many threads?

We impose rlimits to stop people from forkbombing and the like, but this doesn't even need that many processes to trigger, and with some effort could probably done with even fewer if I found ways to keep other cores busy in the kernel for long enough.

That all said, I don't have easy reproducers for this right now, due to other bugs manifesting long before this gets to be a problem.

Quoted 10 lines · Dave Jones

Today in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

trinity-c342 R running task 13384 766 32295 0x00000000
ffff880068943d58 0000000000000002 0000000000000002 ffff880193c8c680 00000000001d4100 0000000000000000 ffff880068943fd8 00000000001d4100 ffff88024302c680 ffff880193c8c680 ffff880068943fd8 0000000000000000

Quoted 13 lines

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff880d9424>] ? lock_acquire+0xd4/0x2b0
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d4d5>] kill_pid_info+0x45/0x130
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d6d2>] SYSC_kill+0xf2/0x2f0
 [<ffffffff8808d67b>] ? SYSC_kill+0x9b/0x2f0
 [<ffffffff8819c2b7>] ? context_tracking_user_exit+0x57/0x280
 [<ffffffff880136bd>] ? syscall_trace_enter+0x13d/0x310
 [<ffffffff8808fd9e>] SyS_kill+0xe/0x10
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

Well, there is a loop in kill_pid_info(). I am surprised that it would loop indefinitely, but if it did, you would certainly get RCU CPU stalls. Please see patch below, adding Oleg for his thoughts.

Quoted 26 lines · Paul E. McKenney

Quoted 10 lines · Dave Jones

Today in "rcu stall while fuzzing" news:

INFO: rcu_preempt detected stalls on CPUs/tasks:
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	Tasks blocked on level-0 rcu_node (CPUs 0-3): P766 P646
	(detected by 0, t=6502 jiffies, g=75434, c=75433, q=0)

trinity-c342 R running task 13384 766 32295 0x00000000
ffff880068943d58 0000000000000002 0000000000000002 ffff880193c8c680 00000000001d4100 0000000000000000 ffff880068943fd8 00000000001d4100 ffff88024302c680 ffff880193c8c680 ffff880068943fd8 0000000000000000

Quoted 13 lines

Call Trace:
 [<ffffffff888368e2>] preempt_schedule_irq+0x52/0xb0
 [<ffffffff8883df10>] retint_kernel+0x20/0x30
 [<ffffffff880d9424>] ? lock_acquire+0xd4/0x2b0
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d4d5>] kill_pid_info+0x45/0x130
 [<ffffffff8808d495>] ? kill_pid_info+0x5/0x130
 [<ffffffff8808d6d2>] SYSC_kill+0xf2/0x2f0
 [<ffffffff8808d67b>] ? SYSC_kill+0x9b/0x2f0
 [<ffffffff8819c2b7>] ? context_tracking_user_exit+0x57/0x280
 [<ffffffff880136bd>] ? syscall_trace_enter+0x13d/0x310
 [<ffffffff8808fd9e>] SyS_kill+0xe/0x10
 [<ffffffff8883d3a4>] tracesys+0xdd/0xe2

Quoted 3 lines

Well, there is a loop in kill_pid_info(). I am surprised that it would loop indefinitely, but if it did, you would certainly get RCU CPU stalls. Please see patch below, adding Oleg for his thoughts.

Yes, this loops should not be a problem, we only restart if we race with a multi-threaded exec from a non-leader thread.

But I already saw a couple of bug-reports which look as a task_struct corruption (->signal/creds == NULL), looks like something was broken recently. Perhaps an unbalanced put_task_struct...

_Perhaps_ this is another case. If ->sighand was nullified then it will loop forever.

OK, so making each pass through the loop a separate RCU read-side critical section might be considered to be suppressing notification of an error condition?

Quoted 4 lines · Paul E. McKenney

OK, so making each pass through the loop a separate RCU read-side critical section might be considered to be suppressing notification of an error condition?

I agree, this change probably makes sense anyway. Personally I'd prefer the version below (somehow I hate multiple unlock's), but I won't insist.

Your code, your rules. ;-)

But given this structure, why not use a for() loop replace the "goto retry" with an inverted condition and a "return error"? Maybe something like the following patch?

Quoted 2 lines · Paul E. McKenney

Your code, your rules. ;-)

Heh, no. I do not trust my (perverted) taste, I never-never argue with cosmetic issues ;)

Cough... and at the same time I have a small nit.

Quoted 3 lines

But given this structure, why not use a for() loop replace the "goto retry" with an inverted condition and a "return error"? Maybe something like the following patch?

Thanks,

Acked-by Oleg Nesterov <[email protected]>

Today in "rcu stall while fuzzing" news: