kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178 with scsi_mod.use_blk_mq=y

kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178 with scsi_mod.use_blk_mq=y

[Eric Wheeler]

Hello,

We are using the 4.19.75 stable tree with dm-thin and multi-queue scsi.  
We have been using the 4.19 branch for months without issue; we just 
switched to MQ and we seem to have hit this BUG_ON.  Whether or not MQ is 
related to the issue, I don't know, maybe coincidence:

	static int sm_disk_new_block(struct dm_space_map *sm, dm_block_t *b)
	{
	    int r;
	    enum allocation_event ev;
	    struct sm_disk *smd = container_of(sm, struct sm_disk, sm);

	    /* FIXME: we should loop round a couple of times */
	    r = sm_ll_find_free_block(&smd->old_ll, smd->begin, smd->old_ll.nr_blocks, b);
	    if (r)
		return r;

	    smd->begin = *b + 1;
	    r = sm_ll_inc(&smd->ll, *b, &ev);
	    if (!r) {
		BUG_ON(ev != SM_ALLOC); <<<<<<<<<<<<<<<<<<<<<<<<<<<<<
		smd->nr_allocated_this_transaction++;
	    }

	    return r;
	}

This is a brand-new thin pool created about 12 hours ago:

  lvcreate -c 64k -L 12t --type thin-pool --thinpool data-pool --poolmetadatasize 16G data /dev/bcache0

We are using bcache, but I don't see any bcache code in the backtraces.  
The metadata is also on the bcache volume.

We were transferring data to the new thin volumes and it ran for about 12 
hours and then gave the trace below.  So far it has only happened once 
and I don't have a way to reproduce it.

Any idea what this BUG_ON would indicate and how we might contrive a fix?

-Eric



[199391.677689] ------------[ cut here ]------------
[199391.678437] kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178!
[199391.679183] invalid opcode: 0000 [#1] SMP NOPTI
[199391.679941] CPU: 4 PID: 31359 Comm: kworker/u16:4 Not tainted 4.19.75 #1
[199391.680683] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.2 02/20/2015
[199391.681446] Workqueue: dm-thin do_worker [dm_thin_pool]
[199391.682187] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199391.682929] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
[199391.684432] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
[199391.685186] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
[199391.685936] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
[199391.686659] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
[199391.687379] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
[199391.688120] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
[199391.688843] FS:  0000000000000000(0000) GS:ffff88880fb00000(0000) knlGS:0000000000000000
[199391.689571] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[199391.690253] CR2: 00007f5ae49a1000 CR3: 000000000200a003 CR4: 00000000001626e0
[199391.690984] Call Trace:
[199391.691714]  dm_pool_alloc_data_block+0x3f/0x60 [dm_thin_pool]
[199391.692411]  alloc_data_block.isra.52+0x6d/0x1e0 [dm_thin_pool]
[199391.693142]  process_cell+0x2a3/0x550 [dm_thin_pool]
[199391.693852]  ? sort+0x17b/0x270
[199391.694527]  ? u32_swap+0x10/0x10
[199391.695192]  do_worker+0x268/0x9a0 [dm_thin_pool]
[199391.695890]  process_one_work+0x171/0x370
[199391.696640]  worker_thread+0x49/0x3f0
[199391.697332]  kthread+0xf8/0x130
[199391.697988]  ? max_active_store+0x80/0x80
[199391.698659]  ? kthread_bind+0x10/0x10
[199391.699281]  ret_from_fork+0x1f/0x40
[199391.699930] Modules linked in: dm_snapshot btrfs xor zstd_decompress zstd_compress xxhash raid6_pq xfs dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio drbd lru_cache xt_CHECKSUM iptable_mangle ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c ipt_REJECT nf_reject_ipv4 ebtable_filter ebtables binfmt_misc ip6table_filter ip6_tables bcache xt_comment crc64 iptable_filter netconsole bridge 8021q garp stp mrp llc lz4 lz4_compress zram sunrpc x86_pkg_temp_thermal intel_powerclamp coretemp iTCO_wdt iTCO_vendor_support kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul pcc_cpufreq ghash_clmulni_intel pcspkr sg ipmi_si ipmi_devintf lpc_ich ipmi_msghandler video i2c_i801 mfd_core ip_tables ext4 mbcache jbd2 mgag200 i2c_algo_
 bit drm_kms_helper
