Re: localed stuck in recent 3.18 git in copy_net_ns?

[Eric W. Biederman]

"Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx> writes:

> On Wed, Oct 22, 2014 at 12:53:24PM -0500, Eric W. Biederman wrote:
>> Cong Wang <cwang@xxxxxxxxxxxxxxxx> writes:
>> 
>> > (Adding Paul and Eric in Cc)
>> >
>> >
>> > On Wed, Oct 22, 2014 at 10:12 AM, Josh Boyer <jwboyer@xxxxxxxxxxxxxxxxx> wrote:
>> >>
>> >> Someone else is seeing this when they try and modprobe ppp_generic:
>> >>
>> >> [  240.599195] INFO: task kworker/u16:5:100 blocked for more than 120 seconds.
>> >> [  240.599338]       Not tainted 3.18.0-0.rc1.git2.1.fc22.x86_64 #1
>> >> [  240.599446] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> >> disables this message.
>> >> [  240.599583] kworker/u16:5   D ffff8802202db480 12400   100      2 0x00000000
>> >> [  240.599744] Workqueue: netns cleanup_net
>> >> [  240.599823]  ffff8802202eb9e8 0000000000000096 ffff8802202db480
>> >> 00000000001d5f00
>> >> [  240.600066]  ffff8802202ebfd8 00000000001d5f00 ffff8800368c3480
>> >> ffff8802202db480
>> >> [  240.600228]  ffffffff81ee2690 7fffffffffffffff ffffffff81ee2698
>> >> ffffffff81ee2690
>> >> [  240.600386] Call Trace:
>> >> [  240.600445]  [<ffffffff8185e239>] schedule+0x29/0x70
>> >> [  240.600541]  [<ffffffff8186345c>] schedule_timeout+0x26c/0x410
>> >> [  240.600651]  [<ffffffff81865ef7>] ? retint_restore_args+0x13/0x13
>> >> [  240.600765]  [<ffffffff818644e4>] ? _raw_spin_unlock_irq+0x34/0x50
>> >> [  240.600879]  [<ffffffff8185fc6c>] wait_for_completion+0x10c/0x150
>> >> [  240.601025]  [<ffffffff810e53e0>] ? wake_up_state+0x20/0x20
>> >> [  240.601133]  [<ffffffff8112a749>] _rcu_barrier+0x159/0x200
>> >> [  240.601237]  [<ffffffff8112a845>] rcu_barrier+0x15/0x20
>> >> [  240.601335]  [<ffffffff81718ebf>] netdev_run_todo+0x6f/0x310
>> >> [  240.601442]  [<ffffffff8170da85>] ? rollback_registered_many+0x265/0x2e0
>> >> [  240.601564]  [<ffffffff81725f2e>] rtnl_unlock+0xe/0x10
>> >> [  240.601660]  [<ffffffff8170f8e6>] default_device_exit_batch+0x156/0x180
>> >> [  240.601781]  [<ffffffff810fd8a0>] ? abort_exclusive_wait+0xb0/0xb0
>> >> [  240.601895]  [<ffffffff81707993>] ops_exit_list.isra.1+0x53/0x60
>> >> [  240.602028]  [<ffffffff81708540>] cleanup_net+0x100/0x1f0
>> >> [  240.602131]  [<ffffffff810ccfa8>] process_one_work+0x218/0x850
>> >> [  240.602241]  [<ffffffff810ccf0f>] ? process_one_work+0x17f/0x850
>> >> [  240.602350]  [<ffffffff810cd6c7>] ? worker_thread+0xe7/0x4a0
>> >> [  240.602454]  [<ffffffff810cd64b>] worker_thread+0x6b/0x4a0
>> >> [  240.602555]  [<ffffffff810cd5e0>] ? process_one_work+0x850/0x850
>> >> [  240.602665]  [<ffffffff810d399b>] kthread+0x10b/0x130
>> >> [  240.602762]  [<ffffffff81028cc9>] ? sched_clock+0x9/0x10
>> >> [  240.602862]  [<ffffffff810d3890>] ? kthread_create_on_node+0x250/0x250
>> >> [  240.603004]  [<ffffffff818651fc>] ret_from_fork+0x7c/0xb0
>> >> [  240.603106]  [<ffffffff810d3890>] ? kthread_create_on_node+0x250/0x250
>> >> [  240.603224] 4 locks held by kworker/u16:5/100:
>> >> [  240.603304]  #0:  ("%s""netns"){.+.+.+}, at: [<ffffffff810ccf0f>]
>> >> process_one_work+0x17f/0x850
>> >> [  240.603495]  #1:  (net_cleanup_work){+.+.+.}, at:
>> >> [<ffffffff810ccf0f>] process_one_work+0x17f/0x850
>> >> [  240.603691]  #2:  (net_mutex){+.+.+.}, at: [<ffffffff817084cc>]
>> >> cleanup_net+0x8c/0x1f0
>> >> [  240.603869]  #3:  (rcu_sched_state.barrier_mutex){+.+...}, at:
>> >> [<ffffffff8112a625>] _rcu_barrier+0x35/0x200
>> >> [  240.604211] INFO: task modprobe:1387 blocked for more than 120 seconds.
>> >> [  240.604329]       Not tainted 3.18.0-0.rc1.git2.1.fc22.x86_64 #1
>> >> [  240.604434] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> >> disables this message.
>> >> [  240.604570] modprobe        D ffff8800cb4f1a40 13112  1387   1386 0x00000080
>> >> [  240.604719]  ffff8800cafbbbe8 0000000000000096 ffff8800cb4f1a40
>> >> 00000000001d5f00
>> >> [  240.604878]  ffff8800cafbbfd8 00000000001d5f00 ffff880223280000
>> >> ffff8800cb4f1a40
>> >> [  240.605068]  ffff8800cb4f1a40 ffffffff81f8fb48 0000000000000246
>> >> ffff8800cb4f1a40
>> >> [  240.605228] Call Trace:
>> >> [  240.605283]  [<ffffffff8185e7e1>] schedule_preempt_disabled+0x31/0x80
>> >> [  240.605400]  [<ffffffff81860033>] mutex_lock_nested+0x183/0x440
>> >> [  240.605510]  [<ffffffff8170835f>] ? register_pernet_subsys+0x1f/0x50
>> >> [  240.605626]  [<ffffffff8170835f>] ? register_pernet_subsys+0x1f/0x50
>> >> [  240.605757]  [<ffffffffa0701000>] ? 0xffffffffa0701000
>> >> [  240.605854]  [<ffffffff8170835f>] register_pernet_subsys+0x1f/0x50
>> >> [  240.606005]  [<ffffffffa0701048>] br_init+0x48/0xd3 [bridge]
>> >> [  240.606112]  [<ffffffff81002148>] do_one_initcall+0xd8/0x210
>> >> [  240.606224]  [<ffffffff81153c02>] load_module+0x20c2/0x2870
>> >> [  240.606327]  [<ffffffff8114ebe0>] ? store_uevent+0x70/0x70
>> >> [  240.606433]  [<ffffffff8110ac26>] ? lock_release_non_nested+0x3c6/0x3d0
>> >> [  240.606557]  [<ffffffff81154497>] SyS_init_module+0xe7/0x140
>> >> [  240.606664]  [<ffffffff818652a9>] system_call_fastpath+0x12/0x17
>> >> [  240.606773] 1 lock held by modprobe/1387:
>> >> [  240.606845]  #0:  (net_mutex){+.+.+.}, at: [<ffffffff8170835f>]
>> >> register_pernet_subsys+0x1f/0x50
>> >> [  240.607114] INFO: task modprobe:1466 blocked for more than 120 seconds.
>> >> [  240.607231]       Not tainted 3.18.0-0.rc1.git2.1.fc22.x86_64 #1
>> >> [  240.607337] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
>> >> disables this message.
>> >> [  240.607473] modprobe        D ffff88020fbab480 13096  1466   1399 0x00000084
>> >> [  240.607622]  ffff88020d1bbbe8 0000000000000096 ffff88020fbab480
>> >> 00000000001d5f00
>> >> [  240.607791]  ffff88020d1bbfd8 00000000001d5f00 ffffffff81e1b580
>> >> ffff88020fbab480
>> >> [  240.607949]  ffff88020fbab480 ffffffff81f8fb48 0000000000000246
>> >> ffff88020fbab480
>> >> [  240.608138] Call Trace:
>> >> [  240.608193]  [<ffffffff8185e7e1>] schedule_preempt_disabled+0x31/0x80
>> >> [  240.608316]  [<ffffffff81860033>] mutex_lock_nested+0x183/0x440
>> >> [  240.608425]  [<ffffffff817083ad>] ? register_pernet_device+0x1d/0x70
>> >> [  240.608542]  [<ffffffff817083ad>] ? register_pernet_device+0x1d/0x70
>> >> [  240.608662]  [<ffffffffa071d000>] ? 0xffffffffa071d000
>> >> [  240.608759]  [<ffffffff817083ad>] register_pernet_device+0x1d/0x70
>> >> [  240.608881]  [<ffffffffa071d020>] ppp_init+0x20/0x1000 [ppp_generic]
>> >> [  240.609021]  [<ffffffff81002148>] do_one_initcall+0xd8/0x210
>> >> [  240.609131]  [<ffffffff81153c02>] load_module+0x20c2/0x2870
>> >> [  240.609235]  [<ffffffff8114ebe0>] ? store_uevent+0x70/0x70
>> >> [  240.609339]  [<ffffffff8110ac26>] ? lock_release_non_nested+0x3c6/0x3d0
>> >> [  240.609462]  [<ffffffff81154497>] SyS_init_module+0xe7/0x140
>> >> [  240.609568]  [<ffffffff818652a9>] system_call_fastpath+0x12/0x17
>> >> [  240.609677] 1 lock held by modprobe/1466:
>> >> [  240.609749]  #0:  (net_mutex){+.+.+.}, at: [<ffffffff817083ad>]
>> >> register_pernet_device+0x1d/0x70
>> >>
>> >> Looks like contention on net_mutex or something, but I honestly have
>> >> no idea yet.  I can't recreate it myself at the moment or I would
>> >> bisect.
>> >>
>> >> Has nobody else run into this with the pre-3.18 kernels?  Fedora isn't
>> >> carrying any patches in this area.
>> 
>> > I am not aware of any change in net/core/dev.c related here,
>> > so I guess it's a bug in rcu_barrier().
>> 
>> >From the limited trace data I see in this email I have to agree.
>> 
>> It looks like for some reason rcu_barrier is taking forever
>> while the rtnl_lock is held in cleanup_net.  Because the
>> rtnl_lock is held modprobe of the ppp driver is getting stuck.
>> 
>> Is it possible we have an AB BA deadlock between the rtnl_lock
>> and rcu.  With something the module loading code assumes?
>
> I am not aware of RCU ever acquiring rtnl_lock, not directly, anyway.

Does the module loading code do something strange with rcu?  Perhaps
blocking an rcu grace period until the module loading completes?

If the module loading somehow blocks an rcu grace period that would
create an AB deadlock because loading the ppp module grabs the
rtnl_lock.  And elsewhere we have the rtnl_lock waiting for an rcu grace
period.

I would think trying and failing to get the rtnl_lock would sleep and
thus let any rcu grace period happen but shrug.

It looks like something is holding up the rcu grace period, and causing
this.  Although it is possible that something is causing cleanup_net
to run slowly and we are just seeing that slowness show up in
rcu_barrier as that is one of the slower bits.  With a single trace I
can't definitely same that the rcu barrier is getting stuck but it
certainly looks that way.

Eric
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/