xfs: Preallocated ioend transactions cause deadlock due to log buffer exhaustion

Bug #2007219 reported by Matthew Ruffell
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
linux (Ubuntu)
Fix Released
Undecided
Unassigned
Focal
Fix Released
High
Matthew Ruffell

Bug Description

BugLink: https://bugs.launchpad.net/bugs/2007219

[Impact]

A deadlock exists in the XFS filesystem that occurs when the XFS log buffer becomes completely exhausted.

XFS maintains a circular ring buffer for the log, and it is a fixed size. To be able to create a transaction, you need to be able to reserve space on the log buffer.

Certain ioend transactions, such as file append, can be preallocated for a negligible performance gain. This takes up space in the log buffer, and these preallocated ioends are placed on a workqueue, behind other ioends that are not preallocated.

The deadlock occurs when the XFS log buffer is running low on space, and an ioend append transaction comes in. It is preallocated, consuming nearly all of the remaining XFS log buffer space, and is placed at the very end of the ioend workqueue. The kernel then takes a ioend from the top of the ioend workqeueue, creates a transaction, xfs_trans_alloc(), attempts to allocate space for it, xfs_trans_reserve(), xfs_log_reserve(), and then waits in a while loop checking free space in the log, xlog_grant_head_check(), xlog_grant_head_wait().

Since there is no space, the thread sleeps with schedule(). This happens with all ioend transactions, since the log is exhausted and I/O is not moving.

Since I/O never moves, the thread is never woken up, and we get hung task timeouts, with system failure shortly afterward.

An example hung task timeout is:

INFO: task kworker/60:0:4002982 blocked for more than 360 seconds.
      Tainted: G OE 5.4.0-137-generic #154-Ubuntu
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/60:0 D 0 4002982 2 0x90004080
Workqueue: xfs-conv/dm-3 xfs_end_io [xfs]
Call Trace:
 __schedule+0x2e3/0x740
 schedule+0x42/0xb0
 xlog_grant_head_wait+0xb9/0x1e0 [xfs]
 xlog_grant_head_check+0xde/0x100 [xfs]
 xfs_log_reserve+0xc9/0x1e0 [xfs]
 xfs_trans_reserve+0x17a/0x1e0 [xfs]
 xfs_trans_alloc+0xda/0x170 [xfs]
 xfs_iomap_write_unwritten+0x128/0x2f0 [xfs]
 xfs_end_ioend+0x15b/0x1b0 [xfs]
 xfs_end_io+0xb1/0xe0 [xfs]
 process_one_work+0x1eb/0x3b0
 worker_thread+0x4d/0x400
 kthread+0x104/0x140
 ? process_one_work+0x3b0/0x3b0
 ? kthread_park+0x90/0x90
 ret_from_fork+0x1f/0x40

There is no known workaround, other than to have a larger log buffer at filesystem creation, but even then, it only buys you time until you get high enough load to exhaust the log buffer.

[Fix]

This was fixed in 5.13-rc1 by the following patch:

commit 7cd3099f4925d7c15887d1940ebd65acd66100f5
Author: Brian Foster <email address hidden>
Date: Fri Apr 9 10:27:43 2021 -0700
Subject: xfs: drop submit side trans alloc for append ioends
Link: https://github.com/torvalds/linux/commit/7cd3099f4925d7c15887d1940ebd65acd66100f5

The patch more or less removes all preallocated ioend transactions, and instead, when ioend appends are needed, they go to the standard workqueue like any other ioend, where transactions are allocated when they reach the top of the workqueue.

The patch required some backporting for Focal. The changes to the patch itself is minimal and should be straightforward to read, however, the changes to the XFS ioend subsystem between 5.4 and 5.13-rc1 were quite extreme, with a lot of refactoring taking place over very many commits.

Additionally, the patch was part of a five part series, the first, fixes the deadlock, and the rest remove all the code to do with transaction preallocation.

It is safe to leave the rest of the code in place. It will become dead code, but it will not be reachable, and not cause any risk of regression, due to ioend->io_append_trans always being NULL, and not entering into any of the if statements.

[Testcase]

There is currently no known testcase for this issue. The issue has only been seen in a customer production environment, running under heavy load. The issue has not been seen in a customer test environment, only production.

The production workload is a busy Kubernetes cluster running containers and VMs, with the hosts's filesystem being broken into separate mountpoints over several partitions, all XFS.

The kubernetes containers are all backed from a large 4TB disk which is XFS.

A test kernel is available in the following ppa:

https://launchpad.net/~mruffell/+archive/ubuntu/sf353709-test

This test kernel has been deployed to several production hosts, and the deadlock no longer occurs.

[Where problems can occur]