[199391.705631]  syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm crc32c_intel i2c_core ahci libahci ixgbe libata e1000e arcmsr mdio dca dm_mirror dm_region_hash dm_log dm_mod
[199391.708083] ---[ end trace c31536d98046e8ec ]---
[199391.866776] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199391.867960] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
[199391.870379] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
[199391.871524] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
[199391.872364] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
[199391.873173] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
[199391.873871] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
[199391.874550] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
[199391.875231] FS:  0000000000000000(0000) GS:ffff88880fb00000(0000) knlGS:0000000000000000
[199391.875941] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[199391.876633] CR2: 00007f5ae49a1000 CR3: 000000000200a003 CR4: 00000000001626e0
[199391.877317] Kernel panic - not syncing: Fatal exception
[199391.878006] Kernel Offset: disabled
[199392.032304] ---[ end Kernel panic - not syncing: Fatal exception ]---
[199392.032962] unchecked MSR access error: WRMSR to 0x83f (tried to write 0x00000000000000f6) at rIP: 0xffffffff81067af4 (native_write_msr+0x4/0x20)
[199392.034277] Call Trace:
[199392.034929]  <IRQ>
[199392.035576]  native_apic_msr_write+0x2e/0x40
[199392.036228]  arch_irq_work_raise+0x28/0x40
[199392.036877]  irq_work_queue_on+0x83/0xa0
[199392.037518]  irq_work_run_list+0x4c/0x70
[199392.038149]  irq_work_run+0x14/0x40
[199392.038771]  smp_call_function_single_interrupt+0x3a/0xd0
[199392.039393]  call_function_single_interrupt+0xf/0x20
[199392.040011]  </IRQ>
[199392.040624] RIP: 0010:panic+0x209/0x25c
[199392.041234] Code: 83 3d 86 de 75 01 00 74 05 e8 ff 5d 02 00 48 c7 c6 e0 bc 80 82 48 c7 c7 10 cd e5 81 31 c0 e8 fe 2b 06 00 fb 66 0f 1f 44 00 00 <45> 31 e4 e8 eb 2e 0d 00 4d 39 ec 7c 1e 41 83 f6 01 48 8b 05 2b de
[199392.042518] RSP: 0018:ffffc9000a147a30 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff04
[199392.043174] RAX: 0000000000000039 RBX: 0000000000000200 RCX: 0000000000000006
[199392.043833] RDX: 0000000000000000 RSI: 0000000000000086 RDI: ffff88880fb168b0
[199392.044493] RBP: ffffc9000a147aa0 R08: 0000000000000001 R09: 00000000000174b5
[199392.045155] R10: ffff8883d9753f00 R11: 0000000000000001 R12: ffffffff81e4a15c
[199392.045820] R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff81e49951
[199392.046486]  oops_end+0xc1/0xd0
[199392.047149]  do_trap+0x13d/0x150
[199392.047795]  do_error_trap+0xd5/0x130
[199392.048427]  ? sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199392.049048]  invalid_op+0x14/0x20
[199392.049650] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199392.050245] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
[199392.051434] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
[199392.052010] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
[199392.052580] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
[199392.053150] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
[199392.053715] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
[199392.054266] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
[199392.054807]  ? __wake_up_common_lock+0x87/0xc0
[199392.055342]  ? sm_disk_new_block+0x82/0xb0 [dm_persistent_data]
[199392.055877]  dm_pool_alloc_data_block+0x3f/0x60 [dm_thin_pool]
[199392.056410]  alloc_data_block.isra.52+0x6d/0x1e0 [dm_thin_pool]
[199392.056947]  process_cell+0x2a3/0x550 [dm_thin_pool]
[199392.057484]  ? sort+0x17b/0x270
[199392.058016]  ? u32_swap+0x10/0x10
[199392.058538]  do_worker+0x268/0x9a0 [dm_thin_pool]
[199392.059060]  process_one_work+0x171/0x370
[199392.059576]  worker_thread+0x49/0x3f0
[199392.060083]  kthread+0xf8/0x130
[199392.060587]  ? max_active_store+0x80/0x80
[199392.061086]  ? kthread_bind+0x10/0x10
[199392.061569]  ret_from_fork+0x1f/0x40
[199392.062038] ------------[ cut here ]------------
[199392.062508] sched: Unexpected reschedule of offline CPU#1!
[199392.062989] WARNING: CPU: 4 PID: 31359 at arch/x86/kernel/smp.c:128 native_smp_send_reschedule+0x39/0x40
[199392.063485] Modules linked in: dm_snapshot btrfs xor zstd_decompress zstd_compress xxhash raid6_pq xfs dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio drbd lru_cache xt_CHECKSUM iptable_mangle ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c ipt_REJECT nf_reject_ipv4 ebtable_filter ebtables binfmt_misc ip6table_filter ip6_tables bcache xt_comment crc64 iptable_filter netconsole bridge 8021q garp stp mrp llc lz4 lz4_compress zram sunrpc x86_pkg_temp_thermal intel_powerclamp coretemp iTCO_wdt iTCO_vendor_support kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul pcc_cpufreq ghash_clmulni_intel pcspkr sg ipmi_si ipmi_devintf lpc_ich ipmi_msghandler video i2c_i801 mfd_core ip_tables ext4 mbcache jbd2 mgag200 i2c_algo_
 bit drm_kms_helper
