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
I ran with OSTs mounted directly to slave device. Disabled multipath and flushed all the paths.. It still got an error.
[ 7087.139668] mlx5_2:mlx5_poll_one:671:(pid 0): CQN: 0x405 Got SIGERR on key: 0x8000c273 err_type 0 err_offset 207 expected 948f actual 9a8f [ 7087.200807] PI error found type 0 at sector 1337928 expected 948f vs actual 9a8f [ 7087.223066] blk_update_request: I/O error, dev sdac, sector 20150568 [ 7087.242167] Buffer I/O error on dev sdac, logical block 2518821, lost async page write
We are only using DM. I Will test with-out DM.
If the write fails as it is logged. Why doesn't the MMP update log an error.
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).
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
It is also confusing to me why there is no "Error writing to MMP block" message being printed in this case, since the write error should be propagated up to the caller with REQ_SYNC. It makes me start to wonder if this block write is being generated somewhere else in the code, and only the MMP code is overwriting the same block in place?
As mentioned previously, it might help to hexdump the MMP block contents in the low-level code, and print out the address of the buffer being written, so that we can see if it is the same page as was submitted by write_mmp_block() or some other copy.