From: Dave Jones <hidden> Date: 2014-10-20 20:43:38
On Mon, Oct 20, 2014 at 02:15:15PM -0600, Kevin Fenzi wrote:
> I'm seeing suspend/resume failures with recent 3.18 git kernels.
>
> Full dmesg at: http://paste.fedoraproject.org/143615/83287914/
>
> The possibly interesting parts:
>
> [ 78.373144] PM: Syncing filesystems ... done.
> [ 78.411180] PM: Preparing system for mem sleep
> [ 78.411995] Freezing user space processes ...
> [ 98.429955] Freezing of tasks failed after 20.001 seconds (1 tasks refusing to freeze, wq_busy=0):
> [ 98.429971] (-localed) D ffff88025f214c80 0 1866 1 0x00000084
> [ 98.429975] ffff88024e777df8 0000000000000086 ffff88009b4444b0 0000000000014c80
> [ 98.429978] ffff88024e777fd8 0000000000014c80 ffff880250ffb110 ffff88009b4444b0
> [ 98.429981] 0000000000000000 ffffffff81cec1a0 ffffffff81cec1a4 ffff88009b4444b0
> [ 98.429983] Call Trace:
> [ 98.429991] [<ffffffff8175d619>] schedule_preempt_disabled+0x29/0x70
> [ 98.429994] [<ffffffff8175f433>] __mutex_lock_slowpath+0xb3/0x120
> [ 98.429997] [<ffffffff8175f4c3>] mutex_lock+0x23/0x40
> [ 98.430001] [<ffffffff8163e325>] copy_net_ns+0x75/0x140
> [ 98.430005] [<ffffffff810b8c2d>] create_new_namespaces+0xfd/0x1a0
> [ 98.430008] [<ffffffff810b8e5a>] unshare_nsproxy_namespaces+0x5a/0xc0
> [ 98.430012] [<ffffffff81098813>] SyS_unshare+0x193/0x340
> [ 98.430015] [<ffffffff817617a9>] system_call_fastpath+0x12/0x17
I've seen similar soft lockup traces from the sys_unshare path when running my
fuzz tester. It seems that if you create enough network namespaces,
it can take a huge amount of time for them to be iterated.
(Running trinity with '-c unshare' you can see the slow down happen. In
some cases, it takes so long that the watchdog process kills it --
though the SIGKILL won't get delivered until the unshare() completes)
Any idea what this machine had been doing prior to this that may have
involved creating lots of namespaces ?
Dave
From: Kevin Fenzi <hidden> Date: 2014-10-20 20:54:04
On Mon, 20 Oct 2014 16:43:26 -0400
Dave Jones [off-list ref] wrote:
I've seen similar soft lockup traces from the sys_unshare path when
running my fuzz tester. It seems that if you create enough network
namespaces, it can take a huge amount of time for them to be iterated.
(Running trinity with '-c unshare' you can see the slow down happen.
In some cases, it takes so long that the watchdog process kills it --
though the SIGKILL won't get delivered until the unshare() completes)
Any idea what this machine had been doing prior to this that may have
involved creating lots of namespaces ?
That was right after boot. ;)
This is my main rawhide running laptop.
A 'ip netns list' shows nothing.
kevin
From: Kevin Fenzi <hidden> Date: 2014-10-21 21:12:31
On Mon, 20 Oct 2014 14:53:59 -0600
Kevin Fenzi [off-list ref] wrote:
On Mon, 20 Oct 2014 16:43:26 -0400
Dave Jones [off-list ref] wrote:
quoted
I've seen similar soft lockup traces from the sys_unshare path when
running my fuzz tester. It seems that if you create enough network
namespaces, it can take a huge amount of time for them to be
iterated. (Running trinity with '-c unshare' you can see the slow
down happen. In some cases, it takes so long that the watchdog
process kills it -- though the SIGKILL won't get delivered until
the unshare() completes)
Any idea what this machine had been doing prior to this that may
have involved creating lots of namespaces ?
That was right after boot. ;)
This is my main rawhide running laptop.
A 'ip netns list' shows nothing.
Some more information:
The problem started between:
v3.17-7872-g5ff0b9e1a1da and v3.17-8307-gf1d0d14120a8
(I can try and do a bisect, but have to head out on a trip tomorrow)
In all the kernels with the problem, there is a kworker process in D.
sysrq-t says:
Showing all locks held in the system:
Oct 21 15:06:31 voldemort.scrye.com kernel: 4 locks held by kworker/u16:0/6:
Oct 21 15:06:31 voldemort.scrye.com kernel: #0: ("%s""netns"){.+.+.+}, at: [<ffffffff810ccbff>] process_one_work+0x17f/0x850
Oct 21 15:06:31 voldemort.scrye.com kernel: #1: (net_cleanup_work){+.+.+.}, at: [<ffffffff810ccbff>] process_one_work+0x17f/0x850
Oct 21 15:06:31 voldemort.scrye.com kernel: #2: (net_mutex){+.+.+.}, at: [<ffffffff817069fc>] cleanup_net+0x8c/0x1f0
Oct 21 15:06:31 voldemort.scrye.com kernel: #3:
(rcu_sched_state.barrier_mutex){+.+...}, at: [<ffffffff8112a395>]
_rcu_barrier+0x35/0x200
On first running any of the systemd units that use PrivateNetwork, then
run ok, but they are also set to timeout after a minute. On sucessive
runs they hang in D also.
kevin
On Tue, Oct 21, 2014 at 5:12 PM, Kevin Fenzi [off-list ref] wrote:
On Mon, 20 Oct 2014 14:53:59 -0600
Kevin Fenzi [off-list ref] wrote:
quoted
On Mon, 20 Oct 2014 16:43:26 -0400
Dave Jones [off-list ref] wrote:
quoted
I've seen similar soft lockup traces from the sys_unshare path when
running my fuzz tester. It seems that if you create enough network
namespaces, it can take a huge amount of time for them to be
iterated. (Running trinity with '-c unshare' you can see the slow
down happen. In some cases, it takes so long that the watchdog
process kills it -- though the SIGKILL won't get delivered until
the unshare() completes)
Any idea what this machine had been doing prior to this that may
have involved creating lots of namespaces ?
That was right after boot. ;)
This is my main rawhide running laptop.
A 'ip netns list' shows nothing.
Some more information:
The problem started between:
v3.17-7872-g5ff0b9e1a1da and v3.17-8307-gf1d0d14120a8
(I can try and do a bisect, but have to head out on a trip tomorrow)
In all the kernels with the problem, there is a kworker process in D.
sysrq-t says:
Showing all locks held in the system:
Oct 21 15:06:31 voldemort.scrye.com kernel: 4 locks held by kworker/u16:0/6:
Oct 21 15:06:31 voldemort.scrye.com kernel: #0: ("%s""netns"){.+.+.+}, at: [<ffffffff810ccbff>] process_one_work+0x17f/0x850
Oct 21 15:06:31 voldemort.scrye.com kernel: #1: (net_cleanup_work){+.+.+.}, at: [<ffffffff810ccbff>] process_one_work+0x17f/0x850
Oct 21 15:06:31 voldemort.scrye.com kernel: #2: (net_mutex){+.+.+.}, at: [<ffffffff817069fc>] cleanup_net+0x8c/0x1f0
Oct 21 15:06:31 voldemort.scrye.com kernel: #3:
(rcu_sched_state.barrier_mutex){+.+...}, at: [<ffffffff8112a395>]
_rcu_barrier+0x35/0x200
On first running any of the systemd units that use PrivateNetwork, then
run ok, but they are also set to timeout after a minute. On sucessive
runs they hang in D also.
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.
josh
From: Cong Wang <hidden> Date: 2014-10-22 17:37:58
(Adding Paul and Eric in Cc)
I am not aware of any change in net/core/dev.c related here,
so I guess it's a bug in rcu_barrier().
Thanks.
On Wed, Oct 22, 2014 at 10:12 AM, Josh Boyer [off-list ref] 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.
josh
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Oct 22, 2014 at 1:37 PM, Cong Wang [off-list ref] wrote:
(Adding Paul and Eric in Cc)
I am not aware of any change in net/core/dev.c related here,
so I guess it's a bug in rcu_barrier().
Possibly. The person that reported the issue below said it showed up
between Linux v3.17-7872-g5ff0b9e1a1da and Linux
v3.17-8307-gf1d0d14120a8 for them. Which is a slightly older window
than the on that Kevin reported. I haven't had a chance to dig
through the commits yet.
josh
On Wed, Oct 22, 2014 at 10:12 AM, Josh Boyer [off-list ref] wrote:
quoted
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.
josh
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
From: Paul E. McKenney <hidden> Date: 2014-10-22 17:59:15
On Wed, Oct 22, 2014 at 10:37:53AM -0700, Cong Wang wrote:
(Adding Paul and Eric in Cc)
I am not aware of any change in net/core/dev.c related here,
so I guess it's a bug in rcu_barrier().
Thanks.
Does commit 789cbbeca4e (workqueue: Add quiescent state between work items)
and 3e28e3772 (workqueue: Use cond_resched_rcu_qs macro) help this?
Thanx, Paul
On Wed, Oct 22, 2014 at 10:12 AM, Josh Boyer [off-list ref] wrote:
quoted
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.
josh
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Oct 22, 2014 at 1:59 PM, Paul E. McKenney
[off-list ref] wrote:
On Wed, Oct 22, 2014 at 10:37:53AM -0700, Cong Wang wrote:
quoted
(Adding Paul and Eric in Cc)
I am not aware of any change in net/core/dev.c related here,
so I guess it's a bug in rcu_barrier().
Thanks.
Does commit 789cbbeca4e (workqueue: Add quiescent state between work items)
and 3e28e3772 (workqueue: Use cond_resched_rcu_qs macro) help this?
I don't believe so. The output below is from a post 3.18-rc1 kernel
(Linux v3.18-rc1-221-gc3351dfabf5c to be exact), and both of those
commits are included in that if I'm reading the git output correctly.
josh
quoted
On Wed, Oct 22, 2014 at 10:12 AM, Josh Boyer [off-list ref] wrote:
quoted
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.
josh
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html