From: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
To: "Eric W. Biederman" <ebiederm@xmission.com>
Cc: Cong Wang <cwang@twopensource.com>,
Josh Boyer <jwboyer@fedoraproject.org>,
Kevin Fenzi <kevin@scrye.com>, netdev <netdev@vger.kernel.org>,
"Linux-Kernel@Vger. Kernel. Org" <linux-kernel@vger.kernel.org>
Subject: Re: localed stuck in recent 3.18 git in copy_net_ns?
Date: Wed, 22 Oct 2014 11:55:11 -0700 [thread overview]
Message-ID: <20141022185511.GI4977@linux.vnet.ibm.com> (raw)
In-Reply-To: <87d29kezby.fsf@x220.int.ebiederm.org>
On Wed, Oct 22, 2014 at 01:25:37PM -0500, Eric W. Biederman wrote:
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> writes:
>
> > On Wed, Oct 22, 2014 at 12:53:24PM -0500, Eric W. Biederman wrote:
> >> Cong Wang <cwang@twopensource.com> writes:
> >>
> >> > (Adding Paul and Eric in Cc)
> >> >
> >> >
> >> > On Wed, Oct 22, 2014 at 10:12 AM, Josh Boyer <jwboyer@fedoraproject.org> 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.
Don't get me wrong -- the fact that this kthread appears to have
blocked within rcu_barrier() for 120 seconds means that something is
most definitely wrong here. I am surprised that there are no RCU CPU
stall warnings, but perhaps the blockage is in the callback execution
rather than grace-period completion. Or something is preventing this
kthread from starting up after the wake-up callback executes. Or...
Is this thing reproducible?
Thanx, Paul
next prev parent reply other threads:[~2014-10-22 18:55 UTC|newest]
Thread overview: 63+ messages / expand[flat|nested] mbox.gz Atom feed top
2014-10-20 20:15 localed stuck in recent 3.18 git in copy_net_ns? Kevin Fenzi
2014-10-20 20:43 ` Dave Jones
2014-10-20 20:53 ` Kevin Fenzi
2014-10-21 21:12 ` Kevin Fenzi
2014-10-22 17:12 ` Josh Boyer
2014-10-22 17:37 ` Cong Wang
2014-10-22 17:49 ` Josh Boyer
2014-10-22 17:53 ` Eric W. Biederman
2014-10-22 18:11 ` Paul E. McKenney
2014-10-22 18:25 ` Eric W. Biederman
2014-10-22 18:55 ` Paul E. McKenney [this message]
2014-10-22 19:33 ` Josh Boyer
2014-10-22 22:40 ` Yanko Kaneti
2014-10-22 23:24 ` Paul E. McKenney
2014-10-23 6:09 ` Yanko Kaneti
2014-10-23 12:27 ` Paul E. McKenney
2014-10-23 15:33 ` Paul E. McKenney
[not found] ` <CA+5PVA4H6EAf6cBc4a_8W8x4Mgppjc5GsskKaCRry2jq+LP+FA@mail.gmail.com>
2014-10-23 16:28 ` Paul E. McKenney
2014-10-23 19:51 ` Yanko Kaneti
2014-10-23 20:05 ` Paul E. McKenney
2014-10-23 21:45 ` Yanko Kaneti
2014-10-23 22:04 ` Paul E. McKenney
2014-10-24 4:48 ` Jay Vosburgh
2014-10-24 14:50 ` Paul E. McKenney
2014-10-24 18:20 ` Jay Vosburgh
2014-10-24 18:33 ` Paul E. McKenney
2014-10-24 9:08 ` Yanko Kaneti
2014-10-24 15:40 ` Paul E. McKenney
2014-10-24 16:29 ` Yanko Kaneti
2014-10-24 16:54 ` Paul E. McKenney
2014-10-24 17:09 ` Yanko Kaneti
2014-10-24 17:20 ` Paul E. McKenney
2014-10-24 17:35 ` Yanko Kaneti
2014-10-24 18:32 ` Paul E. McKenney
2014-10-24 18:49 ` Jay Vosburgh
2014-10-24 18:57 ` Paul E. McKenney
2014-10-24 20:15 ` Paul E. McKenney
2014-10-24 21:25 ` Yanko Kaneti
2014-10-24 21:49 ` Paul E. McKenney
2014-10-24 22:02 ` Jay Vosburgh
2014-10-24 22:16 ` Paul E. McKenney
2014-10-24 22:41 ` Jay Vosburgh
2014-10-24 22:34 ` Jay Vosburgh
2014-10-24 22:59 ` Paul E. McKenney
2014-10-24 23:05 ` Paul E. McKenney
2014-10-25 0:20 ` Jay Vosburgh
2014-10-25 2:03 ` Paul E. McKenney
2014-10-25 4:33 ` Jay Vosburgh
2014-10-25 5:16 ` Paul E. McKenney
2014-10-25 16:38 ` Jay Vosburgh
2014-10-25 18:18 ` Paul E. McKenney
2014-10-27 17:45 ` Paul E. McKenney
2014-10-27 20:43 ` Jay Vosburgh
2014-10-27 21:07 ` Paul E. McKenney
2014-10-28 8:12 ` Yanko Kaneti
2014-10-28 12:50 ` Paul E. McKenney
2014-10-28 13:00 ` Yanko Kaneti
2014-10-28 15:54 ` Kevin Fenzi
2014-10-28 16:15 ` Paul E. McKenney
2014-10-25 12:09 ` Yanko Kaneti
2014-10-25 13:38 ` Paul E. McKenney
2014-10-22 17:59 ` Paul E. McKenney
2014-10-22 18:03 ` Josh Boyer
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20141022185511.GI4977@linux.vnet.ibm.com \
--to=paulmck@linux.vnet.ibm.com \
--cc=cwang@twopensource.com \
--cc=ebiederm@xmission.com \
--cc=jwboyer@fedoraproject.org \
--cc=kevin@scrye.com \
--cc=linux-kernel@vger.kernel.org \
--cc=netdev@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).