Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1324261 > unrolled thread
| Started by | Philipp Hahn <pmhahn@pmhahn.de> |
|---|---|
| First post | 2016-02-02 17:40 +0100 |
| Last post | 2016-02-05 16:30 +0100 |
| Articles | 3 — 2 participants |
Back to article view | Back to linux.kernel
Bug 4.1.16: self-detected stall in net/unix/? Philipp Hahn <pmhahn@pmhahn.de> - 2016-02-02 17:40 +0100
Re: Bug 4.1.16: self-detected stall in net/unix/? Hannes Frederic Sowa <hannes@stressinduktion.org> - 2016-02-03 02:50 +0100
Re: Bug 4.1.16: self-detected stall in net/unix/? Philipp Hahn <pmhahn@pmhahn.de> - 2016-02-05 16:30 +0100
| From | Philipp Hahn <pmhahn@pmhahn.de> |
|---|---|
| Date | 2016-02-02 17:40 +0100 |
| Subject | Bug 4.1.16: self-detected stall in net/unix/? |
| Message-ID | <qXM9J-5Km-17@gated-at.bofh.it> |
Hi,
we recently updated our kernel to 4.1.16 + patch for "unix: properly
account for FDs passed over unix sockets" and have since then
self-detected stalls triggered by the Samba daemon:
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] INFO: rcu_sched self-detected stall on CPU { 3} (t=162780 jiffies g=47565 c=47564 q=1055670)
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] Task dump for CPU 3:
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] smbd R running task 0 5938 1 0x0000000c
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] 0000000000000004 ffffffff81851340 ffffffff810d3c84 000000000000b9cd
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] ffff8801bfd97100 ffffffff81851340 ffffffff81851340 ffffffff818f6c60
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] ffffffff810d7659 0000000000000000 0000000000000000 00001e847fc2f700
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] Call Trace:
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] <IRQ> [<ffffffff810d3c84>] ? rcu_dump_cpu_stacks+0x84/0xc0
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff810d7659>] ? rcu_check_callbacks+0x449/0x740
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff810ec7c0>] ? tick_sched_do_timer+0x40/0x40
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff810dcc54>] ? update_process_times+0x34/0x70
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff810ec45c>] ? tick_sched_handle.isra.12+0x2c/0x70
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff810ec809>] ? tick_sched_timer+0x49/0x80
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff810dd57d>] ? __run_hrtimer+0x6d/0x1b0
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff810ddd4d>] ? hrtimer_interrupt+0xed/0x210
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff815a0ed9>] ? smp_apic_timer_interrupt+0x39/0x50
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff8159ef7e>] ? apic_timer_interrupt+0x6e/0x80
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] <EOI> [<ffffffff8159de85>] ? _raw_spin_lock+0x35/0x50
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff8153b343>] ? unix_dgram_connect+0x93/0x200
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff8147f248>] ? SYSC_connect+0xe8/0x100
> Feb 1 09:03:14 dcs1 kernel: [ 1152.840007] [<ffffffff8159e0f2>] ? system_call_fast_compare_end+0xc/0x6b
> Feb 1 11:48:13 ucs22f kernel: [307999.162254] INFO: rcu_sched self-detected stall on CPU { 0} (t=5250 jiffies g=6586733 c=6586732 q=6757)
> Feb 1 11:48:13 ucs22f kernel: [307999.162264] Task dump for CPU 0:
> Feb 1 11:48:13 ucs22f kernel: [307999.162267] smbd R running 0 4615 4609 0x00000008
> Feb 1 11:48:13 ucs22f kernel: [307999.162272] 00200082 f5863b90 c10b3fe9 c1682cc0 c1682cc0 c1682cc0 f79d2b00 f 5863bdc
> Feb 1 11:48:13 ucs22f kernel: [307999.162276] c10b722d c15bd400 00001482 0064816d 0064816c 00001a65 f79cd840 c 108b166
> Feb 1 11:48:13 ucs22f kernel: [307999.162280] 00000001 f5863bb8 f5863bb8 00000000 c1682cc0 f6808cf0 00001a65 f 6808cf0
> Feb 1 11:48:13 ucs22f kernel: [307999.162285] Call Trace:
> Feb 1 11:48:13 ucs22f kernel: [307999.162296] [<c10b3fe9>] ? rcu_dump_cpu_stacks+0x79/0xc0
> Feb 1 11:48:13 ucs22f kernel: [307999.162300] [<c10b722d>] ? rcu_check_callbacks+0x3cd/0x630
> Feb 1 11:48:13 ucs22f kernel: [307999.162304] [<c108b166>] ? account_process_tick+0x66/0x160
> Feb 1 11:48:13 ucs22f kernel: [307999.162307] [<c10bbe4f>] ? update_process_times+0x2f/0x60
> Feb 1 11:48:13 ucs22f kernel: [307999.162310] [<c10cbf9d>] ? tick_sched_handle.isra.12+0x2d/0x60
> Feb 1 11:48:13 ucs22f kernel: [307999.162328] [<c10cc210>] ? tick_sched_timer+0x40/0x80
> Feb 1 11:48:13 ucs22f kernel: [307999.162331] [<c10bc6b0>] ? __remove_hrtimer+0x40/0xa0
> Feb 1 11:48:13 ucs22f kernel: [307999.162334] [<c10bc97f>] ? __run_hrtimer+0x6f/0x190
> Feb 1 11:48:13 ucs22f kernel: [307999.162337] [<c10cc1d0>] ? tick_sched_do_timer+0x30/0x30
> Feb 1 11:48:13 ucs22f kernel: [307999.162339] [<c10bd15f>] ? hrtimer_interrupt+0xef/0x260
> Feb 1 11:48:13 ucs22f kernel: [307999.162343] [<c119ae3d>] ? getname_kernel+0x2d/0x100
> Feb 1 11:48:13 ucs22f kernel: [307999.162348] [<c1046f7f>] ? local_apic_timer_interrupt+0x2f/0x60
> Feb 1 11:48:13 ucs22f kernel: [307999.162353] [<c14e4543>] ? smp_apic_timer_interrupt+0x33/0x50
> Feb 1 11:48:13 ucs22f kernel: [307999.162355] [<c14e3c7c>] ? apic_timer_interrupt+0x34/0x3c
> Feb 1 11:48:13 ucs22f kernel: [307999.162358] [<c14e2dc1>] ? _raw_spin_lock+0x51/0x70
> Feb 1 11:48:13 ucs22f kernel: [307999.162362] [<c148c075>] ? unix_state_double_lock+0x25/0x60
> Feb 1 11:48:13 ucs22f kernel: [307999.162365] [<c148de10>] ? unix_dgram_connect+0x90/0x1f0
> Feb 1 11:48:13 ucs22f kernel: [307999.162369] [<c13e4267>] ? SYSC_connect+0xc7/0xe0
> Feb 1 11:48:13 ucs22f kernel: [307999.162371] [<c13e2931>] ? sock_map_fd+0x41/0x60
> Feb 1 11:48:13 ucs22f kernel: [307999.162374] [<c13e5014>] ? SYSC_socketcall+0x1b4/0xa20
> Feb 1 11:48:13 ucs22f kernel: [307999.162376] [<c10c2940>] ? ktime_get+0x50/0x100
> Feb 1 11:48:13 ucs22f kernel: [307999.162379] [<c10466db>] ? lapic_next_event+0x1b/0x20
> Feb 1 11:48:13 ucs22f kernel: [307999.162381] [<c10ca0ed>] ? clockevents_program_event+0x9d/0x140
> Feb 1 11:48:13 ucs22f kernel: [307999.162385] [<c129e068>] ? list_del+0x8/0x20
> Feb 1 11:48:13 ucs22f kernel: [307999.162388] [<c1097ef7>] ? remove_wait_queue+0x27/0x40
> Feb 1 11:48:13 ucs22f kernel: [307999.162392] [<c11c8795>] ? inotify_read+0x295/0x340
> Feb 1 11:48:13 ucs22f kernel: [307999.162396] [<c10acc76>] ? handle_irq_event_percpu+0xa6/0x1a0
> Feb 1 11:48:13 ucs22f kernel: [307999.162399] [<c11a786f>] ? set_close_on_exec+0x2f/0x60
> Feb 1 11:48:13 ucs22f kernel: [307999.162402] [<c119d084>] ? do_fcntl+0x2f4/0x4e0
> Feb 1 11:48:13 ucs22f kernel: [307999.162405] [<c107d6df>] ? commit_creds+0xff/0x1f0
> Feb 1 11:48:13 ucs22f kernel: [307999.162407] [<c119d380>] ? SyS_fcntl64+0x60/0x100
> Feb 1 11:48:13 ucs22f kernel: [307999.162409] [<c13e5953>] ? SyS_socketcall+0x13/0x20
> Feb 1 11:48:13 ucs22f kernel: [307999.162412] [<c14e30db>] ? sysenter_do_call+0x12/0x12
We have not yet been able to reproduce the hang, but going back to our
previous kernel 4.1.12 makes the problem go away.
Is this a known issue or do you have an idea where to look?
What information should I collect next time it happens?
(Can unix_diag.ko with `ss` help?)
What other kernel configs should I enable do debug this dead-lock?
Thanks in advance
Philipp
[toc] | [next] | [standalone]
| From | Hannes Frederic Sowa <hannes@stressinduktion.org> |
|---|---|
| Date | 2016-02-03 02:50 +0100 |
| Message-ID | <qXUJZ-3F0-21@gated-at.bofh.it> |
| In reply to | #1324261 |
On 02.02.2016 17:25, Philipp Hahn wrote: > Hi, > > we recently updated our kernel to 4.1.16 + patch for "unix: properly > account for FDs passed over unix sockets" and have since then > self-detected stalls triggered by the Samba daemon: > > > > > [...] > > > > We have not yet been able to reproduce the hang, but going back to our > previous kernel 4.1.12 makes the problem go away. Can you remove the patch "unix: properly account for FDs passed over unix sockets" and see if the problem still happens? I couldn't quickly see any problems with your added patch. I currently suspect a tight loop because of a SOCK_DEAD flag set but the socket not removed from unix_socket_table or the vfs. Hmmm... The stack trace is rather unreliable, maybe something completely different happend. Do you happend to see better reports? > Is this a known issue or do you have an idea where to look? > What information should I collect next time it happens? > > (Can unix_diag.ko with `ss` help?) Would be interesting if it is a conventional file based socket or autobounded one (sun_path[0] != '\0'). Thanks, Hannes
[toc] | [prev] | [next] | [standalone]
| From | Philipp Hahn <pmhahn@pmhahn.de> |
|---|---|
| Date | 2016-02-05 16:30 +0100 |
| Message-ID | <qYQuB-22s-11@gated-at.bofh.it> |
| In reply to | #1324819 |
Hello Hannes,
thank you for your previous reply.
Am 03.02.2016 um 02:43 schrieb Hannes Frederic Sowa:
> On 02.02.2016 17:25, Philipp Hahn wrote:
>> we recently updated our kernel to 4.1.16 + patch for "unix: properly
>> account for FDs passed over unix sockets" and have since then
>> self-detected stalls triggered by the Samba daemon:
...
>> We have not yet been able to reproduce the hang, but going back to our
>> previous kernel 4.1.12 makes the problem go away.
>
> Can you remove the patch "unix: properly account for FDs passed over
> unix sockets" and see if the problem still happens?
I will try.
The problem is that I can't trigger the bug reliably. It always happens
to "smbd", but I don't know the triggering condition.
> I couldn't quickly see any problems with your added patch. I currently
> suspect a tight loop because of a SOCK_DEAD flag set but the socket not
> removed from unix_socket_table or the vfs. Hmmm...
All occurrences of the bug show _raw_spin_lock() as the sleeping
function, never anything other thus far.
I have seen the bug both on amd64 and i386.
If it would spin in
> 1097 restart:
> 1098 »···»···other = unix_find_other(net, sunaddr, alen, sock->type, hash, &err);
> 1099 »···»···if (!other)
> 1100 »···»···»···goto out;
> 1101
> 1102 »···»···unix_state_double_lock(sk, other);
> 1103
> 1104 »···»···/* Apparently VFS overslept socket death. Retry. */
> 1105 »···»···if (sock_flag(other, SOCK_DEAD)) {
> 1106 »···»···»···unix_state_double_unlock(sk, other);
> 1107 »···»···»···sock_put(other);
> 1108 »···»···»···goto restart;
> 1109 »···»···}
I would expect some other function to show up in the trace, but it's
always the call chain "unix_dgram_connect -> unix_state_double_lock ->
_raw_spin_lock".
The only case I see is that unix_find_other() returns the same "other"
again and again.
Q: How will that dead "other" be garbage collected finally? The kernel is
> # CONFIG_PREEMPT_NONE is not set
> CONFIG_PREEMPT_VOLUNTARY=y
> # CONFIG_PREEMPT is not set
During my hunt I found the following difference between 4.4 and 4.1.16
in net/unix/af_unix.c:
> commit 1586a5877db9eee313379738d6581bc7c6ffb5e3
> Author: Eric Dumazet <edumazet@google.com>
> Date: Fri Oct 23 10:59:16 2015 -0700
>
> af_unix: do not report POLLOUT on listeners
>
> poll(POLLOUT) on a listener should not report fd is ready for
> a write().
>
> This would break some applications using poll() and pfd.events = -1,
> as they would not block in poll()
>
> Signed-off-by: Eric Dumazet <edumazet@google.com>
> Reported-by: Alan Burlison <Alan.Burlison@oracle.com>
> Tested-by: Eric Dumazet <edumazet@google.com>
> Signed-off-by: David S. Miller <davem@davemloft.net>
...
> -static inline int unix_writable(struct sock *sk)
> +static int unix_writable(const struct sock *sk)
> {
> - return (atomic_read(&sk->sk_wmem_alloc) << 2) <= sk->sk_sndbuf;
> + return sk->sk_state != TCP_LISTEN &&
> + (atomic_read(&sk->sk_wmem_alloc) << 2) <= sk->sk_sndbuf;
> }
Q: That *TCP*_LISTEN in net/*unix*/ looks strange to my eyes, but I'm
not a kernel guru (yet).
There is one hunk in 5c77e26862ce604edea05b3442ed765e9756fe0f, which
uses the result of that function, which might explain the difference,
why it shows with 4.1.16 but not with 4.4?
> @@ -2245,14 +2388,16 @@ static unsigned int unix_dgram_poll(struct file *file, struct socket *sock,
> writable = unix_writable(sk);
> - other = unix_peer_get(sk);
> - if (other) {
> - if (unix_peer(other) != sk) {
> - sock_poll_wait(file, &unix_sk(other)->peer_wait, wait);
> - if (unix_recvq_full(other))
> - writable = 0;
> - }
> - sock_put(other);
> + if (writable) {
> + unix_state_lock(sk);
> +
> + other = unix_peer(sk);
> + if (other && unix_peer(other) != sk &&
> + unix_recvq_full(other) &&
> + unix_dgram_peer_wake_me(sk, other))
> + writable = 0;
> +
> + unix_state_unlock(sk);
> }
> if (writable)
I will for now build a new kernel with
> $ git log --oneline v4.1.12..v4.1.17 -- net/unix
> dc6b0ec unix: properly account for FDs passed over unix sockets
> cc01a0a af_unix: Revert 'lock_interruptible' in stream receive code
> 5c77e26 unix: avoid use-after-free in ep_remove_wait_queue
reverted to see if it still happens. The "middle" patch seems harmless,
as it only changes a code path for STREAMS, while the bug triggers with
DGRAMS only.
> The stack trace is rather unreliable, maybe something completely
> different happend. Do you happend to see better reports?
So far they look all the same.
Anything more I can do to prepare for collection better information next
time I get that bug?
Thanks again.
Philipp
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web