Details
-
Bug
-
Resolution: Fixed
-
Critical
-
Lustre 2.10.3
-
None
-
2
-
9223372036854775807
Description
We had seen this before. LU-5481. At time we just removed MMP from the OST, because we didn't use hos failover. But our new filesystem does use host failover. We are seeing the same error on a ISER+T10PI connect storage. This error can happen at mount time and random times during IO.
[ 3520.840977] mlx5_3:mlx5_poll_one:657:(pid 0): CQN: 0xc05 Got SIGERR on key: 0x80007b0b err_type 0 err_offset 207 expected 9b3c actual a13c [ 3520.878451] PI error found type 0 at sector 1337928 expected 953c vs actual 9b3c [ 3520.900800] PI error found type 0 at sector 1337928 expected 9b3c vs actual a13c [ 3520.923968] blk_update_request: I/O error, dev sdai, sector 20150568 [ 3520.943377] blk_update_request: I/O error, dev sdae, sector 20150568 [ 3520.963067] blk_update_request: I/O error, dev dm-15, sector 20150568 [ 3520.982436] Buffer I/O error on dev dm-15, logical block 2518821, lost async page write [ 3521.006511] Buffer I/O error on dev dm-15, logical block 2518822, lost async page write [ 3521.006558] blk_update_request: I/O error, dev dm-13, sector 20150568 [ 3521.006559] Buffer I/O error on dev dm-13, logical block 2518821, lost async page write [ 3521.006563] Buffer I/O error on dev dm-13, logical block 2518822, lost async device /dev/dm-15 mounted by lustre Filesystem volume name: nbp10-OST001d Last mounted on: / Filesystem UUID: 08b337bb-b3b1-48b0-925b-0bf5d3ba7253 Filesystem magic number: 0xEF53 Filesystem revision #: 1 (dynamic) Filesystem features: has_journal ext_attr dir_index filetype needs_recovery extent 64bit mmp flex_bg sparse_super large_file huge_file uninit_bg dir_nlink extra_isize quota Filesystem flags: signed_directory_hash Default mount options: user_xattr acl Filesystem state: clean Errors behavior: Continue Filesystem OS type: Linux Inode count: 9337344 Block count: 19122880512 Reserved block count: 0 Free blocks: 19120188065 Free inodes: 9337011 First block: 0 Block size: 4096 Fragment size: 4096 Group descriptor size: 64 Blocks per group: 32768 Fragments per group: 32768 Inodes per group: 16 Inode blocks per group: 2 Flex block group size: 64 Filesystem created: Fri Jul 27 10:21:56 2018 Last mount time: Fri Jul 27 10:44:14 2018 Last write time: Fri Jul 27 10:44:15 2018 Mount count: 4 Maximum mount count: -1 Last checked: Fri Jul 27 10:21:56 2018 Check interval: 0 (<none>) Lifetime writes: 7774 kB Reserved blocks uid: 0 (user root) Reserved blocks gid: 0 (group root) First inode: 11 Inode size: 512 Required extra isize: 32 Desired extra isize: 32 Journal inode: 8 Default directory hash: half_md4 Directory Hash Seed: 2ebd542d-9757-456f-b597-43fae5c542c0 Journal backup: inode blocks MMP block number: 2518821 MMP update interval: 5 User quota inode: 3 Group quota inode: 4
Note block with the error is the MMP block.
Attachments
Issue Links
- is duplicated by
-
-
- Resolved
-
Activity
Mahmoud, that indicates that the T10-PI layer detected some kind of corruption, but the block was not modified in memory. This would indicate corruption at some lower layer, though it is confusing why only the MMP block is affected.
One option would be to add a similar hex dump at the point where the error is being reported after the checksum failure, to see if the data is different somehow? It also makes sense to print out the buffer address, to see if there is a copy of the page being used or something, possibly being caused by the device mapper layer.
Are you using software RAID or similar on this system, or is DM only in use for multipath? Have you tried to disable multipath to see if the problems go away? The only other thing I can think of is to remove the REQ_SYNC | REQ_META | REQ_PRIO flags from submit_bh() one at a time to see if this makes a difference, as it might indicate where the problem is located. Removing the REQ_SYNC flag may cause legitimate failures if the system is very busy, since the MMP thread would only be waiting on the 5s MMP update interval and not the actual write completion.
At this point the problem looks to be outside of the scope of Lustre/ext4 so I'm not sure what else we can do.
I ran with the latest patch set 3. Reproduced the PI error but there was no output from the debug patch.
[ 988.391944] mlx5_3:mlx5_poll_one:671:(pid 0): CQN: 0xc05 Got SIGERR on key: 0x80009d6b err_type 0 err_offset 207 expected 24f1 actual 2af1 [ 988.430812] PI error found type 0 at sector 1337928 expected 24f1 vs actual 2af1 [ 988.453087] blk_update_request: I/O error, dev sdam, sector 20150568 [ 988.472382] blk_update_request: I/O error, dev dm-18, sector 20150568 [ 988.491746] Buffer I/O error on dev dm-18, logical block 2518821, lost async page write
[ 996.218102] mlx5_2:mlx5_poll_one:671:(pid 0): CQN: 0x405 Got SIGERR on key: 0x80003110 err_type 0 err_offset 207 expected 9377 actual 9977 [ 996.260232] PI error found type 0 at sector 1337928 expected 9377 vs actual 9977 [ 996.282509] blk_update_request: I/O error, dev sdu, sector 20150568 [ 996.301422] blk_update_request: I/O error, dev dm-9, sector 20150568 [ 996.320524] Buffer I/O error on dev dm-9, logical block 2518821, lost async page write
ok I've made a stupid mistake in the debug patch, Mahmoud can you rerun it using the latest patchset 3? My apologies.
Attaching hexdump for one of the devices.
I was running deadline I changed it to noop no difference in the MMP failures.
I've updated the debug patch to print the hexdump, Mahmoud could you give that a try?
Looks like you are using mq as the scheduler? It's just a stab in the dark but can you try it with mq disabled?
The debug information shows that it is not the MMP block data itself that is changing, but something else in the 1KB buffer that is not part of the MMP structure? The MMP memcmp() that was added is detecting the difference in the buffer at least, so we do have confirmation that the buffer is actually being changed, and it isn't just a transient issue in the block layer. One option to debug further is to dump the rest of the buffer as hex values before and after to see which byte(s) are modified.
Here is console output for PI error
[ 4105.807355] LDISKFS-fs warning (device dm-4): kmmpd:208: MMP block mismatch. [ 4105.828551] LDISKFS-fs warning (device dm-4): kmmpd:208: MMP failure info: last update time: 1535161818, last update node: nbp16-srv1, last update device: dm-4 [ 4105.828551] magic: 4d4d50, seq: 215, check_interval: 10, checksum: 0 [ 4105.828551] [ 4105.894981] LDISKFS-fs warning (device dm-4): kmmpd:209: copy of MMP block. [ 4105.915920] LDISKFS-fs warning (device dm-4): kmmpd:209: MMP failure info: last update time: 1535161818, last update node: nbp16-srv1, last update device: dm-4 [ 4105.915920] magic: 4d4d50, seq: 215, check_interval: 10, checksum: 0 [ 4105.915920] [ 4106.201033] mlx5_3:mlx5_poll_one:671:(pid 0): CQN: 0xc05 Got SIGERR on key: 0x800068a4 err_type 0 err_offset 207 expected 2480 actual 2a80 [ 4106.240867] PI error found type 0 at sector 1337928 expected 2480 vs actual 2a80 [ 4106.263174] blk_update_request: I/O error, dev sdl, sector 20150568 [ 4106.282557] blk_update_request: I/O error, dev dm-4, sector 20150568 [ 4106.301660] CPU: 19 PID: 141 Comm: ksoftirqd/19 Tainted: G OE ------------ 3.10.0-693.21.1.el7.20180508.x86_64.lustre211 #1 [ 4106.338539] Hardware name: HPE ProLiant DL380 Gen10/ProLiant DL380 Gen10, BIOS U30 02/15/2018 [ 4106.348118] LDISKFS-fs warning (device dm-7): kmmpd:208: MMP block mismatch. [ 4106.348120] LDISKFS-fs warning (device dm-7): kmmpd:208: MMP failure info: last update time: 1535161818, last update node: nbp16-srv1, last update device: dm-7 [ 4106.348120] magic: 4d4d50, seq: 21c, check_interval: 10, checksum: 0 [ 4106.348120] [ 4106.348121] LDISKFS-fs warning (device dm-7): kmmpd:209: copy of MMP block. [ 4106.348122] LDISKFS-fs warning (device dm-7): kmmpd:209: MMP failure info: last update time: 1535161818, last update node: nbp16-srv1, last update device: dm-7 [ 4106.348122] magic: 4d4d50, seq: 21c, check_interval: 10, checksum: 0 [ 4106.348122] [ 4106.472717] Call Trace: [ 4106.472723] [<ffffffff8168f4b8>] dump_stack+0x19/0x1b [ 4106.472727] [<ffffffff81235550>] end_buffer_async_write+0xf0/0x120 [ 4106.472728] [<ffffffff81233dcf>] end_bio_bh_io_sync+0x2f/0x60 [ 4106.472730] [<ffffffff8123aec7>] bio_endio+0x67/0xb0 [ 4106.472731] [<ffffffff8123913d>] ? bio_advance+0x1d/0xd0 [ 4106.472734] [<ffffffff812f2ce0>] blk_update_request+0x90/0x370 [ 4106.472735] [<ffffffff812f2fdc>] blk_update_bidi_request+0x1c/0x80 [ 4106.472736] [<ffffffff812f32ef>] blk_end_bidi_request+0x1f/0x60 [ 4106.472737] [<ffffffff812f340f>] blk_end_request_all+0x1f/0x30 [ 4106.472754] [<ffffffffa03b5755>] dm_softirq_done+0x255/0x2d0 [dm_mod] [ 4106.472756] [<ffffffff812fa0d6>] blk_done_softirq+0x96/0xc0 [ 4106.472759] [<ffffffff81091135>] __do_softirq+0xf5/0x280 [ 4106.472761] [<ffffffff810912f8>] run_ksoftirqd+0x38/0x50 [ 4106.472763] [<ffffffff810b9854>] smpboot_thread_fn+0x144/0x1a0 [ 4106.472764] [<ffffffff810b9710>] ? lg_double_unlock+0x40/0x40 [ 4106.472766] [<ffffffff810b1131>] kthread+0xd1/0xe0 [ 4106.472767] [<ffffffff810b1060>] ? insert_kthread_work+0x40/0x40 [ 4106.472769] [<ffffffff816a14dd>] ret_from_fork+0x5d/0xb0 [ 4106.472770] [<ffffffff810b1060>] ? insert_kthread_work+0x40/0x40 [ 4106.472772] Buffer I/O error on dev dm-4, logical block 2518821, lost async page write [ 4106.801045] LDISKFS-fs warning (device dm-11): kmmpd:208: MMP block mismatch. [ 4106.801047] LDISKFS-fs warning (device dm-11): kmmpd:208: MMP failure info: last update time: 1535161819, last update node: nbp16-srv1, last update device: dm-11 [ 4106.801047] magic: 4d4d50, seq: 222, check_interval: 10, checksum: 0 [ 4106.801047] [ 4106.801047] LDISKFS-fs warning (device dm-11): kmmpd:209: copy of MMP block. [ 4106.801049] LDISKFS-fs warning (device dm-11): kmmpd:209: MMP failure info: last update time: 1535161819, last update node: nbp16-srv1, last update device: dm-11 [ 4106.801049] magic: 4d4d50, seq: 222, check_interval: 10, checksum: 0
I've added the debug patch as Andreas suggested, I also noticed that in the log we have
[ 3520.982436] Buffer I/O error on dev dm-15, logical block 2518821, lost async page write
The "lost async page write" message is from end_buffer_async_write(), but in write_mmp_block(),
we use end_buffer_write_sync() as the completion handler, which would have a different message.
Also there's no "Error writing to MMP block" in the log. I suspect the write to the mmp block is not from the mmp code path, I've added a dump_stack() just above where the async message would appear hopefully we can find out who was writing to the mmp block.
Li Dongyang (dongyangli@ddn.com) uploaded a new patch: https://review.whamcloud.com/33038
Subject: LU-11187 ldiskfs: add debug patches to show mmp block contents
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: daef03d32567d61fab0db16d254412a6d818c1f1
I think there are two possible approaches to debugging this - either save a checksum of the MMP block before/after the write and use that to compare whether the block is modified, or just save a copy of the whole MMP structure in memory for later comparison once the write completes. With newer kernels having support for EXT4_FEATURE_RO_COMPAT_METADATA_CSUM it would be straight forward to use the MMP checksum (this was added in the 3.4 kernel), but not quite as useful for debugging since we wouldn't know more than just "the MMP block was modified".
I think a better approach would be to save the whole MMP structure before each write, and then do a memcmp() after the timeout to see if the block has been modified. Use dump_mmp_msg() to print out the saved and current MMP block contents for comparison (e.g. is it random garbage, was it updated by another node or e2fsck, is it a stale copy of the data, etc).
While looking at this code, I thought it might be possible that the mmp_check_interval at the end of the loop was possibly modifying the buffer while it is being written, but write_mmp_block() should not be returning before the write is complete (it is using REQ_SYNC and b_end_io = end_buffer_write_sync()). Also, there is no mention of the "Error writing to MMP block" message in the logs, so it doesn't seem like there is a problem with the IO submission itself or we would be seeing an error up at the filesystem level.
One thing that is puzzling is the error message "lost async page write", since the REQ_SYNC flag should be forcing the write to be synchronous? I wonder if this is an artifact of the DM Multipath code submitting sync writes asynchronously, so that it isn't blocked waiting for completion if one of the paths fails? That would lend more weight to trying to reproduce this problem without the DM Multipath driver involved. If the problem goes away, you can contact Red Hat about this issue, since MMP and ext4 exist in the upstream kernel and we do not modify MMP in recent releases so it should be reproducible without Lustre (given a sufficiently similar IO workload).