[199392.067463]  syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm crc32c_intel i2c_core ahci libahci ixgbe libata e1000e arcmsr mdio dca dm_mirror dm_region_hash dm_log dm_mod
[199392.068729] CPU: 4 PID: 31359 Comm: kworker/u16:4 Tainted: G      D           4.19.75 #1
[199392.069356] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.2 02/20/2015
[199392.069982] Workqueue: dm-thin do_worker [dm_thin_pool]
[199392.070604] RIP: 0010:native_smp_send_reschedule+0x39/0x40
[199392.071229] Code: 0f 92 c0 84 c0 74 15 48 8b 05 93 f1 eb 00 be fd 00 00 00 48 8b 40 30 e9 85 f4 9a 00 89 fe 48 c7 c7 08 23 e5 81 e8 c7 9a 05 00 <0f> 0b c3 0f 1f 40 00 0f 1f 44 00 00 53 be 20 00 48 00 48 89 fb 48
[199392.072528] RSP: 0018:ffff88880fb03dc0 EFLAGS: 00010082
[199392.073186] RAX: 0000000000000000 RBX: ffff88880fa625c0 RCX: 0000000000000006
[199392.073847] RDX: 0000000000000000 RSI: 0000000000000096 RDI: ffff88880fb168b0
[199392.074512] RBP: ffff88880fa625c0 R08: 0000000000000001 R09: 00000000000174e5
[199392.075182] R10: ffff8881f2512300 R11: 0000000000000000 R12: ffff888804541640
[199392.075849] R13: ffff88880fb03e08 R14: 0000000000000000 R15: 0000000000000001
[199392.076512] FS:  0000000000000000(0000) GS:ffff88880fb00000(0000) knlGS:0000000000000000
[199392.077179] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[199392.077833] CR2: 00007f5ae49a1000 CR3: 000000000200a003 CR4: 00000000001626e0
[199392.078481] Call Trace:
[199392.079117]  <IRQ>
[199392.079745]  check_preempt_curr+0x6b/0x90
[199392.080373]  ttwu_do_wakeup+0x19/0x130
[199392.080999]  try_to_wake_up+0x1e2/0x460
[199392.081623]  __wake_up_common+0x8f/0x160
[199392.082246]  ep_poll_callback+0x1af/0x300
[199392.082860]  __wake_up_common+0x8f/0x160
[199392.083470]  __wake_up_common_lock+0x7a/0xc0
[199392.084074]  irq_work_run_list+0x4c/0x70
[199392.084675]  smp_call_function_single_interrupt+0x3a/0xd0
[199392.085277]  call_function_single_interrupt+0xf/0x20
[199392.085879]  </IRQ>
[199392.086477] RIP: 0010:panic+0x209/0x25c
[199392.087079] Code: 83 3d 86 de 75 01 00 74 05 e8 ff 5d 02 00 48 c7 c6 e0 bc 80 82 48 c7 c7 10 cd e5 81 31 c0 e8 fe 2b 06 00 fb 66 0f 1f 44 00 00 <45> 31 e4 e8 eb 2e 0d 00 4d 39 ec 7c 1e 41 83 f6 01 48 8b 05 2b de
[199392.088341] RSP: 0018:ffffc9000a147a30 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff04
[199392.088988] RAX: 0000000000000039 RBX: 0000000000000200 RCX: 0000000000000006
[199392.089639] RDX: 0000000000000000 RSI: 0000000000000086 RDI: ffff88880fb168b0
[199392.090291] RBP: ffffc9000a147aa0 R08: 0000000000000001 R09: 00000000000174b5
[199392.090947] R10: ffff8883d9753f00 R11: 0000000000000001 R12: ffffffff81e4a15c
[199392.091601] R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff81e49951
[199392.092255]  oops_end+0xc1/0xd0
[199392.092894]  do_trap+0x13d/0x150
[199392.093516]  do_error_trap+0xd5/0x130
[199392.094122]  ? sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199392.094718]  invalid_op+0x14/0x20
[199392.095296] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199392.095866] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
[199392.097006] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
[199392.097558] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
[199392.098103] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
[199392.098644] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
[199392.099176] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
[199392.099703] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
[199392.100229]  ? __wake_up_common_lock+0x87/0xc0
[199392.100744]  ? sm_disk_new_block+0x82/0xb0 [dm_persistent_data]
[199392.101251]  dm_pool_alloc_data_block+0x3f/0x60 [dm_thin_pool]
[199392.101752]  alloc_data_block.isra.52+0x6d/0x1e0 [dm_thin_pool]
[199392.102252]  process_cell+0x2a3/0x550 [dm_thin_pool]
[199392.102750]  ? sort+0x17b/0x270
[199392.103242]  ? u32_swap+0x10/0x10
[199392.103733]  do_worker+0x268/0x9a0 [dm_thin_pool]
[199392.104228]  process_one_work+0x171/0x370
[199392.104714]  worker_thread+0x49/0x3f0
[199392.105193]  kthread+0xf8/0x130
[199392.105665]  ? max_active_store+0x80/0x80
[199392.106132]  ? kthread_bind+0x10/0x10
[199392.106601]  ret_from_fork+0x1f/0x40
[199392.107069] ---[ end trace c31536d98046e8ed ]---
[199392.107544] ------------[ cut here ]------------
[199392.108017] sched: Unexpected reschedule of offline CPU#7!
[199392.108497] WARNING: CPU: 4 PID: 31359 at arch/x86/kernel/smp.c:128 native_smp_send_reschedule+0x39/0x40
[199392.108996] Modules linked in: dm_snapshot btrfs xor zstd_decompress zstd_compress xxhash raid6_pq xfs dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio drbd lru_cache xt_CHECKSUM iptable_mangle ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c ipt_REJECT nf_reject_ipv4 ebtable_filter ebtables binfmt_misc ip6table_filter ip6_tables bcache xt_comment crc64 iptable_filter netconsole bridge 8021q garp stp mrp llc lz4 lz4_compress zram sunrpc x86_pkg_temp_thermal intel_powerclamp coretemp iTCO_wdt iTCO_vendor_support kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul pcc_cpufreq ghash_clmulni_intel pcspkr sg ipmi_si ipmi_devintf lpc_ich ipmi_msghandler video i2c_i801 mfd_core ip_tables ext4 mbcache jbd2 mgag200 i2c_algo_
 bit drm_kms_helper
