dm_cache BUG() after power loss

dm_cache BUG() after power loss

[Steinar H. Gunderson]

Hi,

We had a power loss event, and when a server with dm-cache came up again,
it paniced (see below for the panic text). I couldn't find any other way to
remedy this than to blow away the metadata volume, which I assumed was safe
as the cache is in writethrough mode (after several catastrophic events with
dm-cache earlier, I don't trust writeback anymore). Unfortunately, this was
seemingly not enough, as the underlying devices came back with various levels
of corruption and eventually had to be restored from backup. (It's running
without dm-cache now.)

Here's the panic:

[   13.388089] device-mapper: cache: You have created a cache device with a lot of individual cache blocks (1114672)
[   13.388089] All these mappings can consume a lot of kernel memory, and take some time to read/write.
[   13.388089] Please consider increasing the cache block size to reduce the overall cache block count.
[   13.452782] device-mapper: array: array_block_check failed: blocknr 1082331758718 != wanted 2156
[   13.462194] device-mapper: block manager: array validator check failed for block 2156
[   13.470643] device-mapper: array: get_ablock failed
[   13.475869] device-mapper: cache metadata: dm_array_cursor_next for mapping failed
[   13.484075] ------------[ cut here ]------------
[   13.489036] kernel BUG at drivers/md/dm-bufio.c:1180!
[   13.494443] invalid opcode: 0000 [#1] SMP PTI
[   13.499144] CPU: 34 PID: 5918 Comm: dmsetup Not tainted 4.18.11 #1
[   13.505671] Hardware name: Supermicro X10DRi/X10DRI-T, BIOS 1.1 04/14/2015
[   13.512885] RIP: 0010:dm_bufio_release+0x18/0x74 [dm_bufio]
[   13.518797] Code: 43 18 48 b8 00 02 00 00 00 00 ad de 48 89 43 20 5b c3 55 53 48 8b 6f 60 48 89 fb 48 89 ef e8 04 7e 20 e1 8b 43 3c 85 c0 75 02 <0f> 0b ff c8 85 c0 89 43 3c 75 47 31 c9 ba 01 00 00 00 be 03 00 00
[   13.538588] RSP: 0018:ffffc90000a03ba0 EFLAGS: 00010246
[   13.544157] RAX: 0000000000000000 RBX: ffff881025a6cea0 RCX: 00000000ffffffff
[   13.551632] RDX: ffff8810303a3980 RSI: ffff881025a6cea0 RDI: ffff881032b37800
[   13.559110] RBP: ffff881032b37800 R08: 0000000000000000 R09: ffff8800000b8c80
[   13.566591] R10: ffffc90000a03b00 R11: ffffffff82194947 R12: 0000000000000000
[   13.574071] R13: ffff881027631340 R14: 00000000000011e4 R15: ffffffffa0127443
[   13.581550] FS:  00007f3cd0894400(0000) GS:ffff88103f480000(0000) knlGS:0000000000000000
[   13.590256] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.596337] CR2: 0000563e475af7a8 CR3: 000000102f802006 CR4: 00000000001606e0
[   13.603812] Call Trace:
[   13.606614]  dm_array_cursor_end+0x1c/0x27 [dm_persistent_data]
[   13.612880]  dm_cache_load_mappings+0x2be/0x2fe [dm_cache]
[   13.618717]  ? retrieve_status+0x176/0x176 [dm_mod]
[   13.623935]  cache_preresume+0xc6/0x195 [dm_cache]
[   13.629067]  dm_table_resume_targets+0x38/0xaa [dm_mod]
[   13.634641]  dm_resume+0x7e/0xa7 [dm_mod]
[   13.639000]  dev_suspend+0x15b/0x1bc [dm_mod]
[   13.643706]  ctl_ioctl+0x2f8/0x394 [dm_mod]
[   13.648238]  dm_ctl_ioctl+0x5/0x8 [dm_mod]
[   13.652681]  vfs_ioctl+0x19/0x26
[   13.656247]  do_vfs_ioctl+0x4d0/0x547
[   13.660255]  ? handle_mm_fault+0x151/0x1b9
[   13.664695]  ksys_ioctl+0x4b/0x6b
[   13.668355]  __x64_sys_ioctl+0x11/0x14
[   13.672446]  do_syscall_64+0x4a/0xd3
[   13.676365]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   13.681758] RIP: 0033:0x7f3ccff7edd7
[   13.685670] Code: 00 00 00 48 8b 05 c1 80 2b 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 91 80 2b 00 f7 d8 64 89 01 48
[   13.705454] RSP: 002b:00007ffcdf6a6f18 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[   13.713640] RAX: ffffffffffffffda RBX: 000055f036494280 RCX: 00007f3ccff7edd7
[   13.721117] RDX: 000055f036494280 RSI: 00000000c138fd06 RDI: 0000000000000003
[   13.728595] RBP: 000000000000000f R08: 00007f3cd048a648 R09: 00007ffcdf6a6d80
[   13.736073] R10: 00007f3cd0489b53 R11: 0000000000000246 R12: 000055f0364942b0
[   13.743553] R13: 00007f3cd0489b53 R14: 000055f036493030 R15: 0000000000000001
[   13.751034] Modules linked in: raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid1 raid10 raid6_pq raid0 md_mod sd_mod usbhid dm_cache_smq dm_cache dm_bio_prison dm_persistent_data dm_bufio dm_mod libcrc32c crc32c_generic ixgbe i2c_i801 mdio ehci_pci crc32c_intel mpt3sas ahci ptp raid_class i2c_core ehci_hcd libahci pps_core unix
[   13.783877] ---[ end trace 1140618cbf25a884 ]---
[   13.792516] RIP: 0010:dm_bufio_release+0x18/0x74 [dm_bufio]
[   13.798431] Code: 43 18 48 b8 00 02 00 00 00 00 ad de 48 89 43 20 5b c3 55 53 48 8b 6f 60 48 89 fb 48 89 ef e8 04 7e 20 e1 8b 43 3c 85 c0 75 02 <0f> 0b ff c8 85 c0 89 43 3c 75 47 31 c9 ba 01 00 00 00 be 03 00 00
[   13.818221] RSP: 0018:ffffc90000a03ba0 EFLAGS: 00010246
[   13.823787] RAX: 0000000000000000 RBX: ffff881025a6cea0 RCX: 00000000ffffffff
[   13.831260] RDX: ffff8810303a3980 RSI: ffff881025a6cea0 RDI: ffff881032b37800
[   13.838742] RBP: ffff881032b37800 R08: 0000000000000000 R09: ffff8800000b8c80
[   13.846220] R10: ffffc90000a03b00 R11: ffffffff82194947 R12: 0000000000000000
[   13.853701] R13: ffff881027631340 R14: 00000000000011e4 R15: ffffffffa0127443
[   13.861182] FS:  00007f3cd0894400(0000) GS:ffff88103f480000(0000) knlGS:0000000000000000
[   13.869889] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.875988] CR2: 0000563e475af7a8 CR3: 000000102f802006 CR4: 00000000001606e0

