Hi
several docker users reported long stalls when they used containers
with network filesystem mounts. For example, this was reported here:
https://github.com/moby/moby/issues/5618#issuecomment-314515980.
Another user, Pierre Carru (@piec on GH), then managed to create a
simpler reproduction here: https://github.com/piec/docker-samba-loop
which I analysed initially here:
https://github.com/moby/moby/issues/5618#issuecomment-318432218
I managed to condense a repro down to a simple script below, which
does not rely on docker.
- Configure and start a SMB server on the host
- Create a veth pair and configure one peer in the root namespace
- Create a network namespace and move and configure the other veth peer there
- Execute a (mount.cifs; ls; unmount) inside the network namespace
(and in its own mount namespace, though the mount namespace is not
strictly required)
- Direclty after the 'unmount', delete the network namespace and try
to create a new network namespace
Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:
[ 67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1
Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).
While the creation of the new namespace is stalled, I used 'sysrq' a
few times to dump the work queues. There is an example below. Also,
the hung task detection kicks in after 120 seconds (also below)
I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.
It would be great if someone more familiar with the code could take a
look. I'm happy to provide additional info (perf traces etc) or test
patches if needed.
Thanks
Rolf
Work queue dump:
----------------
[ 67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1
[ 76.821394] sysrq: SysRq : Show Blocked State
[ 76.821820] task PC stack pid father
[ 76.822394] kworker/u2:0 D 0 6 2 0x00000000
[ 76.822896] Workqueue: netns cleanup_net
[ 76.823216] 0000000000018980 0000000000000000 ffff99797a80f080
ffffffff89c10500
[ 76.824007] ffff99797c9980c0 ffff99797cc18980 ffffffff897cfc83
0000000000000002
[ 76.824809] ffff99797c9980c0 ffffb3580002fd00 ffffb3580002fd28
0000000000000001
[ 76.825551] Call Trace:
[ 76.826001] [<ffffffff897cfc83>] ? __schedule+0x364/0x465
[ 76.826468] [<ffffffff897cfe02>] ? schedule+0x7e/0x87
[ 76.826913] [<ffffffff897d1b0a>] ? schedule_timeout+0xc1/0x101
[ 76.827431] [<ffffffff89127ba6>] ? del_timer_sync+0x42/0x42
[ 76.827875] [<ffffffff89127f62>] ? msleep+0x1a/0x1d
[ 76.828328] [<ffffffff89127f62>] ? msleep+0x1a/0x1d
[ 76.828783] [<ffffffff8963ba0b>] ? netdev_run_todo+0x158/0x296
[ 76.829311] [<ffffffff89636cf4>] ? default_device_exit_batch+0x138/0x158
[ 76.829907] [<ffffffff8910ea06>] ? __wake_up_sync+0x9/0x9
[ 76.830411] [<ffffffff896308e1>] ? cleanup_net+0x1a1/0x252
[ 76.830973] [<ffffffff890f2adb>] ? process_one_work+0x185/0x287
[ 76.832052] [<ffffffff890f30a5>] ? worker_thread+0x1d8/0x2ab
[ 76.833063] [<ffffffff890f2ecd>] ? rescuer_thread+0x2c4/0x2c4
[ 76.833769] [<ffffffff890f739c>] ? kthread+0xb4/0xbc
[ 76.834350] [<ffffffff890f72e8>] ? init_completion+0x1d/0x1d
[ 76.834859] [<ffffffff897d2a55>] ? ret_from_fork+0x25/0x30
[ 76.835644] ip D 0 656 653 0x00000000
[ 76.836260] 0000000000018980 0000000000000000 ffff99796ca68840
ffffffff89c10500
[ 76.836960] ffff99796cb9ce80 ffff99797cc18980 ffffffff897cfc83
0000000000000002
[ 76.837665] ffff99796cb9ce80 ffffb35800433e60 ffffffff89d006e4
ffff99796cb9ce80
[ 76.838369] Call Trace:
[ 76.838604] [<ffffffff897cfc83>] ? __schedule+0x364/0x465
[ 76.839126] [<ffffffff897cfe02>] ? schedule+0x7e/0x87
[ 76.839525] [<ffffffff897cffcd>] ? schedule_preempt_disabled+0xa/0xb
[ 76.840139] [<ffffffff897d10f1>] ? __mutex_lock_slowpath+0xb6/0x13b
[ 76.840751] [<ffffffff897d1191>] ? mutex_lock+0x1b/0x2a
[ 76.841234] [<ffffffff897d1191>] ? mutex_lock+0x1b/0x2a
[ 76.841829] [<ffffffff89630a36>] ? copy_net_ns+0xa4/0x12c
[ 76.842335] [<ffffffff890f848d>] ? create_new_namespaces+0x125/0x191
[ 76.842859] [<ffffffff890f8675>] ? unshare_nsproxy_namespaces+0x87/0xa4
[ 76.843788] [<ffffffff890dd418>] ? SyS_unshare+0x17b/0x306
[ 76.844263] [<ffffffff897d27f7>] ? entry_SYSCALL_64_fastpath+0x1a/0xa9
[ 77.648626] unregister_netdevice: waiting for lo to become free.
Usage count = 1
Hung task detection
-------------------
[ 241.612198] unregister_netdevice: waiting for lo to become free.
Usage count = 1
[ 243.955712] INFO: task ip:656 blocked for more than 120 seconds.
[ 243.956292] Not tainted 4.9.39-linuxkit #1
[ 243.956703] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 243.957394] ip D 0 656 653 0x00000000
[ 243.957963] 0000000000018980 0000000000000000 ffff99796ca68840
ffffffff89c10500
[ 243.958701] ffff99796cb9ce80 ffff99797cc18980 ffffffff897cfc83
0000000000000002
[ 243.959438] ffff99796cb9ce80 ffffb35800433e60 ffffffff89d006e4
ffff99796cb9ce80
[ 243.960175] Call Trace:
[ 243.960482] [<ffffffff897cfc83>] ? __schedule+0x364/0x465
[ 243.961063] [<ffffffff897cfe02>] ? schedule+0x7e/0x87
[ 243.961538] [<ffffffff897cffcd>] ? schedule_preempt_disabled+0xa/0xb
[ 243.962052] [<ffffffff897d10f1>] ? __mutex_lock_slowpath+0xb6/0x13b
[ 243.962642] [<ffffffff897d1191>] ? mutex_lock+0x1b/0x2a
[ 243.963156] [<ffffffff897d1191>] ? mutex_lock+0x1b/0x2a
[ 243.963649] [<ffffffff89630a36>] ? copy_net_ns+0xa4/0x12c
[ 243.964166] [<ffffffff890f848d>] ? create_new_namespaces+0x125/0x191
[ 243.964757] [<ffffffff890f8675>] ? unshare_nsproxy_namespaces+0x87/0xa4
[ 243.965381] [<ffffffff890dd418>] ? SyS_unshare+0x17b/0x306
[ 243.965898] [<ffffffff897d27f7>] ? entry_SYSCALL_64_fastpath+0x1a/0xa9
[ 251.877100] unregister_netdevice: waiting for lo to become free.
Usage count = 1
[ 262.139630] unregister_netdevice: waiting for lo to become free.
Usage count = 1
Script to repro:
----------------
apk add --no-cache iproute2 samba samba-common-tools cifs-utils
# For debian/ubuntu
# apt-get install -y samba cifs-utils
# SMB server setup
cat <<EOF > /etc/samba/smb.conf
[global]
workgroup = WORKGROUP
netbios name = FOO
passdb backend = tdbsam
security = user
guest account = nobody
strict locking = no
min protocol = SMB2
[public]
path = /share
browsable = yes
read only = no
guest ok = yes
browseable = yes
create mask = 777
EOF
adduser -D -G nobody nobody && smbpasswd -a -n nobody
mkdir /share && chmod ugo+rwx /share && touch /share/foo
chown -R nobody.nobody /share
# Start SMB server and sleep for it to serve
smbd -D
# Bring up a veth pair
ip link add hdev type veth peer name nsdev
ip addr add 10.0.0.1/24 dev hdev
ip link set hdev up
# Create namespace and configure veth peer
ip netns add client-ns
ip link set nsdev netns client-ns
ip netns exec client-ns ip addr add 10.0.0.2/24 dev nsdev
ip netns exec client-ns ip link set lo up
ip netns exec client-ns ip link set nsdev up
sleep 1 # Wait for device to be up
# Execute (mount, ls, unmount) in the network namespace and a new
mount namespace
ip netns exec client-ns unshare --mount \
/bin/sh -c 'mount.cifs //10.0.0.1/public /mnt -o vers=3.0,guest;
ls /mnt; umount /mnt'
# Delete the client network namespace.
ip netns del client-ns
# create a new namespace. This stalls
ip netns add client-ns2
From: Cong Wang <hidden> Date: 2017-07-28 17:50:18
Hello,
On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:
Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:
[ 67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1
Sounds like another netdev refcnt leak.
Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).
Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?
While the creation of the new namespace is stalled, I used 'sysrq' a
few times to dump the work queues. There is an example below. Also,
the hung task detection kicks in after 120 seconds (also below)
Yeah, the net_mutex is held by cleanup_net().
I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.
OK, so commit d747a7a51b00984127a88113c does not help this case
either.
It would be great if someone more familiar with the code could take a
look. I'm happy to provide additional info (perf traces etc) or test
patches if needed.
The last time I debugged this kind of netdev refcnt leak problem,
I added a few trace_printk() to dev_hold() and dev_put(),
so you can try it too. I will see if I can use your reproducer
here.
Thanks.
On Fri, Jul 28, 2017 at 6:49 PM, Cong Wang [off-list ref] wrote:
Hello,
On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:
quoted
Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:
[ 67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1
Sounds like another netdev refcnt leak.
I don't think it's a leak as such because the system eventually
recovers after around 200 seconds.
quoted
Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).
Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?
Yes. I suspect, that with a sleep some cleanup code (maybe umount)
gets run and the ref count gets decremented within the second. Without
the sleep, something gets yanked, and whatever operation needs to be
done can't get performed, times out after 200s and then the ref count
gets decremented.
quoted
While the creation of the new namespace is stalled, I used 'sysrq' a
few times to dump the work queues. There is an example below. Also,
the hung task detection kicks in after 120 seconds (also below)
Yeah, the net_mutex is held by cleanup_net().
quoted
I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.
OK, so commit d747a7a51b00984127a88113c does not help this case
either.
d747a7a51b009("tcp: reset sk_rx_dst in tcp_disconnect()") indeed seems
a different issue. As I understand that actually caused the ref count
never to get decremented, while here eventually some cleanup kicks in
after a long timeout.
quoted
It would be great if someone more familiar with the code could take a
look. I'm happy to provide additional info (perf traces etc) or test
patches if needed.
The last time I debugged this kind of netdev refcnt leak problem,
I added a few trace_printk() to dev_hold() and dev_put(),
so you can try it too. I will see if I can use your reproducer
here.
The last time I encountered the same symptoms were here
http://www.spinics.net/lists/netdev/msg403433.html but this had an
entirely different cause.
I'll also try if I can get some traces out of dev_hold()/dev_put().
Rolf
From: David Ahern <hidden> Date: 2017-07-28 19:16:56
On 7/28/17 12:58 PM, Rolf Neugebauer wrote:
quoted
quoted
I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.
OK, so commit d747a7a51b00984127a88113c does not help this case
either.
d747a7a51b009("tcp: reset sk_rx_dst in tcp_disconnect()") indeed seems
a different issue. As I understand that actually caused the ref count
never to get decremented, while here eventually some cleanup kicks in
after a long timeout.
It could be a dst is cached on a socket and does not get cleared until
the socket time outs are done.
Test that theory by something like this for IPv4 TCP (similar change for
UDP if the client is UDP based):
On Fri, Jul 28, 2017 at 8:16 PM, David Ahern [off-list ref] wrote:
quoted hunk
On 7/28/17 12:58 PM, Rolf Neugebauer wrote:
quoted
quoted
quoted
I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.
OK, so commit d747a7a51b00984127a88113c does not help this case
either.
d747a7a51b009("tcp: reset sk_rx_dst in tcp_disconnect()") indeed seems
a different issue. As I understand that actually caused the ref count
never to get decremented, while here eventually some cleanup kicks in
after a long timeout.
It could be a dst is cached on a socket and does not get cleared until
the socket time outs are done.
Test that theory by something like this for IPv4 TCP (similar change for
UDP if the client is UDP based):
This removes the 200s stall (the test is IPv4/TCP based)
quoted
I'll also try if I can get some traces out of dev_hold()/dev_put().
Attached patch puts tracepoints in dev_hold / dev_put; very useful for
debugging cases like this. Use perf record and perf script.
I extended the patch to also print out the ifindex and the nd_net to
make it easier to distinguish the different lo interfaces.
I've attached two perf traces, stall.script.txt is with the issue
present and nostall-sleep.script.txt is the same setup but with a
"sleep 1" after the executing the mount/ls/umount in the name space
and before deleting the network namespace. In the latter case there is
*no* stall for 200s.
In stall.script.txt the "struct net *" of the interfaces in question
is net=0xffff897c6a86c080 and in nostall-sleep.script.txt it is
net=0xffff897c6a8a4100.
The two traces start diverging wrt to the reference counts on lo after
the reference count reaches 5 when deleting the namespace (timestamp
138.709884 in stall.script.txt and 550.856279 in
nostall-sleep.script.txt). In the trace where the stalls are, the
trace point of last decrement is:
kworker/0:1 20 [000] 361.938911: net:dev_put: dev=lo[1]
net=0xffff897c6a86c080 refcnt 1
ffffffffad704f6c perf_trace_dev_put+0xa3 ([kernel.kallsyms])
ffffffffad6dc90e dev_put+0x111 ([kernel.kallsyms])
ffffffffad6ec5df dst_destroy+0x4b ([kernel.kallsyms])
ffffffffad6ec70c dst_gc_task+0xbe ([kernel.kallsyms])
ffffffffad102bf8 process_one_work+0x276 ([kernel.kallsyms])
ffffffffad103374 worker_thread+0x1eb ([kernel.kallsyms])
ffffffffad1082d2 kthread+0xe3 ([kernel.kallsyms])
ffffffffad8b947a ret_from_fork+0x2a ([kernel.kallsyms])
Let me know if there is additional data needed
Rolf
From: Cong Wang <hidden> Date: 2017-07-31 17:07:03
On Fri, Jul 28, 2017 at 11:58 AM, Rolf Neugebauer
[off-list ref] wrote:
On Fri, Jul 28, 2017 at 6:49 PM, Cong Wang [off-list ref] wrote:
quoted
Hello,
On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:
quoted
Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:
[ 67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1
Sounds like another netdev refcnt leak.
I don't think it's a leak as such because the system eventually
recovers after around 200 seconds.
quoted
quoted
Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).
Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?
Yes. I suspect, that with a sleep some cleanup code (maybe umount)
gets run and the ref count gets decremented within the second. Without
the sleep, something gets yanked, and whatever operation needs to be
done can't get performed, times out after 200s and then the ref count
gets decremented.
This reminds me of
commit f186ce61bb8235d80068c390dc2aad7ca427a4c2
Author: Krister Johansen [off-list ref]
Date: Thu Jun 8 13:12:38 2017 -0700
Fix an intermittent pr_emerg warning about lo becoming free.
but this one is merged in 4.12 too, so must be something else.
On Mon, Jul 31, 2017 at 6:06 PM, Cong Wang [off-list ref] wrote:
On Fri, Jul 28, 2017 at 11:58 AM, Rolf Neugebauer
[off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 6:49 PM, Cong Wang [off-list ref] wrote:
quoted
Hello,
On Fri, Jul 28, 2017 at 9:47 AM, Rolf Neugebauer
[off-list ref] wrote:
quoted
Creating the new namespace is stalling for around 200 seconds and
there 20 odd messages on the console, like:
[ 67.372603] unregister_netdevice: waiting for lo to become free.
Usage count = 1
Sounds like another netdev refcnt leak.
I don't think it's a leak as such because the system eventually
recovers after around 200 seconds.
quoted
quoted
Adding a 'sleep 1' before deleting the original network namespace
"solves" the issue, but that doesn't sound like a good fix. Not using
unmount also does not help (understandable).
Interesting, if sleeping for 1sec help, why did you see the stall for
200sec? The "leak" should go away eventually without 'sleep 1',
right?
Yes. I suspect, that with a sleep some cleanup code (maybe umount)
gets run and the ref count gets decremented within the second. Without
the sleep, something gets yanked, and whatever operation needs to be
done can't get performed, times out after 200s and then the ref count
gets decremented.
This reminds me of
commit f186ce61bb8235d80068c390dc2aad7ca427a4c2
Author: Krister Johansen [off-list ref]
Date: Thu Jun 8 13:12:38 2017 -0700
Fix an intermittent pr_emerg warning about lo becoming free.
but this one is merged in 4.12 too, so must be something else.
I've done my last test on 4.9.40 not 4.12.x but another user reported
the same issue on 4.12 and 4.4.x and I just verified on 4.12.4 as
well.
I reported something with similar symptoms, i.e. stalls which
eventually stopped here:
http://marc.info/?l=linux-netdev&m=147870616302799&w=2 but judging by
the backtraces from that post it looks entirely different
Rolf
From: Cong Wang <hidden> Date: 2017-07-31 22:01:29
On Mon, Jul 31, 2017 at 9:22 AM, Rolf Neugebauer
[off-list ref] wrote:
On Fri, Jul 28, 2017 at 8:16 PM, David Ahern [off-list ref] wrote:
quoted
On 7/28/17 12:58 PM, Rolf Neugebauer wrote:
quoted
quoted
quoted
I can readily reproduce this on 4.9.39, 4.11.12 and another user
repro-ed it on 4.12.3. It seems to happen every time. At least one
user reported issues with NFS mounts as well, but we were not able to
reproduce it. It's not clear to me if this is directly related to
'mount.cifs' or if that just happens to reliably repro it.
OK, so commit d747a7a51b00984127a88113c does not help this case
either.
d747a7a51b009("tcp: reset sk_rx_dst in tcp_disconnect()") indeed seems
a different issue. As I understand that actually caused the ref count
never to get decremented, while here eventually some cleanup kicks in
after a long timeout.
It could be a dst is cached on a socket and does not get cleared until
the socket time outs are done.
Test that theory by something like this for IPv4 TCP (similar change for
UDP if the client is UDP based):
This removes the 200s stall (the test is IPv4/TCP based)
Interesting. This means we have a kernel socket which holds
the dst refcnt.
Looking at the cifs code, it does create a TCP kernel socket
which doesn't hold refcnt to netns but its sk_rx_dst could
still be set as usual, therefore this socket could hold the dst
which holds lo device after the netns is gone. But its timeout
seems to be 60sec (SMB_ECHO_INTERVAL_DEFAULT),
not 200sec.
Ideally it should use a per netns socket so that it would have
a same life-time with netns. But you need to check this with
cifs developers, I don't understand cifs at all.
This removes the 200s stall (the test is IPv4/TCP based)
Interesting. This means we have a kernel socket which holds
the dst refcnt.
Right now there is no tracking that I am aware of for a dst cached on
the socket (outside of walking all sockets). I have been bitten by it
several times in trying to make various changes. It's basically a hidden
reference for the device.