[199392.112967]  syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm crc32c_intel i2c_core ahci libahci ixgbe libata e1000e arcmsr mdio dca dm_mirror dm_region_hash dm_log dm_mod
[199392.114203] CPU: 4 PID: 31359 Comm: kworker/u16:4 Tainted: G      D W         4.19.75 #1
[199392.114819] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.2 02/20/2015
[199392.115439] Workqueue: dm-thin do_worker [dm_thin_pool]
[199392.116061] RIP: 0010:native_smp_send_reschedule+0x39/0x40
[199392.116683] Code: 0f 92 c0 84 c0 74 15 48 8b 05 93 f1 eb 00 be fd 00 00 00 48 8b 40 30 e9 85 f4 9a 00 89 fe 48 c7 c7 08 23 e5 81 e8 c7 9a 05 00 <0f> 0b c3 0f 1f 40 00 0f 1f 44 00 00 53 be 20 00 48 00 48 89 fb 48
[199392.117982] RSP: 0018:ffff88880fb03ee0 EFLAGS: 00010082
[199392.118632] RAX: 0000000000000000 RBX: ffff8887d093ac80 RCX: 0000000000000006
[199392.119295] RDX: 0000000000000000 RSI: 0000000000000092 RDI: ffff88880fb168b0
[199392.119961] RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000017529
[199392.120623] R10: ffff8881438ba800 R11: 0000000000000000 R12: ffffc9000a147988
[199392.121283] R13: ffffffff8113f9a0 R14: 0000000000000002 R15: ffff88880fb1cff8
[199392.121938] FS:  0000000000000000(0000) GS:ffff88880fb00000(0000) knlGS:0000000000000000
[199392.122589] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[199392.123229] CR2: 00007f5ae49a1000 CR3: 000000000200a003 CR4: 00000000001626e0
[199392.123867] Call Trace:
[199392.124495]  <IRQ>
[199392.125116]  update_process_times+0x40/0x50
[199392.125742]  tick_sched_handle+0x25/0x60
[199392.126367]  tick_sched_timer+0x37/0x70
[199392.126987]  __hrtimer_run_queues+0xfb/0x270
[199392.127601]  hrtimer_interrupt+0x122/0x270
[199392.128211]  smp_apic_timer_interrupt+0x6a/0x140
[199392.128819]  apic_timer_interrupt+0xf/0x20
[199392.129423]  </IRQ>
[199392.130020] RIP: 0010:panic+0x209/0x25c
[199392.130619] Code: 83 3d 86 de 75 01 00 74 05 e8 ff 5d 02 00 48 c7 c6 e0 bc 80 82 48 c7 c7 10 cd e5 81 31 c0 e8 fe 2b 06 00 fb 66 0f 1f 44 00 00 <45> 31 e4 e8 eb 2e 0d 00 4d 39 ec 7c 1e 41 83 f6 01 48 8b 05 2b de
[199392.131883] RSP: 0018:ffffc9000a147a30 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
[199392.132530] RAX: 0000000000000039 RBX: 0000000000000200 RCX: 0000000000000006
[199392.133180] RDX: 0000000000000000 RSI: 0000000000000086 RDI: ffff88880fb168b0
[199392.133830] RBP: ffffc9000a147aa0 R08: 0000000000000001 R09: 00000000000174b5
[199392.134482] R10: ffff8883d9753f00 R11: 0000000000000001 R12: ffffffff81e4a15c
[199392.135136] R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff81e49951
[199392.135792]  oops_end+0xc1/0xd0
[199392.136444]  do_trap+0x13d/0x150
[199392.137094]  do_error_trap+0xd5/0x130
[199392.137740]  ? sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199392.138383]  invalid_op+0x14/0x20
[199392.139010] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
[199392.139630] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
[199392.140870] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
[199392.141472] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
[199392.142066] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
[199392.142647] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
[199392.143211] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
[199392.143759] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
[199392.144301]  ? __wake_up_common_lock+0x87/0xc0
[199392.144838]  ? sm_disk_new_block+0x82/0xb0 [dm_persistent_data]
[199392.145374]  dm_pool_alloc_data_block+0x3f/0x60 [dm_thin_pool]
[199392.145909]  alloc_data_block.isra.52+0x6d/0x1e0 [dm_thin_pool]
[199392.146435]  process_cell+0x2a3/0x550 [dm_thin_pool]
[199392.146949]  ? sort+0x17b/0x270
[199392.147450]  ? u32_swap+0x10/0x10
[199392.147944]  do_worker+0x268/0x9a0 [dm_thin_pool]
[199392.148441]  process_one_work+0x171/0x370
[199392.148937]  worker_thread+0x49/0x3f0
[199392.149430]  kthread+0xf8/0x130
[199392.149922]  ? max_active_store+0x80/0x80
[199392.150406]  ? kthread_bind+0x10/0x10
[199392.150883]  ret_from_fork+0x1f/0x40
[199392.151353] ---[ end trace c31536d98046e8ee ]---


--
Eric Wheeler

Re: kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178 with scsi_mod.use_blk_mq=y

[Mike Snitzer]

On Wed, Sep 25 2019 at  2:40pm -0400,
Eric Wheeler <dm-devel@lists.ewheeler.net> wrote:

