http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c2 Steffen Winterfeldt changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |aschnell@suse.com Flags| |needinfo?(aschnell@suse.com | |) --- Comment #2 from Steffen Winterfeldt --- Arvin, could you check, please? -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c4 --- Comment #4 from Arvin Schnell --- Correction: Backtrace for snapperd for all threads. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c6 Arvin Schnell changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution|--- |NORESPONSE Flags|needinfo?(aschnell@suse.com | |) | --- Comment #6 from Arvin Schnell --- Feel free to reopen when requested information is provided. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c8 Oliver Kurz changed: What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |REOPENED Resolution|NORESPONSE |--- --- Comment #8 from Oliver Kurz --- see above (strange, I thought I reopened it) -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 Arvin Schnell changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|yast2-maintainers@suse.de |kernel-maintainers@forge.pr | |ovo.novell.com -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c11 --- Comment #11 from Oliver Kurz --- The problem seems to be even more severe for me. There is one kernel thread kworker/0:1 blocked for that time (multiple days). I don't know how to debug that currently running thread (or process?). The only thing I found: ``` $ sudo cat /proc/32086/stack [<ffffffff813a9c70>] acpi_os_execute_deferred+0x10/0x20 [<ffffffff810977a5>] process_one_work+0x155/0x440 [<ffffffff810982e6>] worker_thread+0x116/0x4b0 [<ffffffff810981d0>] worker_thread+0x0/0x4b0 [<ffffffff810981d0>] worker_thread+0x0/0x4b0 [<ffffffff8109d8d2>] kthread+0xd2/0xf0 [<ffffffff8109d800>] kthread+0x0/0xf0 [<ffffffff8160fb0f>] ret_from_fork+0x3f/0x70 [<ffffffff8109d800>] kthread+0x0/0xf0 [<ffffffffffffffff>] 0xffffffffffffffff ``` ``` $ for i in {1..3} ; do ps -flp 32086 ; sleep 0.4; done F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD 1 R root 32086 2 90 80 0 - 0 - 13:48 ? 00:46:36 [kworker/0:1] 1 R root 32086 2 90 80 0 - 0 - 13:48 ? 00:46:37 [kworker/0:1] 1 R root 32086 2 90 80 0 - 0 - 13:48 ? 00:46:37 [kworker/0:1] ``` so running, not changing state. I guess I have to reboot my system (also into a newer kernel) to make the machine fully usable again. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c13 --- Comment #13 from Oliver Kurz --- Seems to be an ACPI GPE storm although that is not reported by the kernel. I was following instructions on https://bbs.archlinux.org/viewtopic.php?id=184913 ``` grep . -r /sys/firmware/acpi/interrupts/ ``` returned /sys/firmware/acpi/interrupts/gpe24:4037035808 enabled so I disabled that interrupt by ``` echo disable > /sys/firmware/acpi/interrupts/gpe24 ``` and the kworker thread is free again. I will disable that interrupt on bootup as well. I have yet to see if that also unblocks snapper. For now I started some cron jobs explicitly to see if they make problems: `/etc/cron.hourly/suse.de-snapper ; /etc/cron.daily/suse.de-cron-local ; /etc/cron.monthly/btrfs-scrub ; /etc/cron.weekly/btrfs-balance ; /etc/cron.weekly/btrfs-trim` -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c15 --- Comment #15 from Oliver Kurz --- Yes, I have an update by now. I wanted to test a bit longer to see how the situation looks after disabling the GPE. Apparently the snapper problem is not influenced by that, snapper as well as snapperd are currently hanging again, this time since Aug 09. process table: ``` root 8872 0.0 0.0 11868 2592 ? SN Aug09 0:00 \_ /bin/sh /etc/cron.daily/suse.de-snapper root 8877 0.0 0.0 54988 4652 ? SN Aug09 0:00 \_ snapper --config=root --quiet cleanup empty-pre-post root 25641 0.0 0.0 292212 8204 ? Sl Aug09 0:36 /usr/sbin/snapperd ``` Did anyone check the kernel logs I attached? Something else I could do? -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 Jiri Slaby changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |jslaby@suse.com Attachment #733723|text/x-log |text/plain mime type| | -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c17 --- Comment #17 from Nikolay Borisov --- Hello, Can you provide the output of echo w > /proc/sysrq-trigger when the system is in this state. Also how many snapshots do you have and are you using btrfs' qgroups? Also is this btrfs a local filesystem or exported via nfs and you are just the client ? Can you also upload the stacktrace of the snapperd threads which are waiting on the ioctl via cat /proc/PID/stack, I'm interested in the kernel-level stack traces. Also do you see any btrfs related process taking hogging the CPU ? -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c19 --- Comment #19 from Oliver Kurz --- Created attachment 791669 --> http://bugzilla.suse.com/attachment.cgi?id=791669&action=edit snapper log, blocked tasks, backtrace of all snapper and snapperd threads I managed to observe what looks like exactly the same problem on a SLES12SP3 host which got upgraded from SLE12SP1->SLE12SP2->SLE12SP3. Please find attached the logs from snapper, the backtrace of both snapper and snapperd threads as well as the output from "sysrq w", all blocked tasks. The output from /proc/$(pidof snapperd)/stack: ``` [<ffffffff81222a45>] poll_schedule_timeout+0x45/0x60 [<ffffffff81223eac>] do_sys_poll+0x38c/0x4f0 [<ffffffff812240cd>] SyS_poll+0x5d/0xe0 [<ffffffff8161de61>] entry_SYSCALL_64_fastpath+0x20/0xe9 [<ffffffffffffffff>] 0xffffffffffffffff ``` Both snapper and snapperd seem to be running since Dec 01 on that host, that is since the last reboot. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c21 Oliver Kurz changed: What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |REOPENED Resolution|WORKSFORME |--- --- Comment #21 from Oliver Kurz --- # cat /proc/18169/stack [<ffffffff812178ac>] pipe_wait+0x5c/0x90 [<ffffffff812179b7>] pipe_write+0x87/0x430 [<ffffffff8120f0e0>] __vfs_write+0xd0/0x140 [<ffffffff8120fd3d>] vfs_write+0x9d/0x190 [<ffffffffa02bfc6c>] write_buf+0x5c/0x90 [btrfs] [<ffffffffa02c873b>] btrfs_ioctl_send+0x9bb/0x10c0 [btrfs] [<ffffffffa028db37>] btrfs_ioctl+0x3e7/0x23a0 [btrfs] [<ffffffff81222063>] do_vfs_ioctl+0x2e3/0x4c0 [<ffffffff812222b4>] SyS_ioctl+0x74/0x80 [<ffffffff8161de61>] entry_SYSCALL_64_fastpath+0x20/0xe9 [<ffffffffffffffff>] 0xffffffffffffffff that now looks like btrfs related, right? ;) -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c23 --- Comment #23 from Nikolay Borisov --- (In reply to Oliver Kurz from comment #21)

