Repository navigation
Guests running fstrim on a local disk may trigger extreme I/O latency for that drive #11543
Description
This issue is similar to #10478, but triggered by a slightly different scenario. That issue occurs only once per local disk, during initialization, this issue has the potential to repeatedly impact customer environments. Many Linux distros have a systemd fstrim.timer that executes at 00:00 on Mondays, with about 30 minutes of skew, so in an environment that is pervasively using local disks guests may be subject to rolling outages as guests trigger their job. Notably, any other virtual disks hosted on the drive will also be impacted.
Preparing the guest
This example was triggered on dogfood sled 9 with a 1 TiB local volume. The guest is running Ubuntu 26.04 with an empty btrfs volume on the local drive.
Split the local disk into a small partition for measuring latency and a large one for the filesystem. We'll use ioping to measure IO latency within the guest. Here we use btrfs to match the setup of the customer who originally reported this issue, but there is no reason to think the issue is limited to that filesystem.
apt install -y ioping fio
systemctl disable --now fstrim.timer # take the weekly run out of the picture
parted -s /dev/nvme1n1 mklabel gpt mkpart probe 1MiB 16GiB mkpart data 16GiB 100%
mkfs.btrfs -K -f /dev/nvme1n1p2 # -K: skip the whole-device TRIM at mkfs
mkdir -p /mnt/local && mount -o nodiscard /dev/nvme1n1p2 /mnt/local
Measuring the impact of fstrim
In one shell start ioping:
ioping -D -i 0.2 /dev/nvme1n1p1 | tee /root/ioping.log
In another shell run the fstrim:
time fstrim -v /mnt/local
Results
While the fstrim was executing, the guest disabled the local disk device due to timeouts:
[ 1099.899153] nvme nvme1: I/O tag 384 (3180) opcode 0x2 (I/O Cmd) QID 1 timeout, aborting req_op:READ(0) size:4096
[ 1099.899270] nvme nvme1: Abort status: 0x0
[ 1135.225309] nvme nvme1: I/O tag 384 (4180) opcode 0x2 (I/O Cmd) QID 1 timeout, aborting req_op:READ(0) size:4096
[ 1135.225515] nvme nvme1: Abort status: 0x0
[ 1165.431988] nvme nvme1: I/O tag 384 (4180) opcode 0x2 (I/O Cmd) QID 1 timeout, reset controller
[ 1165.481548] nvme nvme1: 2/0/0 default/read/poll queues
[ 1195.638432] nvme nvme1: I/O tag 384 (4180) QID 1 timeout, disable controller
[ 1195.646841] I/O error, dev nvme1n1, sector 13876104 op 0x0:(READ) flags 0x800 phys_seg 1 prio class 2
[ 1195.649911] nvme nvme1: Disabling device after reset failure: 0
[ 1195.653536] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 1, rd 0, flush 0, corrupt 0, gen 0
[ 1195.654180] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 2, rd 0, flush 0, corrupt 0, gen 0
[ 1195.656602] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 3, rd 0, flush 0, corrupt 0, gen 0
[ 1195.663272] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 4, rd 0, flush 0, corrupt 0, gen 0
[ 1195.666298] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 5, rd 0, flush 0, corrupt 0, gen 0
[ 1195.667390] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 6, rd 0, flush 0, corrupt 0, gen 0
[ 1195.669550] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 7, rd 0, flush 0, corrupt 0, gen 0
[ 1195.673067] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 8, rd 0, flush 0, corrupt 0, gen 0
[ 1195.676200] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 9, rd 0, flush 0, corrupt 0, gen 0
[ 1195.681195] BTRFS error (device nvme1n1p2): bdev /dev/nvme1n1p2 errs: wr 10, rd 0, flush 0, corrupt 0, gen 0
[ 1195.686320] BTRFS error (device nvme1n1p2): error while writing out transaction: -5
[ 1195.690445] BTRFS warning (device nvme1n1p2): Skipping commit of aborted transaction.
[ 1195.690452] BTRFS error (device nvme1n1p2 state A): Transaction aborted (error -5)
[ 1195.693657] BTRFS: error (device nvme1n1p2 state A) in cleanup_transaction:2060: errno=-5 IO failure
[ 1195.697269] BTRFS info (device nvme1n1p2 state EA): forced readonly
ioping shows a 1000x increase in latency prior to the drive grinding to a halt:
root@trim-of-terror:~# ioping -D -i 0.2 /dev/nvme1n1p1 | tee /root/ioping.log
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=1 time=276.0 us (warmup)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=2 time=331.2 us
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=3 time=309.3 us
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=4 time=227.4 us
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=5 time=365.3 us
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=6 time=411.1 us
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=7 time=239.5 us
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=8 time=244.0 us
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=9 time=216.1 us
... trim starts ...
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=117 time=148.9 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=118 time=178.7 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=119 time=172.7 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=120 time=183.0 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=121 time=188.8 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=122 time=187.8 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=123 time=195.9 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=124 time=205.3 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=125 time=206.6 ms (slow)
... eventually things get very slow ...
ioping: request failed: Input/output error
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=258 time=616.4 ms (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=259 time=4.23 s (slow)
4 KiB <<< /dev/nvme1n1p1 (block device 16.0 GiB): request=260 time=35.4 s (slow)zpool iostat from the global zone on the zpool hosting the drive show a similar pattern of moderate degradation followed by a complete loss of responsiveness for ~30 seconds:
capacity operations bandwidth total_wait disk_wait syncq_wait asyncq_wait scrub trim
pool alloc free read write read write read write read write read write read write wait wait
---------------------------------------- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- -----
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.29K 3.81K 162M 432M 770us 31ms 490us 107us 41us 238us 2ms 32ms 635ms -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.08K 2.81K 138M 349M 464us 30ms 460us 99us 2us 3us 97us 30ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.15K 4.35K 147M 472M 495us 24ms 493us 92us 2us 4us 28us 25ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1013 4.39K 127M 529M 507us 35ms 502us 97us 2us 2us 43us 36ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.07K 2.83K 137M 291M 460us 19ms 457us 91us 2us 3us 13us 19ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.03K 6.38K 132M 770M 541us 30ms 539us 99us 2us 4us 14us 30ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.06K 639 135M 45.5M 429us 8ms 425us 77us 2us 2us 105us 9ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 998 7.04K 124M 812M 541us 28ms 539us 95us 2us 5us 47us 28ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.05K 1.86K 135M 219M 455us 28ms 452us 98us 2us 2us 27us 31ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.02K 5.32K 130M 600M 520us 29ms 510us 95us 2us 4us 230us 29ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 798 4.72K 99.6M 580M 477us 30ms 476us 98us 2us 4us 2us 31ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.01K 2.39K 129M 240M 481us 26ms 460us 92us 2us 2us 425us 27ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 996 3.64K 125M 441M 518us 36ms 506us 100us 2us 3us 216us 37ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.05K 3.66K 134M 383M 460us 24ms 458us 93us 2us 4us 14us 26ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 995 6.44K 124M 776M 550us 33ms 535us 102us 2us 5us 353us 33ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 899 522 112M 33.5M 425us 6ms 423us 74us 2us 2us 3us 6ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 886 7.05K 111M 817M 577us 31ms 566us 96us 2us 3us 137us 31ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 1.16K 1.30K 148M 153M 448us 28ms 441us 98us 2us 2us 136us 31ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 949 5.87K 119M 666M 531us 40ms 525us 99us 2us 5us 118us 41ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 207 54 25.6M 5.92M 422us 98us 414us 96us 2us 2us 50us - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 228 45 28.4M 580K 419us 54us 416us 53us 2us 2us 50us - - -
... trim starts ...
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 12 1 1.62M 220K 201ms 201ms 201ms 201ms 3us 3us 3us - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 10 0 1.25M 0 201ms - 201ms - 3us - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 10 0 1.37M 0 201ms - 201ms - 3us - 3us - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 9 2 1.25M 257K 201ms 335ms 201ms 201ms 2us - - 134ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 13 4 1.75M 401K 201ms 885ms 201ms 201ms 4us - 3us 845ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 10 6 1.37M 680K 201ms 1s 201ms 201ms 4us 6us - 1s - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 9 5 1.25M 525K 201ms 2s 201ms 201ms 3us - - 2s - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 11 4 1.50M 513K 201ms 3s 201ms 201ms 3us - 3us 2s - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 10 5 1.37M 656K 201ms 5s 201ms 201ms 3us - - 5s - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 11 4 1.50M 448K 201ms 4s 201ms 201ms 3us - - 4s - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 9 5 1.25M 514K 201ms 6s 201ms 201ms 4us - - 5s - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 11 5 1.50M 537K 201ms 5s 201ms 201ms 4us - - 5s - -
... things appear to back up ...
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 635 0 103s - 103s - 5us - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 949 2.80K 80.3M 334M 1s 5s 695ms 36ms 972ms 5us 41us 5s - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 55 3.25K 3.25M 239M 366us 15ms 366us 80us 2us 1us - 15ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 23.5K 0 196us - 196us - 3us - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 23.0K 0 196us - 196us - 3us - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 23.5K 0 196us - 196us - 3us - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 0 0 0 - - - - - - - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 5 658 41.5K 6.69M 139us 4ms 139us 57us 2us 1us - 4ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 2 649 24.5K 78.5M 163us 124us 163us 119us 2us 2us - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 3 1.27K 73.4K 157M 196us 123us 196us 118us 3us 2us - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 2 1.90K 73.0K 236M 196us 126us 196us 121us 3us 2us - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 0 1.27K 23.0K 157M 196us 139us 196us 133us 3us 2us - - - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 13 2.80K 201K 307M 175us 17ms 172us 93us 2us 1us - 17ms - -
oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8 1.33T 1.58T 8 0 216K 0 196us - 196us - 3us - - - - -
A number of ereports like this were written on the sled:
Oct 20 2026 18:42:02.031418040 ereport.fs.zfs.delay
nvlist version: 0
class = ereport.fs.zfs.delay
ena = 0xb24f051df2609001
detector = (embedded nvlist)
nvlist version: 0
version = 0x0
scheme = zfs
pool = 0x251d0924a02cadaf
vdev = 0x3ae371ff88117f15
(end detector)
pool = oxp_0ae29053-29a2-489e-a1e6-6aec0ecd05f8
pool_guid = 0x251d0924a02cadaf
pool_context = 0
pool_failmode = continue
vdev_guid = 0x3ae371ff88117f15
vdev_type = disk
vdev_path = /dev/dsk/c12t0014EE81000D30A5d0s0
vdev_devid = id1,kdev@g06000000000000000014ee81000d30a5/a
vdev_fru = hc://:product-id=913-0000019:product-sn=BRM44220005:server-id=BRM44220005:chassis-id=BRM44220005:serial=A084A6CB:part=WUS4C6432DSP3X3:revision=R2210000/chassis=0/bay=3/nvme=0
vdev_ashift = 0x9
parent_guid = 0x251d0924a02cadaf
parent_type = root
zio_err = 0
zio_offset = 0x6aa5c3a600
zio_size = 0xc00
zio_objset = 0x3639
zio_object = 0x8066
zio_level = 0
zio_blkid = 0x0
__ttl = 0x1
__tod = 0x6ad7b5fa 0x1df66b8
io_latency metrics for the drive queried with get virtual_disk:io_latency | filter disk_id == "7350fcde-36cf-4997-81e4-f79ba06cfc8c" && io_kind == "read" && timestamp > @2026-10-20T18:35:00 && timestamp < @2026-10-20T18:45:00
Activity
wfchandler commentedon Oct 22, 2026
I repeated the exercise with
ext4andxfsusing the same guest and local disk.ext4showed the increase in latency to ~200ms, but never triggered an extended pause. I tried writing 500 GiB, deleting it, and triggering anotherfstrim, with no change.xfsimmediately triggered a ~50s pause after I ranfstrimon a newly created fs.wfchandler commentedon Oct 22, 2026
Drive I've been testing on:
The customer who initially reported the issue have 30T SN655s, model
WUS5EC1B1ESP7Y3, on firmware revRC911002.wfchandler commentedon Oct 22, 2026
io_latencymetrics for the virtual disk. This is for thexfstest mentioned in #11543 (comment). Query isWrite
Read
Discard