Hi All,
I have a question about some timeout/error handling in ext4. And hoping
for tips on how to improve the situation :)
The case:
Virtual Machine (different linux versions) with ext4 + LVM
All the VM's are running on ESXi and using NFS SAN.
There was a short disruption of the SAN, which caused it to be
unavailable for 20-25 minutes for the ESXi.
What was observed in the VM was the following:
- Tasks Hangs
[5877185.755481] RSP: 002b:00007fc1253bc9d0 EFLAGS: 00000293 ORIG_RAX:
0000000000000001
[5877185.755481] RAX: ffffffffffffffda RBX: 000000000000000a RCX:
00007fc138f3f4a7
[5877185.755482] RDX: 0000000000000102 RSI: 00007fc1253bcb80 RDI:
000000000000000a
[5877185.755482] RBP: 00007fc1253bcb80 R08: 0000000000000000 R09:
0000000000000101
[5877185.755483] R10: 0000560111be2660 R11: 0000000000000293 R12:
0000000000000102
[5877185.755483] R13: 00007fc1253bcb80 R14: 0000000000000000 R15:
00007fc1253bcb80
[5877185.755488] INFO: task kworker/u256:0:34652 blocked for more than
120 seconds.
[5877185.755505] Not tainted 4.19.0-6-amd64 #1 Debian
4.19.67-2+deb10u1
[5877185.755520] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[5877185.755538] kworker/u256:0 D 0 34652 2 0x80000000
[5877185.755541] Workqueue: writeback wb_workfn (flush-254:2)
[5877185.755542] Call Trace:
[5877185.755543] ? __schedule+0x2a2/0x870
[5877185.755544] ? bit_wait_timeout+0x90/0x90
[5877185.755545] schedule+0x28/0x80
[5877185.755546] io_schedule+0x12/0x40
[5877185.755547] bit_wait_io+0xd/0x50
[5877185.755548] __wait_on_bit_lock+0x5d/0xa0
[5877185.755549] out_of_line_wait_on_bit_lock+0x91/0xb0
[5877185.755550] ? init_wait_var_entry+0x40/0x40
[5877185.755552] do_get_write_access+0x1d8/0x430 [jbd2]
[5877185.755559] ? ext4_dirty_inode+0x46/0x60 [ext4]
[5877185.755561] jbd2_journal_get_write_access+0x37/0x50 [jbd2]
[5877185.755566] __ext4_journal_get_write_access+0x36/0x70 [ext4]
[5877185.755573] ext4_reserve_inode_write+0x96/0xc0 [ext4]
[5877185.755575] ? jbd2_journal_dirty_metadata+0x117/0x230 [jbd2]
[5877185.755581] ext4_mark_inode_dirty+0x51/0x1d0 [ext4]
[5877185.755587] ? __ext4_journal_start_sb+0x34/0x120 [ext4]
[5877185.755593] ext4_dirty_inode+0x46/0x60 [ext4]
[5877185.755594] __mark_inode_dirty+0x1ba/0x380
[5877185.755600] ext4_da_update_reserve_space+0xcf/0x180 [ext4]
[5877185.755610] ext4_ext_map_blocks+0xb46/0xda0 [ext4]
[5877185.755617] ext4_map_blocks+0xed/0x5f0 [ext4]
[5877185.755623] ext4_writepages+0x9ba/0xf00 [ext4]
[5877185.755626] ? do_writepages+0x41/0xd0
[5877185.755632] ? ext4_mark_inode_dirty+0x1d0/0x1d0 [ext4]
[5877185.755633] do_writepages+0x41/0xd0
[5877185.755639] ? blk_mq_sched_dispatch_requests+0x11e/0x170
[5877185.755641] __writeback_single_inode+0x3d/0x350
[5877185.755642] writeback_sb_inodes+0x1e3/0x450
[5877185.755644] __writeback_inodes_wb+0x5d/0xb0
[5877185.755645] wb_writeback+0x25f/0x2f0
[5877185.755646] ? get_nr_inodes+0x35/0x50
[5877185.755648] ? cpumask_next+0x16/0x20
- After 1080 seconds (SCSi Timeout of 180 * 5 Retries + 1):
[5878128.028672] sd 0:0:1:0: timing out command, waited 1080s
[5878128.028701] sd 0:0:1:0: [sdb] tag#592 FAILED Result:
hostbyte=DID_OK driverbyte=DRIVER_OK
[5878128.028703] sd 0:0:1:0: [sdb] tag#592 CDB: Write(10) 2a 00 06 0c b4
c8 00 00 08 00
[5878128.028704] print_req_error: I/O error, dev sdb, sector 101496008
[5878128.028736] EXT4-fs warning (device dm-2): ext4_end_bio:323: I/O
error 10 writing to inode 3145791 (offset 0 size 0 starting block 12686745)
So you see the I/O is getting aborted.
- When the SAN came back, then the filesystem went Read-Only:
[5878601.212415] EXT4-fs error (device dm-2):
ext4_journal_check_start:61: Detected aborted journal
[5878601.212491] JBD2: Detected IO errors while flushing file data on dm-2-8
[5878601.212571] EXT4-fs error (device dm-0):
ext4_journal_check_start:61: Detected aborted journal
[5878601.212879] EXT4-fs (dm-2): Remounting filesystem read-only
[5878601.213483] EXT4-fs error (device dm-0):
ext4_journal_check_start:61: Detected aborted journal
[5878601.213512] EXT4-fs error (device dm-2):
ext4_journal_check_start:61: Detected aborted journal
[5878601.213513] EXT4-fs (dm-2): Remounting filesystem read-only
[5878601.215667] EXT4-fs error (device dm-0):
ext4_journal_check_start:61: Detected aborted journal
[5878601.216347] EXT4-fs error (device dm-2):
ext4_journal_check_start:61: Detected aborted journal
[5878601.217089] EXT4-fs (dm-2): ext4_writepages: jbd2_start: 12288
pages, ino 786630; err -30
[5878601.217963] EXT4-fs error (device dm-0):
ext4_journal_check_start:61: Detected aborted journal
[5878601.218253] EXT4-fs error (device dm-0):
ext4_journal_check_start:61: Detected aborted journal
[5878601.219040] EXT4-fs error (device dm-2):
ext4_journal_check_start:61: Detected aborted journal
[5878601.219049] EXT4-fs error (device dm-2):
ext4_journal_check_start:61: Detected aborted journal
Now I did a hard reset of the machine, and a manual fsck was needed to
get it booting again.
Fsck was showing the following:
"Inodes that were part of a corrupted orphan linked list found."
Manual fsck started with the following:
Inodes that were part of a corrupted orphan linked list found. Fix<y>?
Inode 165708 was part of the orphaned inode list. FIXED
Block bitmap differences: -(863328--863355)
Fix<y>?
What worries me is that almost all of the VM's (out of 500) were showing
the same error. And even some (+-10) were completely corrupt.
If you would do a hard reset of the VM's as a test (without storage
outage), the ratio of VMs that are corrupt and need manual fsck is WAY
lower.
Is there for example a chance that the filesystem gets corrupted the
moment the SAN storage was back accessible?
I also have some snapshot available of a corrupted disk if some
additional debugging info is required.
It would be great to gather some feedback on how to improve the
situation (next to of course have no SAN outage :)).
On KVM for example there is a unlimited timeout (afaik) until the
storage is back, and the VM just continues running after storage recovery.
I tried to reproduce the issue in our lab (by cutting the network to the
SAN from the ESXi), but we were unable to simulate the exact same
filesystem error.
Thanks
Jean-Louis