# cat /proc/18169/stack [<ffffffff812178ac>] pipe_wait+0x5c/0x90 [<ffffffff812179b7>] pipe_write+0x87/0x430 [<ffffffff8120f0e0>] __vfs_write+0xd0/0x140 [<ffffffff8120fd3d>] vfs_write+0x9d/0x190 [<ffffffffa02bfc6c>] write_buf+0x5c/0x90 [btrfs] [<ffffffffa02c873b>] btrfs_ioctl_send+0x9bb/0x10c0 [btrfs] [<ffffffffa028db37>] btrfs_ioctl+0x3e7/0x23a0 [btrfs] [<ffffffff81222063>] do_vfs_ioctl+0x2e3/0x4c0 [<ffffffff812222b4>] SyS_ioctl+0x74/0x80 [<ffffffff8161de61>] entry_SYSCALL_64_fastpath+0x20/0xe9 [<ffffffffffffffff>] 0xffffffffffffffff

that now looks like btrfs related, right? ;)

This is a start! write_buf+0x5c/0x90 is actually the writebuf call in send_header so right at the beginning of sending the subvolume. Looking at send_header all it does is send BTRFS_SEND_STREAM_MAGI (which has the value: "btrfs-stream") and the stream version (1) to the fd pointed by : sctx->send_filp . From the stack trace it's clear that this fd actually points to a pipe and this fd is in turn derived from:

sctx->send_filp = fget(arg->send_fd);

So it's filled in by the caller of the ioctl (in this case snapperd). I assume it's some sort of a FIFO/named pipes. According to man: If a process attempts to read from an empty pipe, then read(2) will block until data is available. If a process attempts to write to a full pipe (see below), then write(2) blocks until sufficient data has been read from the pipe to allow the write to complete. So what I believe is happening is that the pipe passed by snapperd to btrfs is full (dunno if it's been re-used for other purposes, but not filled by btrfs since it hangs when sending the first couple of bytes defining a send-stream), naturally the users of the pipe (in this case btrfs send) blocks waiting for space in the pipe to be freed - and space can be freed by someone consuming it. This someone must be snapperd. So here I don't see anything related to btrfs per-se apart from the pipe passed from user space is not being read. In any case I think someone from snapper team needs to come here and explain how exactly they are managing the pipe and why could they be missing/ignoring a wake up. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 Jiri Slaby changed: What |Removed |Added ---------------------------------------------------------------------------- CC|jslaby@suse.com | -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 Arvin Schnell changed: What |Removed |Added ---------------------------------------------------------------------------- Blocks| |1111414 -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 Arvin Schnell changed: What |Removed |Added ---------------------------------------------------------------------------- URL| |https://trello.com/c/9qmTx4 | |Hu/546-leap-422 Assignee|yast2-maintainers@suse.de |yast-internal@suse.de -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c26 --- Comment #26 from Arvin Schnell --- So from the information so far it could be that the thread reading and processing the output of the send ioctl dies. I have checked the code and the error handling here seems indeed incorrect: The thread dying should be responsible to close his end of the pipe. Then the send ioctl should no longer block but abort. -- You are receiving this mail because: You are on the CC list for the bug.

http://bugzilla.suse.com/show_bug.cgi?id=1049574 http://bugzilla.suse.com/show_bug.cgi?id=1049574#c27 Oliver Kurz changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(okurz@suse.com) | --- Comment #27 from Oliver Kurz --- (In reply to Lukas Ocilka from comment #25)

Oliver, is Leap 42.2 the right product? Is that an "evergreen" release?

I don't say we should not take a look, I just want to target the right product and I want to give it the right priority.

Sure, that makes sense. Well, Leap 42.2 is just the "version of the software the bug was found in." according to the help text in bugzilla. I am not sure if I should update this field if I see the problem as well in a more recent product. Leap 42.2 *is* EOL and to my knowledge there are no more "evergreen" releases. However I managed to see what looks like exactly the same problem on a SLE12SP3 installation on a different machine with https://bugzilla.suse.com/show_bug.cgi?id=1049574#c19 I gave access to this machine to aschnell to be able to investigate further. -- You are receiving this mail because: You are on the CC list for the bug.