On 11.09.19 г. 13:21 ч., David Newall wrote:
>> echo w > /proc/sysrq-trigger
>
> Interesting.
>
> One material point which I failed to mention is that the btrfs volume is
> on an encrypted volume (cryptsetup luksOpen /dev/vdc backups).
>
> The first step, "mount -r /dev/vg/ext2fs-snapshot
> /btrfs-backup-volume/local-snapshot", seemed to trigger the problem.
> When I did the echo to sysrq-trigger, it seemed to stop blocking, but
> that might have been a coincidence. After the echo, kernel output
> exceeded 100KB, so I saved it to https://davidnewall.com/kern.1
Nothing useful in that log, everything seems normal.
>
> During rsync (--archive --one-file-system --hard-links --inplace
> --numeric-ids --delete /btrfs-backup-volume/local-snapshot/
> /btrfs-backup-volume/data/), initially there was no problem, but, then
> it (df) seemed to hang again. The rsync took a long time to complete,
> and before it did finish, I did the echo to sysrq-trigger again; kernel
> output is saved to https://davidnewall.com/kern.2
Same thing here
>
> The rsync finished not long after the echo to sysrq-trigger, but that's
> probably also a coincidence. After rsync completed, df still hung. I
> did another echo to sysrq-trigger, and saved kernel output to
> https://davidnewall.com/kern.3
So here it seems df is blocked inside btrfs_show_devname trying to acquire
device_list_mutex:
Sep 11 19:24:11 crowies kernel: [1109983.104578] Call Trace:
Sep 11 19:24:11 crowies kernel: [1109983.104580] [<ffffffff81860625>]
schedule+0x35/0x80
Sep 11 19:24:11 crowies kernel: [1109983.104582] [<ffffffff8186097e>]
schedule_preempt_disabled+0xe/0x10
Sep 11 19:24:11 crowies kernel: [1109983.104584] [<ffffffff81862817>]
__mutex_lock_slowpath+0xb7/0x130
Sep 11 19:24:11 crowies kernel: [1109983.104586] [<ffffffff818628af>]
mutex_lock+0x1f/0x30
Sep 11 19:24:11 crowies kernel: [1109983.104599] [<ffffffffc01a0edb>]
btrfs_show_devname+0x2b/0xe0 [btrfs]
Sep 11 19:24:11 crowies kernel: [1109983.104603] [<ffffffff81261547>]
show_mountinfo+0x1b7/0x2a0
Sep 11 19:24:11 crowies kernel: [1109983.104608] [<ffffffff8123d25d>]
m_show+0x1d/0x20
Sep 11 19:24:11 crowies kernel: [1109983.104611] [<ffffffff81242af0>]
seq_read+0x300/0x3d0
Sep 11 19:24:11 crowies kernel: [1109983.104614] [<ffffffff8121d1eb>]
__vfs_read+0x1b/0x40
Sep 11 19:24:11 crowies kernel: [1109983.104616] [<ffffffff8121d966>]
vfs_read+0x86/0x130
Sep 11 19:24:11 crowies kernel: [1109983.104618] [<ffffffff8121e6bc>]
SyS_read+0x5c/0xe0
Sep 11 19:24:11 crowies kernel: [1109983.104623] [<ffffffff8106f0a7>] ?
trace_do_page_fault+0x37/0xe0
Sep 11 19:24:11 crowies kernel: [1109983.104625] [<ffffffff81864f9b>]
entry_SYSCALL_64_fastpath+0x22/0xcb
Looking at the other threads transaction commit is writing the superblocks
to the underlying storage:
Sep 11 19:24:11 crowies kernel: [1109983.104414] [<ffffffff818600e1>] ?
__schedule+0x301/0x810
Sep 11 19:24:11 crowies kernel: [1109983.104417] [<ffffffff81860625>]
schedule+0x35/0x80
Sep 11 19:24:11 crowies kernel: [1109983.104419] [<ffffffff81863be4>]
schedule_timeout+0x1b4/0x270
Sep 11 19:24:11 crowies kernel: [1109983.104421] [<ffffffff81860121>] ?
__schedule+0x341/0x810
Sep 11 19:24:11 crowies kernel: [1109983.104424] [<ffffffff81861132>]
wait_for_completion+0xb2/0x190
Sep 11 19:24:11 crowies kernel: [1109983.104429] [<ffffffff810b34a0>] ?
wake_up_q+0x70/0x70
Sep 11 19:24:11 crowies kernel: [1109983.104485] [<ffffffffc01ce557>]
write_all_supers.isra.43+0x977/0xb10 [btrfs]
Sep 11 19:24:11 crowies kernel: [1109983.104501] [<ffffffffc01cf7b7>]
write_ctree_super+0x17/0x20 [btrfs]
Sep 11 19:24:11 crowies kernel: [1109983.104517] [<ffffffffc01d658a>]
btrfs_commit_transaction+0x7fa/0xb10 [btrfs]
Sep 11 19:24:11 crowies kernel: [1109983.104532] [<ffffffffc01d13c8>]
transaction_kthread+0x1c8/0x230 [btrfs]
Sep 11 19:24:11 crowies kernel: [1109983.104548] [<ffffffffc01d1200>] ?
btrfs_cleanup_transaction+0x570/0x570 [btrfs]
Sep 11 19:24:11 crowies kernel: [1109983.104553] [<ffffffff810a7707>]
kthread+0xe7/0x100
Sep 11 19:24:11 crowies kernel: [1109983.104555] [<ffffffff818600e1>] ?
__schedule+0x301/0x810
Sep 11 19:24:11 crowies kernel: [1109983.104557] [<ffffffff810a7620>] ?
kthread_create_on_node+0x1e0/0x1e0
Sep 11 19:24:11 crowies kernel: [1109983.104560] [<ffffffff81865425>]
ret_from_fork+0x55/0x80
Sep 11 19:24:11 crowies kernel: [1109983.104562] [<ffffffff810a7620>] ?
kthread_create_on_node+0x1e0/0x1e0
And it's waiting for that write to complete, under device_list_mutex. From my
POV it
seems you have slow storage and df is blocked while transaction commit is
finished, in
particular, the last phase of transaction commit - writing the superblocks.
At this point I don't see anything which would suggest foul play. Newer kernels
have changed
the locking in btrfs_show_devname and it takes an RCU rather than
device_list_mutex. Also
4.4.0-159 is ubuntu's own kernel and 4.4 is rather old at this stage. The only
remediation I could
suggest is to upgrade your kernel either via ubuntu's HWE or compiling one on
your own.
>
> I tried a minor change in procedure to see if it would bring the system
> back to normal response. Normally I'd do "btrfs subvolume snapshot",
> but I tried unmounting the lvm2 snapshot first (umount
> /btrfs-backup-volume/local-snapshot). It did not complete within the
> expected time, and another echo to sysrq-trigger resulted in
> https://davidnewall.com/kern.4
>
> Eventually the umount completed and system came back to normal response.
>
> I did the btrfs subvolume snapshot, and it completed faster than I could
> notice without causing any issues.
>
> After unmounting the btrfs volume, I tried each step again, and
> everything completed within expected times without causing any hang.
>
> Something which I did previously mention, but I'll repeat because it
> might well be important, is that the base ext2 filesystem is on a
> drbd-replicated volume. I don't know if it's part of the problem, and I
> observe that the hang condition was not triggered at the point of
> creating the lvm2 snapshot.
>
> I greatly appreciate your advice and help.
>
> Thanks,
>
> David
>
>