We are changing how certain ioend transactions take place in the XFS filesystem. If a regression were to occur, it would impact all XFS users. Users would have to downgrade their kernel, as there are no workarounds for enabling or disabling the behaviour change.

The overall risk of the change should be low. ioend append transactions would still be processed in nearly the same way, still being placed at the end of the ioend workqueue like any other transaction, with the only change being it is allocated at the time the transaction is created, at the top of the workqueue when it is processed, and not preallocated when the ioend is first submitted.

There will be a very minor performance penalty, but it wouldn't be measurable in any tangible workload.

I have run xfstests for the xfs/* subset against the released 5.4.0-137-generic and the test 5.4.0-137-generic test kernel with the patch included. The test kernel had identical results, it will likely not cause any regressions.

There is some additional risk leaving the dead code in place, but I have read the code and the commits to remove the dead code, and I came to the conclusion it is less risky to leave it in place, than to backport the refactor commits.

[Other Info]

The XFS ioend subsystem refactor took place in the following commits:

commit 598ecfbaa742aca0dcdbbea25681406f95cc0b63
From: Christoph Hellwig <email address hidden>
Date: Thu, 17 Oct 2019 13:12:15 -0700
Subject: iomap: lift the xfs writeback code to iomap
Link: https://github.com/torvalds/linux/commit/598ecfbaa742aca0dcdbbea25681406f95cc0b63

commit 9e91c5728cab3d0aa3197d009c3d63e147914e77
From: Christoph Hellwig <email address hidden>
Date: Thu, 17 Oct 2019 13:12:13 -0700
Subject: iomap: lift common tracing code from xfs to iomap
Link: https://github.com/torvalds/linux/commit/9e91c5728cab3d0aa3197d009c3d63e147914e77

commit 433dad94ec5d6b90385b56a8bc8718dd9542b289
From: Christoph Hellwig <email address hidden>
Date: Thu, 17 Oct 2019 13:12:07 -0700
Subject: xfs: refactor the ioend merging code
Link: https://github.com/torvalds/linux/commit/433dad94ec5d6b90385b56a8bc8718dd9542b289

ioend->io_append_trans was renamed to ioend->io_private in the following commit:

commit 5653017bc44e54baa299f3523f160c23ac0628fd
From: Christoph Hellwig <email address hidden>
Date: Thu, 17 Oct 2019 13:12:09 -0700
Subject: xfs: turn io_append_trans into an io_private void pointer
Link: https://github.com/torvalds/linux/commit/5653017bc44e54baa299f3523f160c23ac0628fd

The full five part preallocated ioend deadlock patch series is:

commit 7cd3099f4925d7c15887d1940ebd65acd66100f5
Author: Brian Foster <email address hidden>
Date: Fri Apr 9 10:27:43 2021 -0700
Subject: xfs: drop submit side trans alloc for append ioends
Link: https://github.com/torvalds/linux/commit/7cd3099f4925d7c15887d1940ebd65acd66100f5

commit 7adb8f14e134d5f885d47c4ccd620836235f0b7f
Author: Brian Foster <email address hidden>
Date: Fri Apr 9 10:27:55 2021 -0700
Subject: xfs: open code ioend needs workqueue helper
Link: https://github.com/torvalds/linux/commit/7adb8f14e134d5f885d47c4ccd620836235f0b7f

commit 044c6449f18f174ba8d86640936add3fc7582e49
Author: Brian Foster <email address hidden>
Date: Fri Apr 9 10:27:55 2021 -0700
Subject: xfs: drop unused ioend private merge and setfilesize code
Link: https://github.com/torvalds/linux/commit/044c6449f18f174ba8d86640936add3fc7582e49

commit e7a3d7e792a5ad50583a2e6c35e72bd2ca6096f4
Author: Brian Foster <email address hidden>
Date: Fri Apr 9 10:27:56 2021 -0700
Subject: xfs: drop unnecessary setfilesize helper
Link: https://github.com/torvalds/linux/commit/e7a3d7e792a5ad50583a2e6c35e72bd2ca6096f4

commit 6e552494fb90acae005d74ce6a2ee102d965184b
Author: Brian Foster <email address hidden>
Date: Tue May 4 08:54:29 2021 -0700
Subject: iomap: remove unused private field from ioend
Link: https://github.com/torvalds/linux/commit/6e552494fb90acae005d74ce6a2ee102d965184b

As you can see, the four latter commits are not necessary. They simply remove dead code, which has no harm being left in place. They also do not backport at all, not without the ALL of the significant refactor commits.

Hence, we only take "xfs: drop submit side trans alloc for append ioends" only, as it is the only needed commit to solve the problem.

description: updated
Changed in linux (Ubuntu Focal):
status: New → In Progress
Changed in linux (Ubuntu):
status: New → Fix Released
Changed in linux (Ubuntu Focal):
importance: Undecided → High
assignee: nobody → Matthew Ruffell (mruffell)
tags: added: focal sts
description: updated
Stefan Bader (smb)
Changed in linux (Ubuntu Focal):
status: In Progress → Fix Committed
Revision history for this message
Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote :

This bug is awaiting verification that the linux/5.4.0-145.162 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

tags: added: kernel-spammed-focal-linux verification-needed-focal
Revision history for this message
Matthew Ruffell (mruffell) wrote :

Performing verification for Focal.

The customer in question installed 5.4.0-145-generic to their busy production Kubernetes cluster, and have had no issues in the week and a half the kernel has been running for. Before, they would suffer deadlocks three or four times a day, so the kernel in -proposed fixes the issue.

The customer is happy to mark this bug as verified for Focal.

tags: added: verification-done-focal
removed: verification-needed-focal
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package linux - 5.4.0-146.163

---------------
linux (5.4.0-146.163) focal; urgency=medium

  * focal/linux: 5.4.0-146.163 -proposed tracker (LP: #2012094)

  * NFS deathlock with last Kernel 5.4.0-144.161 and 5.15.0-67.74 (LP: #2009325)
    - NFS: Correct timing for assigning access cache timestamp

linux (5.4.0-145.162) focal; urgency=medium

  * focal/linux: 5.4.0-145.162 -proposed tracker (LP: #2008389)

  * [SRU]Update ice driver to support E823 devices (LP: #1986717)
    - ice: Add device ids for E822 devices
    - ice: add support for E823 devices

  * btrfs/154: rename fails with EOVERFLOW when calculating item size during
    item key collision (LP: #2004132)
    - btrfs: correctly calculate item size used when item key collision happens

  * rtcpie in timers from ubuntu_kernel_selftests randomly failing
    (LP: #1814234)
    - SAUCE: selftest: rtcpie: Force passing unreliable subtest

  * [UBUNTU 20.04] KVM: s390: pv: don't allow userspace to set the clock under
    PV - kernel part (LP: #1999882)
    - KVM: s390x: fix SCK locking
    - KVM: s390: pv: don't allow userspace to set the clock under PV

  * CVE-2021-3669
    - ipc: replace costly bailout check in sysvipc_find_ipc()

  * net:fcnal-test.sh 'nettest' command not found on F/K (LP: #2006391)
    - selftests/net: Find nettest in current directory

  * xfs: Preallocated ioend transactions cause deadlock due to log buffer
    exhaustion (LP: #2007219)
    - xfs: drop submit side trans alloc for append ioends

  * CVE-2022-4382
    - USB: gadgetfs: Fix race between mounting and unmounting

  * CVE-2022-2196
    - KVM: VMX: Execute IBPB on emulated VM-exit when guest has IBRS

  * ubuntu_kernel_selftests: net:udpgso_bench.sh failed (LP: #1951447)
    - selftests: net: udpgso_bench: Fix racing bug between the rx/tx programs

  * net:fcnal-test.sh didn't return a non-zero value even with some sub-tests
    failed (LP: #2006692)
    - selftests: net/fcnal-test.sh: add exit code

  * Fix selftests/ftracetests/Meta-selftests in Focal (LP: #2006453)
    - SAUCE: Fix ftrace/Meta-selftests bashism check

  * CVE-2023-23559
    - wifi: rndis_wlan: Prevent buffer overflow in rndis_query_oid

 -- Luke Nowakowski-Krijger <email address hidden> Fri, 17 Mar 2023 11:08:20 -0700

Changed in linux (Ubuntu Focal):
status: Fix Committed → Fix Released
Revision history for this message
Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote :

This bug is awaiting verification that the linux-aws/5.4.0-1100.108 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

tags: added: kernel-spammed-focal-linux-aws verification-needed-focal
removed: verification-done-focal
Revision history for this message
Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote :

This bug is awaiting verification that the linux-azure/5.4.0-1106.112 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

tags: added: kernel-spammed-focal-linux-azure
Revision history for this message
Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote :

This bug is awaiting verification that the linux-bluefield/5.4.0-1060.66 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

tags: added: kernel-spammed-focal-linux-bluefield
Revision history for this message
Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote :

This bug is awaiting verification that the linux-xilinx-zynqmp/5.4.0-1023.27 kernel in -proposed solves the problem. Please test the kernel and update this bug with the results. If the problem is solved, change the tag 'verification-needed-focal' to 'verification-done-focal'. If the problem still exists, change the tag 'verification-needed-focal' to 'verification-failed-focal'.

If verification is not done by 5 working days from today, this fix will be dropped from the source code, and this bug will be closed.

See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you!

tags: added: kernel-spammed-focal-linux-xilinx-zynqmp
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.