> Hello,
> 
> We are using the 4.19.75 stable tree with dm-thin and multi-queue scsi.  
> We have been using the 4.19 branch for months without issue; we just 
> switched to MQ and we seem to have hit this BUG_ON.  Whether or not MQ is 
> related to the issue, I don't know, maybe coincidence:
> 
> 	static int sm_disk_new_block(struct dm_space_map *sm, dm_block_t *b)
> 	{
> 	    int r;
> 	    enum allocation_event ev;
> 	    struct sm_disk *smd = container_of(sm, struct sm_disk, sm);
> 
> 	    /* FIXME: we should loop round a couple of times */
> 	    r = sm_ll_find_free_block(&smd->old_ll, smd->begin, smd->old_ll.nr_blocks, b);
> 	    if (r)
> 		return r;
> 
> 	    smd->begin = *b + 1;
> 	    r = sm_ll_inc(&smd->ll, *b, &ev);
> 	    if (!r) {
> 		BUG_ON(ev != SM_ALLOC); <<<<<<<<<<<<<<<<<<<<<<<<<<<<<
> 		smd->nr_allocated_this_transaction++;
> 	    }
> 
> 	    return r;
> 	}
> 
> This is a brand-new thin pool created about 12 hours ago:
> 
>   lvcreate -c 64k -L 12t --type thin-pool --thinpool data-pool --poolmetadatasize 16G data /dev/bcache0
> 
> We are using bcache, but I don't see any bcache code in the backtraces.  
> The metadata is also on the bcache volume.

So bcache is be used for both data and metadata.
 
> We were transferring data to the new thin volumes and it ran for about 12 
> hours and then gave the trace below.  So far it has only happened once 
> and I don't have a way to reproduce it.
> 
> Any idea what this BUG_ON would indicate and how we might contrive a fix?
>
> [199391.677689] ------------[ cut here ]------------
> [199391.678437] kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178!
> [199391.679183] invalid opcode: 0000 [#1] SMP NOPTI
> [199391.679941] CPU: 4 PID: 31359 Comm: kworker/u16:4 Not tainted 4.19.75 #1
> [199391.680683] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.2 02/20/2015
> [199391.681446] Workqueue: dm-thin do_worker [dm_thin_pool]
> [199391.682187] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
> [199391.682929] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
> [199391.684432] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
> [199391.685186] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
> [199391.685936] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
> [199391.686659] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
> [199391.687379] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
> [199391.688120] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
> [199391.688843] FS:  0000000000000000(0000) GS:ffff88880fb00000(0000) knlGS:0000000000000000
> [199391.689571] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [199391.690253] CR2: 00007f5ae49a1000 CR3: 000000000200a003 CR4: 00000000001626e0
> [199391.690984] Call Trace:
> [199391.691714]  dm_pool_alloc_data_block+0x3f/0x60 [dm_thin_pool]
> [199391.692411]  alloc_data_block.isra.52+0x6d/0x1e0 [dm_thin_pool]
> [199391.693142]  process_cell+0x2a3/0x550 [dm_thin_pool]
> [199391.693852]  ? sort+0x17b/0x270
> [199391.694527]  ? u32_swap+0x10/0x10
> [199391.695192]  do_worker+0x268/0x9a0 [dm_thin_pool]
> [199391.695890]  process_one_work+0x171/0x370
> [199391.696640]  worker_thread+0x49/0x3f0
> [199391.697332]  kthread+0xf8/0x130
> [199391.697988]  ? max_active_store+0x80/0x80
> [199391.698659]  ? kthread_bind+0x10/0x10
> [199391.699281]  ret_from_fork+0x1f/0x40

The stack shows the call to sm_disk_new_block() is due to
dm_pool_alloc_data_block().

sm_disk_new_block()'s BUG_ON(ev != SM_ALLOC) indicates that somehow it is
getting called without the passed 'ev' being set to SM_ALLOC.  Only
drivers/md/persistent-dat/dm-space-map-common.c:sm_ll_mutate() sets
SM_ALLOC. sm_disk_new_block() is indirectly calling sm_ll_mutate()

sm_ll_mutate() will only return 0 if ll->save_ie() does, the ll_disk *ll
should be ll_disk, and so disk_ll_save_ie()'s call to dm_btree_insert()
returns 0 -- which simply means success.  And on success
sm_disk_new_block() assumes ev was set to SM_ALLOC (by sm_ll_mutate).

sm_ll_mutate() decided to _not_ set SM_ALLOC because either:
1) ref_count wasn't set
or
2) old was identified

So all said: somehow a new data block was found to already be in use.
_WHY_ that is the case isn't clear from this stack...

But it does speak to the possibility of data block allocation racing
with other operations to the same block.  Which implies missing locking.

But that's all I've got so far... I'll review past dm-thinp changes with
all this in mind and see what turns up.  But Joe Thornber (ejt) likely
needs to have a look at this too.

But could it be that bcache is the source of the data device race (same
block used concurrently)?  And DM thinp is acting as the canary in the
coal mine?

Thanks,
Mike

Re: kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178 with scsi_mod.use_blk_mq=y

[Eric Wheeler]

