On Wed, Jan 29, 2020 at 8:25 AM Satoru Takeuchi <satoru.takeuchi@xxxxxxxxx> wrote: > > Hi, > > In Rook(*1)/Ceph community, some users encountered hang_task in XFS and it > would be caused by RBD driver. > > Although we've not reproduced this problem in the newest kernel, could anyone > give us any hint about this problem, if possible? > > *1) An Ceph orchestration in Kubernetes > > - A question about this problem in linux-xfs ML > https://marc.info/?l=linux-xfs&m=158009629016068&w=2 > > - The reply to the above-mentioned question from Dave Chinner. > https://marc.info/?l=linux-xfs&m=158018349207976&w=2 > > I copied-and-pasted the discussion of above-mentioned mails here. > > my question: > ``` > Under some workload in Ceph, many processes got to hang_task. We found > that there are two kinds of processes. > > a) In very high CPU load > b) Encountered hang_task in the XFS > > In addition,a user got the following two kernel traces. > > A (b) process's backtrace with `hung_task_panic=1`. > > ``` > [51717.039319] INFO: task kworker/2:1:5938 blocked for more than 120 seconds. > [51717.039361] Not tainted 4.15.0-72-generic #81-Ubuntu > [51717.039388] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [51717.039426] kworker/2:1 D 0 5938 2 0x80000000 > [51717.039471] Workqueue: xfs-sync/rbd0 xfs_log_worker [xfs] > [51717.039472] Call Trace: > [51717.039478] __schedule+0x24e/0x880 > [51717.039504] ? xlog_sync+0x2d5/0x3c0 [xfs] > [51717.039506] schedule+0x2c/0x80 > [51717.039530] _xfs_log_force_lsn+0x20e/0x350 [xfs] > [51717.039533] ? wake_up_q+0x80/0x80 > [51717.039556] __xfs_trans_commit+0x20b/0x280 [xfs] > [51717.039577] xfs_trans_commit+0x10/0x20 [xfs] > [51717.039600] xfs_sync_sb+0x6d/0x80 [xfs] > [51717.039623] xfs_log_worker+0xe7/0x100 [xfs] > [51717.039626] process_one_work+0x1de/0x420 > [51717.039627] worker_thread+0x32/0x410 > [51717.039628] kthread+0x121/0x140 > [51717.039630] ? process_one_work+0x420/0x420 > [51717.039631] ? kthread_create_worker_on_cpu+0x70/0x70 > [51717.039633] ret_from_fork+0x35/0x40 > ``` > > A (b) process's backtrace that is got by `sudo cat /proc/<PID of a D > process>/stack` > > ``` > [<0>] _xfs_log_force_lsn+0x20e/0x350 [xfs] > [<0>] __xfs_trans_commit+0x20b/0x280 [xfs] > [<0>] xfs_trans_commit+0x10/0x20 [xfs] > [<0>] xfs_sync_sb+0x6d/0x80 [xfs] > [<0>] xfs_log_sbcount+0x4b/0x60 [xfs] > [<0>] xfs_unmountfs+0xe7/0x200 [xfs] > [<0>] xfs_fs_put_super+0x3e/0xb0 [xfs] > [<0>] generic_shutdown_super+0x72/0x120 > [<0>] kill_block_super+0x2c/0x80 > [<0>] deactivate_locked_super+0x48/0x80 > [<0>] deactivate_super+0x40/0x60 > [<0>] cleanup_mnt+0x3f/0x80 > [<0>] __cleanup_mnt+0x12/0x20 > [<0>] task_work_run+0x9d/0xc0 > [<0>] exit_to_usermode_loop+0xc0/0xd0 > [<0>] do_syscall_64+0x121/0x130 > [<0>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 > [<0>] 0xffffffffffffffff > ``` > > Here is the result of my investigation: > > - I couldn't find any commit that would be related to this problem, > both in the upstream > master and master and XFS's for-next > - I couldn't find any discussions that would be related to the > above-mentioned backtrace > in linux-xfs ML > - There would be a problem in the transaction commit of XFS. In both > of two traces, > (b) processes hung in _xfs_log_force_lsn+0x20e/0x350 [xfs]. This > code is one of > the following two xlog_wait(). > > https://github.com/torvalds/linux/blob/master/fs/xfs/xfs_log.c#L3366 > https://github.com/torvalds/linux/blob/master/fs/xfs/xfs_log.c#L3387 > > These processes released CPU voluntarily in the following line. > > https://github.com/torvalds/linux/blob/master/fs/xfs/xfs_log_priv.h#L549 > > These two processes should be woken by the other process after that. > However, unfortunately, it didn't happen. > > Test environment: > - kernel: 4.15.0-<x>-generic > - XFS # Anyone hasn't reported this problem with other filesystems yet. > > Related discussions: > - Issue of Rook: > https://github.com/rook/rook/issues/3132 > - Issue of Ceph > https://tracker.ceph.com/issues/40068 > ``` > > Dave's answer: > ``` > > Under some workload in Ceph, many processes got to hang_task. We found > > that there > > are two kinds of processes. > > > > a) In very high CPU load > > b) Encountered hang_task in the XFS > > > > In addition,a user got the following two kernel traces. > > > > A (b) process's backtrace with `hung_task_panic=1`. > > > > ``` > > [51717.039319] INFO: task kworker/2:1:5938 blocked for more than 120 seconds. > > [51717.039361] Not tainted 4.15.0-72-generic #81-Ubuntu > > Kinda old, and not an upstream LTS kernel, right? > > > [51717.039388] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > > disables this message. > > [51717.039426] kworker/2:1 D 0 5938 2 0x80000000 > > [51717.039471] Workqueue: xfs-sync/rbd0 xfs_log_worker [xfs] > > Filesystem is on a Ceph RBD device. > > > [51717.039472] Call Trace: > > [51717.039478] __schedule+0x24e/0x880 > > [51717.039504] ? xlog_sync+0x2d5/0x3c0 [xfs] > > [51717.039506] schedule+0x2c/0x80 > > [51717.039530] _xfs_log_force_lsn+0x20e/0x350 [xfs] > > [51717.039533] ? wake_up_q+0x80/0x80 > > [51717.039556] __xfs_trans_commit+0x20b/0x280 [xfs] > > [51717.039577] xfs_trans_commit+0x10/0x20 [xfs] > > [51717.039600] xfs_sync_sb+0x6d/0x80 [xfs] > > [51717.039623] xfs_log_worker+0xe7/0x100 [xfs] > > [51717.039626] process_one_work+0x1de/0x420 > > [51717.039627] worker_thread+0x32/0x410 > > [51717.039628] kthread+0x121/0x140 > > [51717.039630] ? process_one_work+0x420/0x420 > > [51717.039631] ? kthread_create_worker_on_cpu+0x70/0x70 > > [51717.039633] ret_from_fork+0x35/0x40 > > That's waiting for log IO completion. > > > ``` > > > > A (b) process's backtrace that is got by `sudo cat /proc/<PID of a D > > process>/stack` > > > > ``` > > [<0>] _xfs_log_force_lsn+0x20e/0x350 [xfs] > > [<0>] __xfs_trans_commit+0x20b/0x280 [xfs] > > [<0>] xfs_trans_commit+0x10/0x20 [xfs] > > [<0>] xfs_sync_sb+0x6d/0x80 [xfs] > > [<0>] xfs_log_sbcount+0x4b/0x60 [xfs] > > [<0>] xfs_unmountfs+0xe7/0x200 [xfs] > > [<0>] xfs_fs_put_super+0x3e/0xb0 [xfs] > > [<0>] generic_shutdown_super+0x72/0x120 > > [<0>] kill_block_super+0x2c/0x80 > > [<0>] deactivate_locked_super+0x48/0x80 > > [<0>] deactivate_super+0x40/0x60 > > [<0>] cleanup_mnt+0x3f/0x80 > > [<0>] __cleanup_mnt+0x12/0x20 > > [<0>] task_work_run+0x9d/0xc0 > > [<0>] exit_to_usermode_loop+0xc0/0xd0 > > [<0>] do_syscall_64+0x121/0x130 > > [<0>] entry_SYSCALL_64_after_hwframe+0x3d/0xa2 > > [<0>] 0xffffffffffffffff > > ANd this is the last reference to the filesystem being dropped and > it waiting for log IO completion. > > So, the filesytem has been unmounted, and it's waiting for journal > IO on the device to complete. I wonder if a wakeup was missed > somewhere? > > Did the system stop/tear down /dev/rbd0 prematurely? Hi Satoru, I would ask the same question. Typically this is seen when the network is shut off before the filesystem on top of rbd is fully unmounted. > > > Related discussions: > > - Issue of Rook: > > https://github.com/rook/rook/issues/3132 > > - Issue of Ceph > > https://tracker.ceph.com/issues/40068 > > These point to Ceph RBDs failing to respond under high load and > tasks hanging because they are waiting on IO. That's exactly the > symptoms you are reporting here. That points to it being a Ceph RBD > issue to me, especially the reports where rbd devices report no IO > load but the ceph back end is at 100% disk utilisation doing > -something-. I skimmed through https://github.com/rook/rook/issues/3132 and this particular stack trace came from someone who was upgrading their cluster, draining node after node and saw a umount process get stuck. This happens outside of k8s as well, but it is easier to hit with k8s because of different volume plugins and sometimes multiple layers of SDN involved. One thing to do is to make sure that the filesystem on top of rbd gets mounted with _netdev option. It has no effect on the kernel, but serves as a cue to systemd to order the unmount before network teardown and some container engines had trouble propagating it between their bind mounts in the past. Of course, if you or k8s somehow shut the network down before umount runs, _netdev won't help. When dealing with suspected kernel issues, try to collect the entire dmesg, not just a couple of stack traces. In this case we would have likely seen the kernel attempting to reconnect to the cluster over the dead network because XFS has not finished unmounting: libceph: connect 10.19.115.5:6789 error -101 libceph: mon1 10.19.115.5:6789 connect error The rest of the issues in that ticket appear to have been resolved by switching from XFS to ext4 on top of rbd. This is crucial when mapping rbd devices on the OSD nodes (i.e. co-locating the kernel client with the OSDs) because XFS is a lot more aggressive about memory reclaim and in doing that it is _much_ more likely to recurse back on itself, which results in a deadlock. This co-location + XFS deadlock is not specific to rbd or ceph, here is someone who hit it with nbd: https://www.spinics.net/lists/linux-xfs/msg26261.html There is no reliable way to prevent it in current kernels. This is why rook and ceph-csi default to ext4. Thanks, Ilya