/* Steinar */
-- 
Homepage: https://www.sesse.net/

Re: dm_cache BUG() after power loss

[Steinar H. Gunderson]

On Tue, Oct 09, 2018 at 06:00:51PM +0200, Steinar H. Gunderson wrote:
> We had a power loss event, and when a server with dm-cache came up again,
> it paniced (see below for the panic text). I couldn't find any other way to
> remedy this than to blow away the metadata volume, which I assumed was safe
> as the cache is in writethrough mode (after several catastrophic events with
> dm-cache earlier, I don't trust writeback anymore). Unfortunately, this was
> seemingly not enough, as the underlying devices came back with various levels
> of corruption and eventually had to be restored from backup. (It's running
> without dm-cache now.)

Is there some other place I should report this? The machine is awfully slow
without its cache, so it's sort of annoying to run without. :-)

/* Steinar */
-- 
Homepage: https://www.sesse.net/

Re: dm_cache BUG() after power loss

[Mike Snitzer]

On Tue, Oct 09 2018 at 12:00pm -0400,
Steinar H. Gunderson <steinar+kernel@gunderson.no> wrote:

> Hi,
> 
> We had a power loss event, and when a server with dm-cache came up again,
> it paniced (see below for the panic text). I couldn't find any other way to
> remedy this than to blow away the metadata volume, which I assumed was safe
> as the cache is in writethrough mode (after several catastrophic events with
> dm-cache earlier, I don't trust writeback anymore). Unfortunately, this was
> seemingly not enough, as the underlying devices came back with various levels
> of corruption and eventually had to be restored from backup. (It's running
> without dm-cache now.)

Please provide the "dmsetup table" line for the cache device if you can.

Are you using writeback mode?

There was a writeback bug that got fixed not too long ago that impacted
users who suffered power loss (or sudden loss of storage), see:
http://git.kernel.org/linus/5b1fe7bec8a8

BUT, it does look like 4.18.11 already has that commit.

Given the "block manager: array validator check failed for block 2156"
error it could easily be that you need to run cache_check and
cache_repair.  Joe (cc'd) may have more specific repair guidance for
you (though Joe is going on vacation.. bad timing).

Mike


> Here's the panic:
> 
> [   13.388089] device-mapper: cache: You have created a cache device with a lot of individual cache blocks (1114672)
> [   13.388089] All these mappings can consume a lot of kernel memory, and take some time to read/write.
> [   13.388089] Please consider increasing the cache block size to reduce the overall cache block count.
> [   13.452782] device-mapper: array: array_block_check failed: blocknr 1082331758718 != wanted 2156
> [   13.462194] device-mapper: block manager: array validator check failed for block 2156
> [   13.470643] device-mapper: array: get_ablock failed
> [   13.475869] device-mapper: cache metadata: dm_array_cursor_next for mapping failed
> [   13.484075] ------------[ cut here ]------------
> [   13.489036] kernel BUG at drivers/md/dm-bufio.c:1180!
> [   13.494443] invalid opcode: 0000 [#1] SMP PTI
> [   13.499144] CPU: 34 PID: 5918 Comm: dmsetup Not tainted 4.18.11 #1
> [   13.505671] Hardware name: Supermicro X10DRi/X10DRI-T, BIOS 1.1 04/14/2015
> [   13.512885] RIP: 0010:dm_bufio_release+0x18/0x74 [dm_bufio]
> [   13.518797] Code: 43 18 48 b8 00 02 00 00 00 00 ad de 48 89 43 20 5b c3 55 53 48 8b 6f 60 48 89 fb 48 89 ef e8 04 7e 20 e1 8b 43 3c 85 c0 75 02 <0f> 0b ff c8 85 c0 89 43 3c 75 47 31 c9 ba 01 00 00 00 be 03 00 00
> [   13.538588] RSP: 0018:ffffc90000a03ba0 EFLAGS: 00010246
> [   13.544157] RAX: 0000000000000000 RBX: ffff881025a6cea0 RCX: 00000000ffffffff
> [   13.551632] RDX: ffff8810303a3980 RSI: ffff881025a6cea0 RDI: ffff881032b37800
> [   13.559110] RBP: ffff881032b37800 R08: 0000000000000000 R09: ffff8800000b8c80
> [   13.566591] R10: ffffc90000a03b00 R11: ffffffff82194947 R12: 0000000000000000
> [   13.574071] R13: ffff881027631340 R14: 00000000000011e4 R15: ffffffffa0127443
> [   13.581550] FS:  00007f3cd0894400(0000) GS:ffff88103f480000(0000) knlGS:0000000000000000
> [   13.590256] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   13.596337] CR2: 0000563e475af7a8 CR3: 000000102f802006 CR4: 00000000001606e0
> [   13.603812] Call Trace:
> [   13.606614]  dm_array_cursor_end+0x1c/0x27 [dm_persistent_data]
> [   13.612880]  dm_cache_load_mappings+0x2be/0x2fe [dm_cache]
> [   13.618717]  ? retrieve_status+0x176/0x176 [dm_mod]
> [   13.623935]  cache_preresume+0xc6/0x195 [dm_cache]
> [   13.629067]  dm_table_resume_targets+0x38/0xaa [dm_mod]
> [   13.634641]  dm_resume+0x7e/0xa7 [dm_mod]
> [   13.639000]  dev_suspend+0x15b/0x1bc [dm_mod]
> [   13.643706]  ctl_ioctl+0x2f8/0x394 [dm_mod]
> [   13.648238]  dm_ctl_ioctl+0x5/0x8 [dm_mod]
> [   13.652681]  vfs_ioctl+0x19/0x26
> [   13.656247]  do_vfs_ioctl+0x4d0/0x547
> [   13.660255]  ? handle_mm_fault+0x151/0x1b9
> [   13.664695]  ksys_ioctl+0x4b/0x6b
> [   13.668355]  __x64_sys_ioctl+0x11/0x14
> [   13.672446]  do_syscall_64+0x4a/0xd3
> [   13.676365]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [   13.681758] RIP: 0033:0x7f3ccff7edd7
> [   13.685670] Code: 00 00 00 48 8b 05 c1 80 2b 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 91 80 2b 00 f7 d8 64 89 01 48
> [   13.705454] RSP: 002b:00007ffcdf6a6f18 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [   13.713640] RAX: ffffffffffffffda RBX: 000055f036494280 RCX: 00007f3ccff7edd7
> [   13.721117] RDX: 000055f036494280 RSI: 00000000c138fd06 RDI: 0000000000000003
> [   13.728595] RBP: 000000000000000f R08: 00007f3cd048a648 R09: 00007ffcdf6a6d80
> [   13.736073] R10: 00007f3cd0489b53 R11: 0000000000000246 R12: 000055f0364942b0
> [   13.743553] R13: 00007f3cd0489b53 R14: 000055f036493030 R15: 0000000000000001
> [   13.751034] Modules linked in: raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid1 raid10 raid6_pq raid0 md_mod sd_mod usbhid dm_cache_smq dm_cache dm_bio_prison dm_persistent_data dm_bufio dm_mod libcrc32c crc32c_generic ixgbe i2c_i801 mdio ehci_pci crc32c_intel mpt3sas ahci ptp raid_class i2c_core ehci_hcd libahci pps_core unix
> [   13.783877] ---[ end trace 1140618cbf25a884 ]---
> [   13.792516] RIP: 0010:dm_bufio_release+0x18/0x74 [dm_bufio]
> [   13.798431] Code: 43 18 48 b8 00 02 00 00 00 00 ad de 48 89 43 20 5b c3 55 53 48 8b 6f 60 48 89 fb 48 89 ef e8 04 7e 20 e1 8b 43 3c 85 c0 75 02 <0f> 0b ff c8 85 c0 89 43 3c 75 47 31 c9 ba 01 00 00 00 be 03 00 00
> [   13.818221] RSP: 0018:ffffc90000a03ba0 EFLAGS: 00010246
> [   13.823787] RAX: 0000000000000000 RBX: ffff881025a6cea0 RCX: 00000000ffffffff
> [   13.831260] RDX: ffff8810303a3980 RSI: ffff881025a6cea0 RDI: ffff881032b37800
> [   13.838742] RBP: ffff881032b37800 R08: 0000000000000000 R09: ffff8800000b8c80
> [   13.846220] R10: ffffc90000a03b00 R11: ffffffff82194947 R12: 0000000000000000
> [   13.853701] R13: ffff881027631340 R14: 00000000000011e4 R15: ffffffffa0127443
> [   13.861182] FS:  00007f3cd0894400(0000) GS:ffff88103f480000(0000) knlGS:0000000000000000
> [   13.869889] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   13.875988] CR2: 0000563e475af7a8 CR3: 000000102f802006 CR4: 00000000001606e0
> 
> /* Steinar */
> -- 
> Homepage: https://www.sesse.net/
> 
> --
> dm-devel mailing list
> dm-devel@redhat.com
> https://www.redhat.com/mailman/listinfo/dm-devel

Re: dm_cache BUG() after power loss

[Steinar H. Gunderson]

On Fri, Oct 19, 2018 at 09:03:50AM -0400, Mike Snitzer wrote:
> Please provide the "dmsetup table" line for the cache device if you can.

It's torn down by now, unfortunately. I can create a new volume and set it
up, if it helps you?

> Are you using writeback mode?

No, it's writethrough. I'd love to use writeback, but I've lost too much data
to it, so I don't really trust it anymore. :-/

Is writethrough actually pure writethrough? When recovering, I had repeated
rounds of:

  - Get to initramfs, which tried to set up the cache and failed.
  - fsck the real, underlying volume, which had lots of corruption.
  - Boot from it.
  - Reboot.
  - Repeat to step 1.

In particular, the volume seemed to become corrupt over and over again
(indicating that dm-cache was writing something to it before it failed),
until I took out the lines fromcachetab.

> Given the "block manager: array validator check failed for block 2156"
> error it could easily be that you need to run cache_check and
> cache_repair.

I hadn't heard of these tools before, and they're not mentioned in
device-mapper/cache.txt. (They should probably have been mentioned in the
error message, too.) Where can I find them?

> Joe (cc'd) may have more specific repair guidance for
> you (though Joe is going on vacation.. bad timing).

Repair is way too late anyway; like I wrote in the original message, I had to
just clear out the entire cache volume to get anywhere.

/* Steinar */
-- 
Homepage: https://www.sesse.net/