On Wed, 25 Sep 2019, Mike Snitzer wrote:
> On Wed, Sep 25 2019 at  2:40pm -0400, Eric Wheeler <dm-devel@lists.ewheeler.net> wrote:
> 
> > Hello,
> > 
> > We are using the 4.19.75 stable tree with dm-thin and multi-queue scsi.  
> > We have been using the 4.19 branch for months without issue; we just 
> > switched to MQ and we seem to have hit this BUG_ON.  Whether or not MQ is 
> > related to the issue, I don't know, maybe coincidence:
> > 
> > 	static int sm_disk_new_block(struct dm_space_map *sm, dm_block_t *b)
> > 	{
> > 	    int r;
> > 	    enum allocation_event ev;
> > 	    struct sm_disk *smd = container_of(sm, struct sm_disk, sm);
> > 
> > 	    /* FIXME: we should loop round a couple of times */
> > 	    r = sm_ll_find_free_block(&smd->old_ll, smd->begin, smd->old_ll.nr_blocks, b);
> > 	    if (r)
> > 		return r;
> > 
> > 	    smd->begin = *b + 1;
> > 	    r = sm_ll_inc(&smd->ll, *b, &ev);
> > 	    if (!r) {
> > 		BUG_ON(ev != SM_ALLOC); <<<<<<<<<<<<<<<<<<<<<<<<<<<<<
> > 		smd->nr_allocated_this_transaction++;
> > 	    }
> > 
> > 	    return r;
> > 	}
> > 
> > This is a brand-new thin pool created about 12 hours ago:
> > 
> >   lvcreate -c 64k -L 12t --type thin-pool --thinpool data-pool --poolmetadatasize 16G data /dev/bcache0
> > 
> > We are using bcache, but I don't see any bcache code in the backtraces.  
> > The metadata is also on the bcache volume.
> 
> So bcache is be used for both data and metadata.

Correct.
  
> > We were transferring data to the new thin volumes and it ran for about 12 
> > hours and then gave the trace below.  So far it has only happened once 
> > and I don't have a way to reproduce it.
> > 
> > Any idea what this BUG_ON would indicate and how we might contrive a fix?
> >
> > [199391.677689] ------------[ cut here ]------------
> > [199391.678437] kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178!
> > [199391.679183] invalid opcode: 0000 [#1] SMP NOPTI
> > [199391.679941] CPU: 4 PID: 31359 Comm: kworker/u16:4 Not tainted 4.19.75 #1
> > [199391.680683] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.2 02/20/2015
> > [199391.681446] Workqueue: dm-thin do_worker [dm_thin_pool]
> > [199391.682187] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
> > [199391.682929] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
> > [199391.684432] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
> > [199391.685186] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
> > [199391.685936] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
> > [199391.686659] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
> > [199391.687379] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
> > [199391.688120] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
> > [199391.688843] FS:  0000000000000000(0000) GS:ffff88880fb00000(0000) knlGS:0000000000000000
> > [199391.689571] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [199391.690253] CR2: 00007f5ae49a1000 CR3: 000000000200a003 CR4: 00000000001626e0
> > [199391.690984] Call Trace:
> > [199391.691714]  dm_pool_alloc_data_block+0x3f/0x60 [dm_thin_pool]
> > [199391.692411]  alloc_data_block.isra.52+0x6d/0x1e0 [dm_thin_pool]
> > [199391.693142]  process_cell+0x2a3/0x550 [dm_thin_pool]
> > [199391.693852]  ? sort+0x17b/0x270
> > [199391.694527]  ? u32_swap+0x10/0x10
> > [199391.695192]  do_worker+0x268/0x9a0 [dm_thin_pool]
> > [199391.695890]  process_one_work+0x171/0x370
> > [199391.696640]  worker_thread+0x49/0x3f0
> > [199391.697332]  kthread+0xf8/0x130
> > [199391.697988]  ? max_active_store+0x80/0x80
> > [199391.698659]  ? kthread_bind+0x10/0x10
> > [199391.699281]  ret_from_fork+0x1f/0x40
> 
> The stack shows the call to sm_disk_new_block() is due to
> dm_pool_alloc_data_block().
> 
> sm_disk_new_block()'s BUG_ON(ev != SM_ALLOC) indicates that somehow it is
> getting called without the passed 'ev' being set to SM_ALLOC.  Only
> drivers/md/persistent-dat/dm-space-map-common.c:sm_ll_mutate() sets
> SM_ALLOC. sm_disk_new_block() is indirectly calling sm_ll_mutate()
> 
> sm_ll_mutate() will only return 0 if ll->save_ie() does, the ll_disk *ll
> should be ll_disk, and so disk_ll_save_ie()'s call to dm_btree_insert()
> returns 0 -- which simply means success.  And on success
> sm_disk_new_block() assumes ev was set to SM_ALLOC (by sm_ll_mutate).
> 
> sm_ll_mutate() decided to _not_ set SM_ALLOC because either:
> 1) ref_count wasn't set
> or
> 2) old was identified
> 
> So all said: somehow a new data block was found to already be in use.
> _WHY_ that is the case isn't clear from this stack...
> 
> But it does speak to the possibility of data block allocation racing
> with other operations to the same block.  Which implies missing locking.
> 
> But that's all I've got so far... I'll review past dm-thinp changes with
> all this in mind and see what turns up.  But Joe Thornber (ejt) likely
> needs to have a look at this too.
> 
> But could it be that bcache is the source of the data device race (same
> block used concurrently)?  And DM thinp is acting as the canary in the
> coal mine?

Hi Mike, thanks for the detail.  

Coly, any idea on the possible bcache interaction here?


--
Eric Wheeler

Re: kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178 with scsi_mod.use_blk_mq=y

[Eric Wheeler]

On Wed, 25 Sep 2019, Mike Snitzer wrote:
> On Wed, Sep 25 2019 at  2:40pm -0400,
> Eric Wheeler <dm-devel@lists.ewheeler.net> wrote:
> 
> > Hello,
> > 
> > We are using the 4.19.75 stable tree with dm-thin and multi-queue scsi.  
> > We have been using the 4.19 branch for months without issue; we just 
> > switched to MQ and we seem to have hit this BUG_ON.  Whether or not MQ is 
> > related to the issue, I don't know, maybe coincidence:
> > 
> > 	static int sm_disk_new_block(struct dm_space_map *sm, dm_block_t *b)
> > 	{
> > 	    int r;
> > 	    enum allocation_event ev;
> > 	    struct sm_disk *smd = container_of(sm, struct sm_disk, sm);
> > 
> > 	    /* FIXME: we should loop round a couple of times */
> > 	    r = sm_ll_find_free_block(&smd->old_ll, smd->begin, smd->old_ll.nr_blocks, b);
> > 	    if (r)
> > 		return r;
> > 
> > 	    smd->begin = *b + 1;
> > 	    r = sm_ll_inc(&smd->ll, *b, &ev);
> > 	    if (!r) {
> > 		BUG_ON(ev != SM_ALLOC); <<<<<<<<<<<<<<<<<<<<<<<<<<<<<
> > 		smd->nr_allocated_this_transaction++;
> > 	    }
> > 
> > 	    return r;
> > 	}
> > 
> > This is a brand-new thin pool created about 12 hours ago:
> > 
> >   lvcreate -c 64k -L 12t --type thin-pool --thinpool data-pool --poolmetadatasize 16G data /dev/bcache0
> > 
> > We are using bcache, but I don't see any bcache code in the backtraces.  
> > The metadata is also on the bcache volume.
> 
> So bcache is be used for both data and metadata.

Hi Mike, 

I pvmoved the tmeta to an SSD logical volume (dm-linear) on a non-bcache 
volume and we got the same trace this morning, so while the tdata still 
passes through bcache, all meta operations are direct to an SSD. This is 
still using multi-queue scsi, but dm_mod.use_blk_mq=N.

Since bcache is no longer involved with metadata operations, and since 
this appears to be a metadata issue, are there any other reasons to 
suspect bcache?

Since we seem to hit this every night, I can try any patches that you 
would like for testing. I appreciate your help, hopefully we can solve 
this quickly. 


-Eric
  
> > We were transferring data to the new thin volumes and it ran for about 12 
> > hours and then gave the trace below.  So far it has only happened once 
> > and I don't have a way to reproduce it.
> > 
> > Any idea what this BUG_ON would indicate and how we might contrive a fix?
> >
> > [199391.677689] ------------[ cut here ]------------
> > [199391.678437] kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178!
> > [199391.679183] invalid opcode: 0000 [#1] SMP NOPTI
> > [199391.679941] CPU: 4 PID: 31359 Comm: kworker/u16:4 Not tainted 4.19.75 #1
> > [199391.680683] Hardware name: Supermicro X9SCL/X9SCM/X9SCL/X9SCM, BIOS 2.2 02/20/2015
> > [199391.681446] Workqueue: dm-thin do_worker [dm_thin_pool]
> > [199391.682187] RIP: 0010:sm_disk_new_block+0xa0/0xb0 [dm_persistent_data]
> > [199391.682929] Code: 22 00 00 49 8b 34 24 e8 4e f9 ff ff 85 c0 75 11 83 7c 24 04 01 75 13 48 83 83 28 22 00 00 01 eb af 89 c5 eb ab e8 e0 95 9b e0 <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55
> > [199391.684432] RSP: 0018:ffffc9000a147c88 EFLAGS: 00010297
> > [199391.685186] RAX: 0000000000000000 RBX: ffff8887ceed8000 RCX: 0000000000000000
> > [199391.685936] RDX: ffff8887d093ac80 RSI: 0000000000000246 RDI: ffff8887faab0a00
> > [199391.686659] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff8887faab0a98
> > [199391.687379] R10: ffffffff810f8077 R11: 0000000000000000 R12: ffffc9000a147d58
> > [199391.688120] R13: ffffc9000a147d58 R14: 00000000ffffffc3 R15: 000000000014bbc0
> > [199391.688843] FS:  0000000000000000(0000) GS:ffff88880fb00000(0000) knlGS:0000000000000000
> > [199391.689571] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [199391.690253] CR2: 00007f5ae49a1000 CR3: 000000000200a003 CR4: 00000000001626e0
> > [199391.690984] Call Trace:
> > [199391.691714]  dm_pool_alloc_data_block+0x3f/0x60 [dm_thin_pool]
> > [199391.692411]  alloc_data_block.isra.52+0x6d/0x1e0 [dm_thin_pool]
> > [199391.693142]  process_cell+0x2a3/0x550 [dm_thin_pool]
> > [199391.693852]  ? sort+0x17b/0x270
> > [199391.694527]  ? u32_swap+0x10/0x10
> > [199391.695192]  do_worker+0x268/0x9a0 [dm_thin_pool]
> > [199391.695890]  process_one_work+0x171/0x370
> > [199391.696640]  worker_thread+0x49/0x3f0
> > [199391.697332]  kthread+0xf8/0x130
> > [199391.697988]  ? max_active_store+0x80/0x80
> > [199391.698659]  ? kthread_bind+0x10/0x10
> > [199391.699281]  ret_from_fork+0x1f/0x40
> 
> The stack shows the call to sm_disk_new_block() is due to
> dm_pool_alloc_data_block().
> 
> sm_disk_new_block()'s BUG_ON(ev != SM_ALLOC) indicates that somehow it is
> getting called without the passed 'ev' being set to SM_ALLOC.  Only
> drivers/md/persistent-dat/dm-space-map-common.c:sm_ll_mutate() sets
> SM_ALLOC. sm_disk_new_block() is indirectly calling sm_ll_mutate()
> 
> sm_ll_mutate() will only return 0 if ll->save_ie() does, the ll_disk *ll
> should be ll_disk, and so disk_ll_save_ie()'s call to dm_btree_insert()
> returns 0 -- which simply means success.  And on success
> sm_disk_new_block() assumes ev was set to SM_ALLOC (by sm_ll_mutate).
> 
> sm_ll_mutate() decided to _not_ set SM_ALLOC because either:
> 1) ref_count wasn't set
> or
> 2) old was identified
> 
> So all said: somehow a new data block was found to already be in use.
> _WHY_ that is the case isn't clear from this stack...
> 
> But it does speak to the possibility of data block allocation racing
> with other operations to the same block.  Which implies missing locking.
> 
> But that's all I've got so far... I'll review past dm-thinp changes with
> all this in mind and see what turns up.  But Joe Thornber (ejt) likely
> needs to have a look at this too.
> 
> But could it be that bcache is the source of the data device race (same
> block used concurrently)?  And DM thinp is acting as the canary in the
> coal mine?
> 
> Thanks,
> Mike
> 

Re: kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178 with scsi_mod.use_blk_mq=y

[Joe Thornber]

Hi Eric,

On Thu, Sep 26, 2019 at 06:27:09PM +0000, Eric Wheeler wrote:
> I pvmoved the tmeta to an SSD logical volume (dm-linear) on a non-bcache 
> volume and we got the same trace this morning, so while the tdata still 
> passes through bcache, all meta operations are direct to an SSD. This is 
> still using multi-queue scsi, but dm_mod.use_blk_mq=N.
> 
> Since bcache is no longer involved with metadata operations, and since 
> this appears to be a metadata issue, are there any other reasons to 
> suspect bcache?

Did you recreate the pool, or are you just using the existing pool but with
a different IO path?  If it's the latter then there could still be something
wrong with the metadata, introduced while bcache was in the stack.

Would it be possible to send me a copy of the metadata device please so
I can double check the space maps (I presume you've run thin_check on it)?

[Assuming you're using the existing pool] Another useful experiment would be to 
thump_dump and then thin_restore the metadata, which will create totally fresh
metadata and see if you can still reproduce the issue.

Thanks,

- Joe

Re: kernel BUG at drivers/md/persistent-data/dm-space-map-disk.c:178 with scsi_mod.use_blk_mq=y

[Eric Wheeler]

On Fri, 27 Sep 2019, Joe Thornber wrote:

> Hi Eric,
> 
> On Thu, Sep 26, 2019 at 06:27:09PM +0000, Eric Wheeler wrote:
> > I pvmoved the tmeta to an SSD logical volume (dm-linear) on a non-bcache 
> > volume and we got the same trace this morning, so while the tdata still 
> > passes through bcache, all meta operations are direct to an SSD. This is 
> > still using multi-queue scsi, but dm_mod.use_blk_mq=N.
> > 
> > Since bcache is no longer involved with metadata operations, and since 
> > this appears to be a metadata issue, are there any other reasons to 
> > suspect bcache?
> 
> Did you recreate the pool, or are you just using the existing pool but with
> a different IO path?  If it's the latter then there could still be something
> wrong with the metadata, introduced while bcache was in the stack.

We did not create the pool after the initial problem, though the pool was 
new just before the problem occurred. 
 
> Would it be possible to send me a copy of the metadata device please so
> I can double check the space maps (I presume you've run thin_check on it)?

~]# /usr/local/bin/thin_check /dev/mapper/data-data--pool_tmeta 
examining superblock
TRANSACTION_ID=2347
METADATA_FREE_BLOCKS=4145151
examining devices tree
examining mapping tree
checking space map counts

~]# echo $?
0

~]# /usr/local/bin/thin_check -V
0.8.5

> [Assuming you're using the existing pool] Another useful experiment would be to 
> thump_dump and then thin_restore the metadata, which will create totally fresh
> metadata and see if you can still reproduce the issue.

It didn't lockup last night, but I'll keep working to reproduce the 
problem and let you know what we find.

Mike said it could be a race:

> The stack shows the call to sm_disk_new_block() is due to
> dm_pool_alloc_data_block().
> 
> sm_disk_new_block()'s BUG_ON(ev != SM_ALLOC) indicates that somehow it is
> getting called without the passed 'ev' being set to SM_ALLOC.  Only
> drivers/md/persistent-dat/dm-space-map-common.c:sm_ll_mutate() sets
> SM_ALLOC. sm_disk_new_block() is indirectly calling sm_ll_mutate()
> 
> sm_ll_mutate() will only return 0 if ll->save_ie() does, the ll_disk *ll
> should be ll_disk, and so disk_ll_save_ie()'s call to dm_btree_insert()
> returns 0 -- which simply means success.  And on success
> sm_disk_new_block() assumes ev was set to SM_ALLOC (by sm_ll_mutate).
> 
> sm_ll_mutate() decided to _not_ set SM_ALLOC because either:
> 1) ref_count wasn't set
> or
> 2) old was identified
> 
> So all said: somehow a new data block was found to already be in use.
> _WHY_ that is the case isn't clear from this stack...
>
> But it does speak to the possibility of data block allocation racing
> with other operations to the same block.  Which implies missing locking.

Would a spinlock on the block solve the issue?

Where might such a spinlock be added?


--
Eric Wheeler


> 
> Thanks,
> 
> - Joe
> 

--
lvm-devel mailing list
lvm-devel@redhat.com
https://www.redhat.com/mailman/listinfo/lvm-devel