dmcache RAID1 bug?

dmcache RAID1 bug?

[Leonardo Santos]

[-- Attachment #1.1: Type: text/plain, Size: 19771 bytes --]

I'm working in tests for my msc thesis envolving dm_cache module. I'm
having problems with the following scenario:

Slowstorage: RAID1 (mdadm) with 4 HDDs;
- /dev/md/raid1_4ssds
-- /dev/sda
-- /dev/sdb
-- /dev/sdc
-- /dev/sdd

Faststorage: RAID1 (mdadm) with 4 SSDs
- /dev/md/raid1_4hdds
-- /dev/sde
-- /dev/sdf
-- /dev/sdg
-- /dev/sdh

Cachestorage: dm_cache envolving both devices
- /dev/mapper/dmcache
-- /dev/md/raid1_4ssds
-- /dev/md/raid1_4hdds

Other informations (strange facts):
In RAID0 it's working very well.
In a virtual machine (vbox) it's working as well (in this case disks have
2GB only for big tests automatization, in production are 160GB SSDs and 2TB
HDDs);

Have you seen about this error? Syslog is bellow.

Thanks!
Leonardo Santos


Nov 14 17:05:36 steinhager mdadm[2412]: NewArray event detected on md
device /dev/md/raid1_4ssds
Nov 14 17:05:36 steinhager kernel: [22995.480318] md/raid1:md126: active
with 4 out of 4 mirrors
Nov 14 17:05:36 steinhager kernel: [22995.480367] md126: detected capacity
change from 0 to 2197865431040
Nov 14 17:05:36 steinhager kernel: [22995.491499]  md126: unknown partition
table
Nov 14 17:05:39 steinhager kernel: [22999.008757] device-mapper:
cache-policy-mq: version 1.2.0 loaded
Nov 14 17:05:40 steinhager kernel: [22999.086449] BUG: unable to handle
kernel paging request at 0000000ffcc35800
Nov 14 17:05:40 steinhager kernel: [22999.086486] IP: [<ffffffffa03c102e>]
bio_list_pop+0x8/0x23 [dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.086518] PGD 0
Nov 14 17:05:40 steinhager kernel: [22999.086531] Oops: 0000 [#1] SMP
Nov 14 17:05:40 steinhager kernel: [22999.086553] Modules linked in:
dm_cache_mq dm_cache dm_persistent_data dm_bio_prison dm_bufio libcrc32c
raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx
raid6_pq raid0 raid1 md_mod coretemp kvm_intel kvm snd_pcm iTCO_wdt
snd_timer snd i7core_edac ioatdma psmouse edac_core iTCO_vendor_support
ipmi_si soundcore lpc_ich mfd_core i2c_i801 evdev pcspkr serio_raw
microcode ipmi_msghandler ehci_pci button acpi_cpufreq processor
thermal_sys ext4 crc16 jbd2 mbcache dm_mod sr_mod cdrom sg sd_mod
crc_t10dif crct10dif_common crc32c_intel uhci_hcd firewire_ohci ehci_hcd
ata_generic ahci firewire_core libahci pata_jmicron crc_itu_t usbcore
libata usb_common megaraid_sas igb i2c_algo_bit i2c_core dca ptp pps_core
scsi_mod [last unloaded: dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.086972] CPU: 4 PID: 6 Comm:
kworker/u48:0 Not tainted 3.17.2 #2
Nov 14 17:05:40 steinhager kernel: [22999.086996] Hardware name: SGI.COM
C3108-TY11/X8DAH, BIOS 1.1     03/16/2011
Nov 14 17:05:40 steinhager kernel: [22999.087024] Workqueue: dm-cache
do_worker [dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.087045] task: ffff8801b90ec050
ti: ffff8801b90fc000 task.ti: ffff8801b90fc000
Nov 14 17:05:40 steinhager kernel: [22999.087072] RIP:
0010:[<ffffffffa03c102e>]  [<ffffffffa03c102e>] bio_list_pop+0x8/0x23
[dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.087132] RSP:
0018:ffff8801b90ffdb0  EFLAGS: 00010206
Nov 14 17:05:40 steinhager kernel: [22999.087176] RAX: 0000000ffcc35800
RBX: ffff880338e5bd48 RCX: 0000000000000008
Nov 14 17:05:40 steinhager kernel: [22999.087226] RDX: 0000000000000000
RSI: ffff88032c1b3400 RDI: ffff8801b90ffde8
Nov 14 17:05:40 steinhager kernel: [22999.087276] RBP: ffff880338e5bc00
R08: ffff8801b90fc000 R09: 0000000000000000
Nov 14 17:05:40 steinhager kernel: [22999.087325] R10: 000000000000b951
R11: 0000000000000005 R12: ffff8801b90ffe00
Nov 14 17:05:40 steinhager kernel: [22999.087375] R13: ffff8801b90ffde8
R14: ffff880338e5bc5c R15: 0000000000000246
Nov 14 17:05:40 steinhager kernel: [22999.087425] FS:
 0000000000000000(0000) GS:ffff88033fc00000(0000) knlGS:0000000000000000
Nov 14 17:05:40 steinhager kernel: [22999.087502] CS:  0010 DS: 0000 ES:
0000 CR0: 000000008005003b
Nov 14 17:05:40 steinhager kernel: [22999.087547] CR2: 0000000ffcc35800
CR3: 0000000001611000 CR4: 00000000000007e0
Nov 14 17:05:40 steinhager kernel: [22999.087597] Stack:
Nov 14 17:05:40 steinhager kernel: [22999.087630]  ffffffffa03c4095
ffff880338e5bc60 ffff8801b90ec050 0000000000000000
Nov 14 17:05:40 steinhager kernel: [22999.087713]  ffff88033fc131f0
ffffffff810016b0 ffff8801b90ec568 0000000ffcc35800
Nov 14 17:05:40 steinhager kernel: [22999.087796]  0000000ee6ea5800
ffff880331a323c0 ffff880331a31470 ffff880331a32400
Nov 14 17:05:40 steinhager kernel: [22999.087879] Call Trace:
Nov 14 17:05:40 steinhager kernel: [22999.087917]  [<ffffffffa03c4095>] ?
do_worker+0x29f/0x649 [dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.087968]  [<ffffffff810016b0>] ?
__switch_to+0x22d/0x45a
Nov 14 17:05:40 steinhager kernel: [22999.088016]  [<ffffffff8104dfb5>] ?
process_one_work+0x158/0x27b
Nov 14 17:05:40 steinhager kernel: [22999.088063]  [<ffffffff8104e765>] ?
worker_thread+0x1ea/0x294
Nov 14 17:05:40 steinhager kernel: [22999.088109]  [<ffffffff8104e57b>] ?
rescuer_thread+0x217/0x217
Nov 14 17:05:40 steinhager kernel: [22999.088157]  [<ffffffff81051db6>] ?
kthread+0xa7/0xaf
Nov 14 17:05:40 steinhager kernel: [22999.088201]  [<ffffffff81051d0f>] ?
__kthread_parkme+0x5b/0x5b
Nov 14 17:05:40 steinhager kernel: [22999.088251]  [<ffffffff81397d2c>] ?
ret_from_fork+0x7c/0xb0
Nov 14 17:05:40 steinhager kernel: [22999.088296]  [<ffffffff81051d0f>] ?
__kthread_parkme+0x5b/0x5b
Nov 14 17:05:40 steinhager kernel: [22999.088342] Code: c3 48 8b 06 48 85
c0 74 19 48 8b 57 08 48 85 d2 74 05 48 89 02 eb 03 48 89 07 48 8b 46 08 48
89 47 08 c3 48 8b 07 48 85 c0 74 1a <48> 8b 10 48 85 d2 48 89 17 75 08 48
c7 47 08 00 00 00 00 48 c7
Nov 14 17:05:40 steinhager kernel: [22999.088625] RIP  [<ffffffffa03c102e>]
bio_list_pop+0x8/0x23 [dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.088677]  RSP <ffff8801b90ffdb0>
Nov 14 17:05:40 steinhager kernel: [22999.088714] CR2: 0000000ffcc35800
Nov 14 17:05:40 steinhager kernel: [22999.089108] ---[ end trace
91dc97f60fa89842 ]---
Nov 14 17:05:40 steinhager kernel: [22999.089114] general protection fault:
0000 [#2] SMP
Nov 14 17:05:40 steinhager kernel: [22999.089151] Modules linked in:
dm_cache_mq dm_cache dm_persistent_data dm_bio_prison dm_bufio libcrc32c
raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx
raid6_pq raid0 raid1 md_mod coretemp kvm_intel kvm snd_pcm iTCO_wdt
snd_timer snd i7core_edac ioatdma psmouse edac_core iTCO_vendor_support
ipmi_si soundcore lpc_ich mfd_core i2c_i801 evdev pcspkr serio_raw
microcode ipmi_msghandler ehci_pci button acpi_cpufreq processor
thermal_sys ext4 crc16 jbd2 mbcache dm_mod sr_mod cdrom sg sd_mod
crc_t10dif crct10dif_common crc32c_intel uhci_hcd firewire_ohci ehci_hcd
ata_generic ahci firewire_core libahci pata_jmicron crc_itu_t usbcore
libata usb_common megaraid_sas igb i2c_algo_bit i2c_core dca ptp pps_core
scsi_mod [last unloaded: dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.089154] CPU: 9 PID: 10045 Comm:
blkid Tainted: G      D        3.17.2 #2
Nov 14 17:05:40 steinhager kernel: [22999.089155] Hardware name: SGI.COM
C3108-TY11/X8DAH, BIOS 1.1     03/16/2011
Nov 14 17:05:40 steinhager kernel: [22999.089157] task: ffff8801b8e4ce60
ti: ffff8801b44b4000 task.ti: ffff8801b44b4000
Nov 14 17:05:40 steinhager kernel: [22999.089163] RIP:
0010:[<ffffffffa0370417>]  [<ffffffffa0370417>]
dm_cell_release_no_holder+0x2c/0x85 [dm_bio_prison]
Nov 14 17:05:40 steinhager kernel: [22999.089164] RSP:
0018:ffff8801b44b7a00  EFLAGS: 00010086
Nov 14 17:05:40 steinhager kernel: [22999.089165] RAX: 0000000000000086
RBX: ffff8801b7818018 RCX: dead000000200200
Nov 14 17:05:40 steinhager kernel: [22999.089166] RDX: dead000000100100
RSI: 0000000000000001 RDI: ffff8801b7818018
Nov 14 17:05:40 steinhager kernel: [22999.089168] RBP: ffff8801b5a38870
R08: 0000000000000010 R09: 0000000000000001
Nov 14 17:05:40 steinhager kernel: [22999.089169] R10: 0000000000000001
R11: ffff8801b93e2810 R12: ffff880338e5bc60
Nov 14 17:05:40 steinhager kernel: [22999.089170] R13: 0000000000000246
R14: 0000000000000000 R15: ffff8801b213fd80
Nov 14 17:05:40 steinhager kernel: [22999.089172] FS:
 00007ffff7fea780(0000) GS:ffff8801bfca0000(0000) knlGS:0000000000000000
Nov 14 17:05:40 steinhager kernel: [22999.089173] CS:  0010 DS: 0000 ES:
0000 CR0: 0000000080050033
Nov 14 17:05:40 steinhager kernel: [22999.089174] CR2: 00007ffff79586a7
CR3: 00000001b0dba000 CR4: 00000000000007e0
Nov 14 17:05:40 steinhager kernel: [22999.089175] Stack:
Nov 14 17:05:40 steinhager kernel: [22999.089178]  ffff880338e5bc00
ffff880338e5bc5c ffff8801b5a38870 ffffffffa03c1b3f
Nov 14 17:05:40 steinhager kernel: [22999.089179]  ffff880338e5bc00
ffff8801b213fd80 0000000000000001 00000000007feebf
Nov 14 17:05:40 steinhager kernel: [22999.089181]  ffff8801b213fd40
ffffffffa03c3d98 ffff8801b0e01900 ffff8801b5a38870
Nov 14 17:05:40 steinhager kernel: [22999.089182] Call Trace:
Nov 14 17:05:40 steinhager kernel: [22999.089187]  [<ffffffffa03c1b3f>] ?
cell_defer+0x45/0x6f [dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.089191]  [<ffffffffa03c3d98>] ?
cache_map+0x319/0x32b [dm_cache]
Nov 14 17:05:40 steinhager kernel: [22999.089198]  [<ffffffffa00ab0e6>] ?
__map_bio+0x39/0xe3 [dm_mod]
Nov 14 17:05:40 steinhager kernel: [22999.089205]  [<ffffffffa00ab5f8>] ?
__split_and_process_bio+0x306/0x33c [dm_mod]
Nov 14 17:05:40 steinhager kernel: [22999.089211]  [<ffffffffa00aba47>] ?
dm_request+0x15e/0x16f [dm_mod]
Nov 14 17:05:40 steinhager kernel: [22999.089216]  [<ffffffff811b686a>] ?
generic_make_request+0xaa/0xf0
Nov 14 17:05:40 steinhager kernel: [22999.089218]  [<ffffffff811b69a7>] ?
submit_bio+0xf7/0x100
Nov 14 17:05:40 steinhager kernel: [22999.089223]  [<ffffffff8113a911>] ?
_submit_bh+0x1b0/0x1d5
Nov 14 17:05:40 steinhager kernel: [22999.089225]  [<ffffffff8113afb5>] ?
block_read_full_page+0x1b8/0x1d1
Nov 14 17:05:40 steinhager kernel: [22999.089228]  [<ffffffff8113c2a3>] ?
I_BDEV+0x8/0x8
Nov 14 17:05:40 steinhager kernel: [22999.089233]  [<ffffffff810cec69>] ?
__add_to_page_cache_locked+0xf2/0x14d
Nov 14 17:05:40 steinhager kernel: [22999.089236]  [<ffffffff810d909c>] ?
get_page+0x9/0x25
Nov 14 17:05:40 steinhager kernel: [22999.089239]  [<ffffffff810d918d>] ?
__lru_cache_add+0x1a/0x39
Nov 14 17:05:40 steinhager kernel: [22999.089242]  [<ffffffff810d7d74>] ?
__do_page_cache_readahead+0x1a8/0x1e1
Nov 14 17:05:40 steinhager kernel: [22999.089245]  [<ffffffff810d8090>] ?
force_page_cache_readahead+0x67/0x80
Nov 14 17:05:40 steinhager kernel: [22999.089247]  [<ffffffff810ced4a>] ?
pagecache_get_page+0x25/0x13c
Nov 14 17:05:40 steinhager kernel: [22999.089249]  [<ffffffff810d8090>] ?
force_page_cache_readahead+0x67/0x80
Nov 14 17:05:40 steinhager kernel: [22999.089252]  [<ffffffff810cf517>] ?
generic_file_read_iter+0x170/0x4ca
Nov 14 17:05:40 steinhager kernel: [22999.089256]  [<ffffffff811153c7>] ?
new_sync_read+0x62/0x86
Nov 14 17:05:40 steinhager kernel: [22999.089259]  [<ffffffff81115963>] ?
vfs_read+0x93/0xe3
Nov 14 17:05:40 steinhager kernel: [22999.089261]  [<ffffffff8111612d>] ?
SyS_read+0x48/0x73
Nov 14 17:05:40 steinhager kernel: [22999.089266]  [<ffffffff81397dd2>] ?
system_call_fastpath+0x16/0x1b
Nov 14 17:05:40 steinhager kernel: [22999.089284] Code: 54 55 48 89 f5 53
49 89 d4 6b 5e 20 fb 23 5f 0c 48 c1 e3 04 48 03 5f 10 48 89 df e8 72 75 02
e1 48 8b 55 00 48 8b 4d 08 48 85 d2 <48> 89 11 74 04 48 89 4a 08 48 8b 55
30 48 be 00 01 10 00 00 00
Nov 14 17:05:40 steinhager kernel: [22999.089287] RIP  [<ffffffffa0370417>]
dm_cell_release_no_holder+0x2c/0x85 [dm_bio_prison]
Nov 14 17:05:40 steinhager kernel: [22999.089291]  RSP <ffff8801b44b7a00>
Nov 14 17:05:40 steinhager kernel: [22999.089293] ---[ end trace
91dc97f60fa89843 ]---
Nov 14 17:06:40 steinhager kernel: [22999.094103] BUG: unable to handle
kernel paging request at ffffffffffffffd8
Nov 14 17:06:40 steinhager kernel: [22999.094291] IP: [<ffffffff81052083>]
kthread_data+0x7/0xc
Nov 14 17:06:40 steinhager kernel: [22999.094428] PGD 1612067 PUD 1614067
PMD 0
Nov 14 17:06:40 steinhager kernel: [22999.094653] Oops: 0000 [#3] SMP
Nov 14 17:06:40 steinhager kernel: [22999.094828] Modules linked in:
dm_cache_mq dm_cache dm_persistent_data dm_bio_prison dm_bufio libcrc32c
raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx
raid6_pq raid0 raid1 md_mod coretemp kvm_intel kvm snd_pcm iTCO_wdt
snd_timer snd i7core_edac ioatdma psmouse edac_core iTCO_vendor_support
ipmi_si soundcore lpc_ich mfd_core i2c_i801 evdev pcspkr serio_raw
microcode ipmi_msghandler ehci_pci button acpi_cpufreq processor
thermal_sys ext4 crc16 jbd2 mbcache dm_mod sr_mod cdrom sg sd_mod
crc_t10dif crct10dif_common crc32c_intel uhci_hcd firewire_ohci ehci_hcd
ata_generic ahci firewire_core libahci pata_jmicron crc_itu_t usbcore
libata usb_common megaraid_sas igb i2c_algo_bit i2c_core dca ptp pps_core
scsi_mod [last unloaded: dm_cache]
Nov 14 17:06:40 steinhager kernel: [22999.099000] CPU: 4 PID: 6 Comm:
kworker/u48:0 Tainted: G      D        3.17.2 #2
Nov 14 17:06:40 steinhager kernel: [22999.099119] Hardware name: SGI.COM
C3108-TY11/X8DAH, BIOS 1.1     03/16/2011
Nov 14 17:06:40 steinhager kernel: [22999.099220] task: ffff8801b90ec050
ti: ffff8801b90fc000 task.ti: ffff8801b90fc000
Nov 14 17:06:40 steinhager kernel: [22999.099339] RIP:
0010:[<ffffffff81052083>]  [<ffffffff81052083>] kthread_data+0x7/0xc
Nov 14 17:06:40 steinhager kernel: [22999.099508] RSP:
0018:ffff8801b90ffaa0  EFLAGS: 00010002
Nov 14 17:06:40 steinhager kernel: [22999.099596] RAX: 0000000000000000
RBX: ffff88033fc13180 RCX: 0000000000000004
Nov 14 17:06:40 steinhager kernel: [22999.099690] RDX: 0000000000000000
RSI: 0000000000000004 RDI: ffff8801b90ec050
Nov 14 17:06:40 steinhager kernel: [22999.099785] RBP: 0000000000000004
R08: ffff88033fc131f0 R09: ffffffff817ceac0
Nov 14 17:06:40 steinhager kernel: [22999.099879] R10: 000000000000b9cd
R11: ffff8801b90f002f R12: 0000000000000004
Nov 14 17:06:40 steinhager kernel: [22999.099973] R13: ffff8801b90ec4b0
R14: ffff8801b90ffb58 R15: ffff8801b90ec3a8
Nov 14 17:06:40 steinhager kernel: [22999.100068] FS:
 0000000000000000(0000) GS:ffff88033fc00000(0000) knlGS:0000000000000000
Nov 14 17:06:40 steinhager kernel: [22999.100189] CS:  0010 DS: 0000 ES:
0000 CR0: 000000008005003b
Nov 14 17:06:40 steinhager kernel: [22999.100279] CR2: 0000000000000028
CR3: 0000000001611000 CR4: 00000000000007e0
Nov 14 17:06:40 steinhager kernel: [22999.100373] Stack:
Nov 14 17:06:40 steinhager kernel: [22999.100451]  ffffffff8104e86c
ffff88033fc13180 ffff8801b90ec050 ffffffff81394f3f
Nov 14 17:06:40 steinhager kernel: [22999.100757]  0000000000013180
ffff8801b90ec050 ffff8801b90fffd8 0000000000000000
Nov 14 17:06:40 steinhager kernel: [22999.101064]  ffff8801b90ec050
ffff8801b90ec6d0 0000000000000001 ffff8801b90ec040
Nov 14 17:06:40 steinhager kernel: [22999.101370] Call Trace:
Nov 14 17:06:40 steinhager kernel: [22999.101451]  [<ffffffff8104e86c>] ?
wq_worker_sleeping+0x9/0x7f
Nov 14 17:06:40 steinhager kernel: [22999.101543]  [<ffffffff81394f3f>] ?
__schedule+0x137/0x4d9
Nov 14 17:06:40 steinhager kernel: [22999.101636]  [<ffffffff8103e220>] ?
do_exit+0x929/0x966
Nov 14 17:06:40 steinhager kernel: [22999.101728]  [<ffffffff8139360e>] ?
printk+0x4a/0x52
Nov 14 17:06:40 steinhager kernel: [22999.101817]  [<ffffffff810050bd>] ?
oops_end+0x9c/0xa1
Nov 14 17:06:40 steinhager kernel: [22999.101908]  [<ffffffff810314c5>] ?
no_context+0x2c8/0x325
Nov 14 17:06:40 steinhager kernel: [22999.101998]  [<ffffffff81031ab2>] ?
__do_page_fault+0x1d7/0x397
Nov 14 17:06:40 steinhager kernel: [22999.102093]  [<ffffffff810582b1>] ?
set_task_cpu+0x92/0xeb
Nov 14 17:06:40 steinhager kernel: [22999.102185]  [<ffffffff810d556d>] ?
__alloc_pages_nodemask+0x16c/0x7c5
Nov 14 17:06:40 steinhager kernel: [22999.102280]  [<ffffffff8110960a>] ?
kmem_getpages+0xbc/0xd0
Nov 14 17:06:40 steinhager kernel: [22999.102370]  [<ffffffff8110a81a>] ?
cache_grow+0x163/0x1b5
Nov 14 17:06:40 steinhager kernel: [22999.102460]  [<ffffffff8110a48a>] ?
____cache_alloc+0x127/0x253
Nov 14 17:06:40 steinhager kernel: [22999.102554]  [<ffffffff813997e2>] ?
page_fault+0x22/0x30
Nov 14 17:06:40 steinhager kernel: [22999.102644]  [<ffffffffa03c102e>] ?
bio_list_pop+0x8/0x23 [dm_cache]
Nov 14 17:06:40 steinhager kernel: [22999.102738]  [<ffffffffa03c4095>] ?
do_worker+0x29f/0x649 [dm_cache]
Nov 14 17:06:40 steinhager kernel: [22999.102830]  [<ffffffff810016b0>] ?
__switch_to+0x22d/0x45a
Nov 14 17:06:40 steinhager kernel: [22999.102921]  [<ffffffff8104dfb5>] ?
process_one_work+0x158/0x27b
Nov 14 17:06:40 steinhager kernel: [22999.103012]  [<ffffffff8104e765>] ?
worker_thread+0x1ea/0x294
Nov 14 17:06:40 steinhager kernel: [22999.103103]  [<ffffffff8104e57b>] ?
rescuer_thread+0x217/0x217
Nov 14 17:06:40 steinhager kernel: [22999.103194]  [<ffffffff81051db6>] ?
kthread+0xa7/0xaf
Nov 14 17:06:40 steinhager kernel: [22999.103282]  [<ffffffff81051d0f>] ?
__kthread_parkme+0x5b/0x5b
Nov 14 17:06:40 steinhager kernel: [22999.103373]  [<ffffffff81397d2c>] ?
ret_from_fork+0x7c/0xb0
Nov 14 17:06:40 steinhager kernel: [22999.103464]  [<ffffffff81051d0f>] ?
__kthread_parkme+0x5b/0x5b
Nov 14 17:06:40 steinhager kernel: [22999.103553] Code: 5d 41 5c 41 5d 41
5e c3 65 48 8b 04 25 c0 b9 00 00 48 8b 80 08 04 00 00 48 8b 40 c8 48 c1 e8
02 83 e0 01 c3 48 8b 87 08 04 00 00 <48> 8b 40 d8 c3 50 48 8b b7 08 04 00
00 ba 08 00 00 00 48 89 e7
Nov 14 17:06:40 steinhager kernel: [22999.112758] RIP  [<ffffffff81052083>]
kthread_data+0x7/0xc
Nov 14 17:06:40 steinhager kernel: [22999.112896]  RSP <ffff8801b90ffaa0>
Nov 14 17:06:40 steinhager kernel: [22999.112978] CR2: ffffffffffffffd8
Nov 14 17:06:40 steinhager kernel: [22999.113060] ---[ end trace
91dc97f60fa89844 ]---
Nov 14 17:06:40 steinhager kernel: [22999.113146] Fixing recursive fault
but reboot is needed!
Nov 14 17:06:40 steinhager kernel: [23029.548874] ------------[ cut here
]------------
Nov 14 17:06:40 steinhager kernel: [23029.548951] WARNING: CPU: 0 PID: 0 at
kernel/watchdog.c:267 watchdog_overflow_callback+0x92/0x9d()
Nov 14 17:06:40 steinhager kernel: [23029.549041] Watchdog detected hard
LOCKUP on cpu 0
Nov 14 17:06:40 steinhager kernel: [23029.549094] Modules linked in:
dm_cache_mq dm_cache dm_persistent_data dm_bio_prison dm_bufio libcrc32c
raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx
raid6_pq raid0 raid1 md_mod coretemp kvm_intel kvm snd_pcm iTCO_wdt
snd_timer snd i7core_edac ioatdma psmouse edac_core iTCO_vendor_support
ipmi_si soundcore lpc_ich mfd_core i2c_i801 evdev pcspkr serio_raw
microcode ipmi_msghandler ehci_pci button acpi_cpufreq processor
thermal_sys ext4 crc16 jbd2 mbcache dm_mod sr_mod cdrom sg sd_mod
crc_t10dif crct10dif_common crc32c_intel uhci_hcd firewire_ohci ehci_hcd
ata_generic ahci firewire_core libahci pata_jmicron crc_itu_t usbcore
libata usb_common megaraid_sas igb i2c_algo_bit i2c_core dca ptp pps_core
scsi_mod [last unloaded: dm_cache]
Nov 14 17:06:40 steinhager kernel: [23029.552866] CPU: 0 PID: 0 Comm:
swapper/0 Tainted: G      D        3.17.2 #2
Nov 14 17:06:40 steinhager kernel: [23029.552938] Hardware name: SGI.COM
C3108-TY11/X8DAH, BIOS 1.1     03/16/2011
Nov 14 17:06:40 steinhager kernel: [23029.553010]  0000000000000006
ffffffff813940f8 ffff8801bfc06ca0 ffffffff8103cb84
Nov 14 17:06:40 steinhager kernel: [23029.553270]  ffffffff810aa484
ffff8801b911e400 ffff8801bfc06cf8 ffff8801bfc06d90
Nov 14 17:06:40 steinhager kernel: [23029.553530]  ffff8801bfc06ef8
ffffffff8103cbdc ffffffff8150ddf9 0000000000000020
Nov 14 17:06:40 steinhager kernel: [23029.553790] Call Trace:
Nov 14 17:06:40 steinhager kernel: [23029.553853]  <NMI>
 [<ffffffff813940f8>] ? dump_stack+0x41/0x51
Nov 14 17:06:40 steinhager kernel: [23029.554016]  [<ffffffff8103cb84>] ?
warn_slowpath_common+0x74/0x89
Nov 14 17:06:40Write failed: Connection reset by peer

[-- Attachment #1.2: Type: text/html, Size: 22506 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: dmcache RAID1 bug?

[Mike Snitzer]

On Mon, Nov 17 2014 at  9:24am -0500,
Leonardo Santos <heiligerstein@gmail.com> wrote:

> I'm working in tests for my msc thesis envolving dm_cache module. I'm
> having problems with the following scenario:
> 
> Slowstorage: RAID1 (mdadm) with 4 HDDs;
> - /dev/md/raid1_4ssds

You mean /dev/md/raid1_4hdds ?

> -- /dev/sda
> -- /dev/sdb
> -- /dev/sdc
> -- /dev/sdd
> 
> Faststorage: RAID1 (mdadm) with 4 SSDs
> - /dev/md/raid1_4hdds

And /dev/md/raid1_4ssds here?

> -- /dev/sde
> -- /dev/sdf
> -- /dev/sdg
> -- /dev/sdh
>
> 
> Cachestorage: dm_cache envolving both devices
> - /dev/mapper/dmcache
> -- /dev/md/raid1_4ssds
> -- /dev/md/raid1_4hdds
> 
> Other informations (strange facts):
> In RAID0 it's working very well.
> In a virtual machine (vbox) it's working as well (in this case disks have
> 2GB only for big tests automatization, in production are 160GB SSDs and 2TB
> HDDs);
> 
> Have you seen about this error? Syslog is bellow.

Never seen this before... have you taken care to zero the dm-cache
metadata's superblock (first 512B of the cache metadata device) each
time you've reconfigured the cache device?

Have you tried using the latest lvm2 to create the dm-cache device?

Re: dmcache RAID1 bug?

[Leonardo Santos]

[-- Attachment #1.1: Type: text/plain, Size: 2370 bytes --]

On Mon, Nov 17, 2014 at 12:46 PM, Mike Snitzer <snitzer@redhat.com> wrote:

> On Mon, Nov 17 2014 at  9:24am -0500,
> Leonardo Santos <heiligerstein@gmail.com> wrote:
>
> > I'm working in tests for my msc thesis envolving dm_cache module. I'm
> > having problems with the following scenario:
> >
> > Slowstorage: RAID1 (mdadm) with 4 HDDs;
> > - /dev/md/raid1_4ssds
>
> You mean /dev/md/raid1_4hdds ?
>

A symlink to raid1 created using 4 ssds.

mdadm --create --verbose /dev/md/raid0_4ssds --raid-devices=4 --force
--level=1 /dev/sdd /dev/sdc /dev/sdb /dev/sda


>
> > -- /dev/sda
> > -- /dev/sdb
> > -- /dev/sdc
> > -- /dev/sdd
> >
> > Faststorage: RAID1 (mdadm) with 4 SSDs
> > - /dev/md/raid1_4hdds
>
> And /dev/md/raid1_4ssds here?
>

mdadm --create --verbose /dev/md/raid0_4hdds --raid-devices=4 --force
--level=1  /dev/sdh /dev/sdg /dev/sdf /dev/sde


>
> > -- /dev/sde
> > -- /dev/sdf
> > -- /dev/sdg
> > -- /dev/sdh
> >
> >
> > Cachestorage: dm_cache envolving both devices
> > - /dev/mapper/dmcache
> > -- /dev/md/raid1_4ssds
> > -- /dev/md/raid1_4hdds
> >
>

Commands:
vgcreate cache /dev/md/raid0_4ssds -y
lvcreate cache -n metadata -l 5%FREE
lvcreate cache -n block -l 100%FREE
dd if=/dev/zero of=/dev/cache/metadata bs=1M count=100
# 16773120 = blockdev --getsize /dev/md/raid0_4hdds
dmsetup create dmcache --table '0 16773120 cache /dev/cache/metadata
/dev/cache/block /dev/md/raid0_4hdds 512 1 writeback default 0'


> > Other informations (strange facts):
> > In RAID0 it's working very well.
> > In a virtual machine (vbox) it's working as well (in this case disks have
> > 2GB only for big tests automatization, in production are 160GB SSDs and
> 2TB
> > HDDs);
> >
> > Have you seen about this error? Syslog is bellow.
>
> Never seen this before... have you taken care to zero the dm-cache
> metadata's superblock (first 512B of the cache metadata device) each
> time you've reconfigured the cache device?
>
> Have you tried using the latest lvm2 to create the dm-cache device?
>

I've used LVM2 from distribution (debian) and a latest kernel version.

LVM2 latest today is 2.02.112 (I'll try with latest LVM2 version and post
results).

# lvm version
  LVM version:     2.02.95(2) (2012-03-06)
  Library version: 1.02.74 (2012-03-06)
  Driver version:  4.27.0

# uname -a
Linux steinhager 3.17.2 #2 SMP Fri Nov 7 12:49:16 BRST 2014 x86_64 GNU/Linux

[-- Attachment #1.2: Type: text/html, Size: 4216 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: dmcache RAID1 bug?

[Leonardo Santos]

[-- Attachment #1.1: Type: text/plain, Size: 2899 bytes --]

I tested updating my xbox to same production kernel (3.17.2) and the
problem appears now.

The old kernel (ok) is 3.13.0-37.

About updating lvm, I think it should not be, because this time I did not
use them and did creating only through the dmsetup command.

I will continue testing with other kernels.

Can anyone help me?


On Mon, Nov 17, 2014 at 4:14 PM, Leonardo Santos <heiligerstein@gmail.com>
wrote:

> On Mon, Nov 17, 2014 at 12:46 PM, Mike Snitzer <snitzer@redhat.com> wrote:
>
>> On Mon, Nov 17 2014 at  9:24am -0500,
>> Leonardo Santos <heiligerstein@gmail.com> wrote:
>>
>> > I'm working in tests for my msc thesis envolving dm_cache module. I'm
>> > having problems with the following scenario:
>> >
>> > Slowstorage: RAID1 (mdadm) with 4 HDDs;
>> > - /dev/md/raid1_4ssds
>>
>> You mean /dev/md/raid1_4hdds ?
>>
>
> A symlink to raid1 created using 4 ssds.
>
> mdadm --create --verbose /dev/md/raid0_4ssds --raid-devices=4 --force
> --level=1 /dev/sdd /dev/sdc /dev/sdb /dev/sda
>
>
>>
>> > -- /dev/sda
>> > -- /dev/sdb
>> > -- /dev/sdc
>> > -- /dev/sdd
>> >
>> > Faststorage: RAID1 (mdadm) with 4 SSDs
>> > - /dev/md/raid1_4hdds
>>
>> And /dev/md/raid1_4ssds here?
>>
>
> mdadm --create --verbose /dev/md/raid0_4hdds --raid-devices=4 --force
> --level=1  /dev/sdh /dev/sdg /dev/sdf /dev/sde
>
>
>>
>> > -- /dev/sde
>> > -- /dev/sdf
>> > -- /dev/sdg
>> > -- /dev/sdh
>> >
>> >
>> > Cachestorage: dm_cache envolving both devices
>> > - /dev/mapper/dmcache
>> > -- /dev/md/raid1_4ssds
>> > -- /dev/md/raid1_4hdds
>> >
>>
>
> Commands:
> vgcreate cache /dev/md/raid0_4ssds -y
> lvcreate cache -n metadata -l 5%FREE
> lvcreate cache -n block -l 100%FREE
> dd if=/dev/zero of=/dev/cache/metadata bs=1M count=100
> # 16773120 = blockdev --getsize /dev/md/raid0_4hdds
> dmsetup create dmcache --table '0 16773120 cache /dev/cache/metadata
> /dev/cache/block /dev/md/raid0_4hdds 512 1 writeback default 0'
>
>
>> > Other informations (strange facts):
>> > In RAID0 it's working very well.
>> > In a virtual machine (vbox) it's working as well (in this case disks
>> have
>> > 2GB only for big tests automatization, in production are 160GB SSDs and
>> 2TB
>> > HDDs);
>> >
>> > Have you seen about this error? Syslog is bellow.
>>
>> Never seen this before... have you taken care to zero the dm-cache
>> metadata's superblock (first 512B of the cache metadata device) each
>> time you've reconfigured the cache device?
>>
>> Have you tried using the latest lvm2 to create the dm-cache device?
>>
>
> I've used LVM2 from distribution (debian) and a latest kernel version.
>
> LVM2 latest today is 2.02.112 (I'll try with latest LVM2 version and post
> results).
>
> # lvm version
>   LVM version:     2.02.95(2) (2012-03-06)
>   Library version: 1.02.74 (2012-03-06)
>   Driver version:  4.27.0
>
> # uname -a
> Linux steinhager 3.17.2 #2 SMP Fri Nov 7 12:49:16 BRST 2014 x86_64
> GNU/Linux
>

[-- Attachment #1.2: Type: text/html, Size: 5125 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: dmcache RAID1 bug?

[Leonardo Santos]

[-- Attachment #1.1: Type: text/plain, Size: 3537 bytes --]

After run regression tests using 'git bisect', I identify that the error
was created after commit 8c081b52c6833a30a69ea3bdcef316eccc740c87

To reproduce this error just:
- create a raid1 HDDs for origin device;
- create a cache device with SSDs (could or not be raid)
- create a metadata device with SSDs (could or not be raid)
- create a cache device using prior devices
- kernel crashes.

I attached the bitseclog and diff file!

On Tue, Nov 18, 2014 at 4:18 PM, Leonardo Santos <heiligerstein@gmail.com>
wrote:

> I tested updating my xbox to same production kernel (3.17.2) and the
> problem appears now.
>
> The old kernel (ok) is 3.13.0-37.
>
> About updating lvm, I think it should not be, because this time I did not
> use them and did creating only through the dmsetup command.
>
> I will continue testing with other kernels.
>
> Can anyone help me?
>
>
> On Mon, Nov 17, 2014 at 4:14 PM, Leonardo Santos <heiligerstein@gmail.com>
> wrote:
>
>> On Mon, Nov 17, 2014 at 12:46 PM, Mike Snitzer <snitzer@redhat.com>
>> wrote:
>>
>>> On Mon, Nov 17 2014 at  9:24am -0500,
>>> Leonardo Santos <heiligerstein@gmail.com> wrote:
>>>
>>> > I'm working in tests for my msc thesis envolving dm_cache module. I'm
>>> > having problems with the following scenario:
>>> >
>>> > Slowstorage: RAID1 (mdadm) with 4 HDDs;
>>> > - /dev/md/raid1_4ssds
>>>
>>> You mean /dev/md/raid1_4hdds ?
>>>
>>
>> A symlink to raid1 created using 4 ssds.
>>
>> mdadm --create --verbose /dev/md/raid0_4ssds --raid-devices=4 --force
>> --level=1 /dev/sdd /dev/sdc /dev/sdb /dev/sda
>>
>>
>>>
>>> > -- /dev/sda
>>> > -- /dev/sdb
>>> > -- /dev/sdc
>>> > -- /dev/sdd
>>> >
>>> > Faststorage: RAID1 (mdadm) with 4 SSDs
>>> > - /dev/md/raid1_4hdds
>>>
>>> And /dev/md/raid1_4ssds here?
>>>
>>
>> mdadm --create --verbose /dev/md/raid0_4hdds --raid-devices=4 --force
>> --level=1  /dev/sdh /dev/sdg /dev/sdf /dev/sde
>>
>>
>>>
>>> > -- /dev/sde
>>> > -- /dev/sdf
>>> > -- /dev/sdg
>>> > -- /dev/sdh
>>> >
>>> >
>>> > Cachestorage: dm_cache envolving both devices
>>> > - /dev/mapper/dmcache
>>> > -- /dev/md/raid1_4ssds
>>> > -- /dev/md/raid1_4hdds
>>> >
>>>
>>
>> Commands:
>> vgcreate cache /dev/md/raid0_4ssds -y
>> lvcreate cache -n metadata -l 5%FREE
>> lvcreate cache -n block -l 100%FREE
>> dd if=/dev/zero of=/dev/cache/metadata bs=1M count=100
>> # 16773120 = blockdev --getsize /dev/md/raid0_4hdds
>> dmsetup create dmcache --table '0 16773120 cache /dev/cache/metadata
>> /dev/cache/block /dev/md/raid0_4hdds 512 1 writeback default 0'
>>
>>
>>> > Other informations (strange facts):
>>> > In RAID0 it's working very well.
>>> > In a virtual machine (vbox) it's working as well (in this case disks
>>> have
>>> > 2GB only for big tests automatization, in production are 160GB SSDs
>>> and 2TB
>>> > HDDs);
>>> >
>>> > Have you seen about this error? Syslog is bellow.
>>>
>>> Never seen this before... have you taken care to zero the dm-cache
>>> metadata's superblock (first 512B of the cache metadata device) each
>>> time you've reconfigured the cache device?
>>>
>>> Have you tried using the latest lvm2 to create the dm-cache device?
>>>
>>
>> I've used LVM2 from distribution (debian) and a latest kernel version.
>>
>> LVM2 latest today is 2.02.112 (I'll try with latest LVM2 version and post
>> results).
>>
>> # lvm version
>>   LVM version:     2.02.95(2) (2012-03-06)
>>   Library version: 1.02.74 (2012-03-06)
>>   Driver version:  4.27.0
>>
>> # uname -a
>> Linux steinhager 3.17.2 #2 SMP Fri Nov 7 12:49:16 BRST 2014 x86_64
>> GNU/Linux
>>
>
>

[-- Attachment #1.2: Type: text/html, Size: 6071 bytes --]

[-- Attachment #2: dmcache.diff --]
[-- Type: text/plain, Size: 9483 bytes --]

diff --git a/drivers/md/dm-cache-target.c b/drivers/md/dm-cache-target.c
index 2c63326..2a156af 100644
--- a/drivers/md/dm-cache-target.c
+++ b/drivers/md/dm-cache-target.c
@@ -718,6 +718,22 @@ static int bio_triggers_commit(struct cache *cache, struct bio *bio)
 	return bio->bi_rw & (REQ_FLUSH | REQ_FUA);
 }
 
+/*
+ * You must increment the deferred set whilst the prison cell is held.  To
+ * encourage this, we ask for 'cell' to be passed in.
+ */
+static void inc_ds(struct cache *cache, struct bio *bio,
+		   struct dm_bio_prison_cell *cell)
+{
+	size_t pb_data_size = get_per_bio_data_size(cache);
+	struct per_bio_data *pb = get_per_bio_data(bio, pb_data_size);
+
+	BUG_ON(!cell);
+	BUG_ON(pb->all_io_entry);
+
+	pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
+}
+
 static void issue(struct cache *cache, struct bio *bio)
 {
 	unsigned long flags;
@@ -737,6 +753,12 @@ static void issue(struct cache *cache, struct bio *bio)
 	spin_unlock_irqrestore(&cache->lock, flags);
 }
 
+static void inc_and_issue(struct cache *cache, struct bio *bio, struct dm_bio_prison_cell *cell)
+{
+	inc_ds(cache, bio, cell);
+	issue(cache, bio);
+}
+
 static void defer_writethrough_bio(struct cache *cache, struct bio *bio)
 {
 	unsigned long flags;
@@ -1015,6 +1037,11 @@ static void issue_overwrite(struct dm_cache_migration *mg, struct bio *bio)
 
 	dm_hook_bio(&pb->hook_info, bio, overwrite_endio, mg);
 	remap_to_cache_dirty(mg->cache, bio, mg->new_oblock, mg->cblock);
+
+	/*
+	 * No need to inc_ds() here, since the cell will be held for the
+	 * duration of the io.
+	 */
 	generic_make_request(bio);
 }
 
@@ -1115,8 +1142,7 @@ static void check_for_quiesced_migrations(struct cache *cache,
 		return;
 
 	INIT_LIST_HEAD(&work);
-	if (pb->all_io_entry)
-		dm_deferred_entry_dec(pb->all_io_entry, &work);
+	dm_deferred_entry_dec(pb->all_io_entry, &work);
 
 	if (!list_empty(&work))
 		queue_quiesced_migrations(cache, &work);
@@ -1252,6 +1278,11 @@ static void process_flush_bio(struct cache *cache, struct bio *bio)
 	else
 		remap_to_cache(cache, bio, 0);
 
+	/*
+	 * REQ_FLUSH is not directed at any particular block so we don't
+	 * need to inc_ds().  REQ_FUA's are split into a write + REQ_FLUSH
+	 * by dm-core.
+	 */
 	issue(cache, bio);
 }
 
@@ -1301,15 +1332,6 @@ static void inc_miss_counter(struct cache *cache, struct bio *bio)
 		   &cache->stats.read_miss : &cache->stats.write_miss);
 }
 
-static void issue_cache_bio(struct cache *cache, struct bio *bio,
-			    struct per_bio_data *pb,
-			    dm_oblock_t oblock, dm_cblock_t cblock)
-{
-	pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
-	remap_to_cache_dirty(cache, bio, oblock, cblock);
-	issue(cache, bio);
-}
-
 static void process_bio(struct cache *cache, struct prealloc *structs,
 			struct bio *bio)
 {
@@ -1318,8 +1340,6 @@ static void process_bio(struct cache *cache, struct prealloc *structs,
 	dm_oblock_t block = get_bio_block(cache, bio);
 	struct dm_bio_prison_cell *cell_prealloc, *old_ocell, *new_ocell;
 	struct policy_result lookup_result;
-	size_t pb_data_size = get_per_bio_data_size(cache);
-	struct per_bio_data *pb = get_per_bio_data(bio, pb_data_size);
 	bool discarded_block = is_discarded_oblock(cache, block);
 	bool passthrough = passthrough_mode(&cache->features);
 	bool can_migrate = !passthrough && (discarded_block || spare_migration_bandwidth(cache));
@@ -1359,9 +1379,8 @@ static void process_bio(struct cache *cache, struct prealloc *structs,
 
 			} else {
 				/* FIXME: factor out issue_origin() */
-				pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
 				remap_to_origin_clear_discard(cache, bio, block);
-				issue(cache, bio);
+				inc_and_issue(cache, bio, new_ocell);
 			}
 		} else {
 			inc_hit_counter(cache, bio);
@@ -1369,20 +1388,21 @@ static void process_bio(struct cache *cache, struct prealloc *structs,
 			if (bio_data_dir(bio) == WRITE &&
 			    writethrough_mode(&cache->features) &&
 			    !is_dirty(cache, lookup_result.cblock)) {
-				pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
 				remap_to_origin_then_cache(cache, bio, block, lookup_result.cblock);
-				issue(cache, bio);
-			} else
-				issue_cache_bio(cache, bio, pb, block, lookup_result.cblock);
+				inc_and_issue(cache, bio, new_ocell);
+
+			} else  {
+				remap_to_cache_dirty(cache, bio, block, lookup_result.cblock);
+				inc_and_issue(cache, bio, new_ocell);
+			}
 		}
 
 		break;
 
 	case POLICY_MISS:
 		inc_miss_counter(cache, bio);
-		pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
 		remap_to_origin_clear_discard(cache, bio, block);
-		issue(cache, bio);
+		inc_and_issue(cache, bio, new_ocell);
 		break;
 
 	case POLICY_NEW:
@@ -1501,6 +1521,9 @@ static void process_deferred_flush_bios(struct cache *cache, bool submit_bios)
 	bio_list_init(&cache->deferred_flush_bios);
 	spin_unlock_irqrestore(&cache->lock, flags);
 
+	/*
+	 * These bios have already been through inc_ds()
+	 */
 	while ((bio = bio_list_pop(&bios)))
 		submit_bios ? generic_make_request(bio) : bio_io_error(bio);
 }
@@ -1518,6 +1541,9 @@ static void process_deferred_writethrough_bios(struct cache *cache)
 	bio_list_init(&cache->deferred_writethrough_bios);
 	spin_unlock_irqrestore(&cache->lock, flags);
 
+	/*
+	 * These bios have already been through inc_ds()
+	 */
 	while ((bio = bio_list_pop(&bios)))
 		generic_make_request(bio);
 }
@@ -2406,16 +2432,13 @@ out:
 	return r;
 }
 
-static int cache_map(struct dm_target *ti, struct bio *bio)
+static int __cache_map(struct cache *cache, struct bio *bio, struct dm_bio_prison_cell **cell)
 {
-	struct cache *cache = ti->private;
-
 	int r;
 	dm_oblock_t block = get_bio_block(cache, bio);
 	size_t pb_data_size = get_per_bio_data_size(cache);
 	bool can_migrate = false;
 	bool discarded_block;
-	struct dm_bio_prison_cell *cell;
 	struct policy_result lookup_result;
 	struct per_bio_data *pb = init_per_bio_data(bio, pb_data_size);
 
@@ -2437,15 +2460,15 @@ static int cache_map(struct dm_target *ti, struct bio *bio)
 	/*
 	 * Check to see if that block is currently migrating.
 	 */
-	cell = alloc_prison_cell(cache);
-	if (!cell) {
+	*cell = alloc_prison_cell(cache);
+	if (!*cell) {
 		defer_bio(cache, bio);
 		return DM_MAPIO_SUBMITTED;
 	}
 
-	r = bio_detain(cache, block, bio, cell,
+	r = bio_detain(cache, block, bio, *cell,
 		       (cell_free_fn) free_prison_cell,
-		       cache, &cell);
+		       cache, cell);
 	if (r) {
 		if (r < 0)
 			defer_bio(cache, bio);
@@ -2458,11 +2481,12 @@ static int cache_map(struct dm_target *ti, struct bio *bio)
 	r = policy_map(cache->policy, block, false, can_migrate, discarded_block,
 		       bio, &lookup_result);
 	if (r == -EWOULDBLOCK) {
-		cell_defer(cache, cell, true);
+		cell_defer(cache, *cell, true);
 		return DM_MAPIO_SUBMITTED;
 
 	} else if (r) {
 		DMERR_LIMIT("Unexpected return from cache replacement policy: %d", r);
+		cell_defer(cache, *cell, false);
 		bio_io_error(bio);
 		return DM_MAPIO_SUBMITTED;
 	}
@@ -2476,52 +2500,44 @@ static int cache_map(struct dm_target *ti, struct bio *bio)
 				 * We need to invalidate this block, so
 				 * defer for the worker thread.
 				 */
-				cell_defer(cache, cell, true);
+				cell_defer(cache, *cell, true);
 				r = DM_MAPIO_SUBMITTED;
 
 			} else {
-				pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
 				inc_miss_counter(cache, bio);
 				remap_to_origin_clear_discard(cache, bio, block);
-
-				cell_defer(cache, cell, false);
 			}
 
 		} else {
 			inc_hit_counter(cache, bio);
-			pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
-
 			if (bio_data_dir(bio) == WRITE && writethrough_mode(&cache->features) &&
 			    !is_dirty(cache, lookup_result.cblock))
 				remap_to_origin_then_cache(cache, bio, block, lookup_result.cblock);
 			else
 				remap_to_cache_dirty(cache, bio, block, lookup_result.cblock);
-
-			cell_defer(cache, cell, false);
 		}
 		break;
 
 	case POLICY_MISS:
 		inc_miss_counter(cache, bio);
-		pb->all_io_entry = dm_deferred_entry_inc(cache->all_io_ds);
-
 		if (pb->req_nr != 0) {
 			/*
 			 * This is a duplicate writethrough io that is no
 			 * longer needed because the block has been demoted.
 			 */
 			bio_endio(bio, 0);
-			cell_defer(cache, cell, false);
-			return DM_MAPIO_SUBMITTED;
-		} else {
+			cell_defer(cache, *cell, false);
+			r = DM_MAPIO_SUBMITTED;
+
+		} else
 			remap_to_origin_clear_discard(cache, bio, block);
-			cell_defer(cache, cell, false);
-		}
+
 		break;
 
 	default:
 		DMERR_LIMIT("%s: erroring bio: unknown policy op: %u", __func__,
 			    (unsigned) lookup_result.op);
+		cell_defer(cache, *cell, false);
 		bio_io_error(bio);
 		r = DM_MAPIO_SUBMITTED;
 	}
@@ -2529,6 +2545,21 @@ static int cache_map(struct dm_target *ti, struct bio *bio)
 	return r;
 }
 
+static int cache_map(struct dm_target *ti, struct bio *bio)
+{
+	int r;
+	struct dm_bio_prison_cell *cell;
+	struct cache *cache = ti->private;
+
+	r = __cache_map(cache, bio, &cell);
+	if (r == DM_MAPIO_REMAPPED) {
+		inc_ds(cache, bio, cell);
+		cell_defer(cache, cell, false);
+	}
+
+	return r;
+}
+
 static int cache_end_io(struct dm_target *ti, struct bio *bio, int error)
 {
 	struct cache *cache = ti->private;
@@ -3072,7 +3103,7 @@ static void cache_io_hints(struct dm_target *ti, struct queue_limits *limits)
 
 static struct target_type cache_target = {
 	.name = "cache",
-	.version = {1, 4, 0},
+	.version = {1, 5, 0},
 	.module = THIS_MODULE,
 	.ctr = cache_ctr,
 	.dtr = cache_dtr,

[-- Attachment #3: bisectlog --]
[-- Type: application/octet-stream, Size: 3423 bytes --]

git bisect start
# bad: [fc14f9c1272f62c3e8d01300f52467c0d9af50f9] Linux 3.18-rc5
git bisect bad fc14f9c1272f62c3e8d01300f52467c0d9af50f9
# good: [d8ec26d7f8287f5788a494f56e8814210f0e64be] Linux 3.13
git bisect good d8ec26d7f8287f5788a494f56e8814210f0e64be
# good: [07ecf16297bbec8d94012f2dd9d615f98093fbbe] Linux 3.13.1
git bisect good 07ecf16297bbec8d94012f2dd9d615f98093fbbe
# good: [d8ec26d7f8287f5788a494f56e8814210f0e64be] Linux 3.13
git bisect good d8ec26d7f8287f5788a494f56e8814210f0e64be
# good: [b77279bc2e81545b20824da701b349272a78e4e7] Merge tag 'sound-3.16-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound into next
git bisect good b77279bc2e81545b20824da701b349272a78e4e7
# good: [a7d7a143d0b4cb1914705884ca5c25e322dba693] Merge branch 'drm-next' of git://people.freedesktop.org/~airlied/linux
git bisect good a7d7a143d0b4cb1914705884ca5c25e322dba693
# bad: [eb785bef684f2b7d03b530efc8e6f199e9777e2f] Merge tag 'dt-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/arm/arm-soc
git bisect bad eb785bef684f2b7d03b530efc8e6f199e9777e2f
# bad: [b22699d6734d66a68816a95f2628b27840da9dad] staging: comedi: adl_pci9118: remove 'ao_maxdata' boardinfo
git bisect bad b22699d6734d66a68816a95f2628b27840da9dad
# good: [dc1cc85133120e49c223f36aa77d398b8abac727] Merge tag 'xfs-for-linus-3.17-rc1' of git://oss.sgi.com/xfs/xfs
git bisect good dc1cc85133120e49c223f36aa77d398b8abac727
# bad: [39bdc95871b57828b3bbefc0280a1a80a6b63d9e] Merge tag 'iio-for-3.18a' of git://git.kernel.org/pub/scm/linux/kernel/git/jic23/iio into work-next
git bisect bad 39bdc95871b57828b3bbefc0280a1a80a6b63d9e
# bad: [0680eb1f485ba5aac2ee02c9f0622239c9a4b16c] timekeeping: Another fix to the VSYSCALL_OLD update_vsyscall
git bisect bad 0680eb1f485ba5aac2ee02c9f0622239c9a4b16c
# good: [4a319a490ca59a746b3d36768c0e29ee19832366] Merge branch 'for-3.17/core' of git://git.kernel.dk/linux-block
git bisect good 4a319a490ca59a746b3d36768c0e29ee19832366
# good: [a8e4def604a9affa04fdd4efa0692da1385ffa3f] Merge tag 'mmc-v3.17-1' of git://git.linaro.org/people/ulf.hansson/mmc
git bisect good a8e4def604a9affa04fdd4efa0692da1385ffa3f
# bad: [ae36e95cf81c98b111b84317adeb358aaffa80e2] Merge tag 'devicetree-for-linus' of git://git.secretlab.ca/git/linux
git bisect bad ae36e95cf81c98b111b84317adeb358aaffa80e2
# bad: [cc8a44c671fd3a2c792e9e1f59ea1df52697cc8b] Merge tag 'vfio-v3.17-rc1' of git://github.com/awilliam/linux-vfio
git bisect bad cc8a44c671fd3a2c792e9e1f59ea1df52697cc8b
# bad: [99eb1908e643609e83454c6fbcbb59f9055abf09] dm switch: factor out switch_region_table_read
git bisect bad 99eb1908e643609e83454c6fbcbb59f9055abf09
# bad: [304affaa88328fe8f40ff14f5e6ccbfad8f121eb] dm cache: fail migrations in the do_worker error path
git bisect bad 304affaa88328fe8f40ff14f5e6ccbfad8f121eb
# good: [50f3c3efdd5773d90396be07a7ecaa58227ff906] dm thin: switch to an atomic_t for tracking pending new block preparations
git bisect good 50f3c3efdd5773d90396be07a7ecaa58227ff906
# bad: [8c081b52c6833a30a69ea3bdcef316eccc740c87] dm cache: simplify deferred set reference count increments
git bisect bad 8c081b52c6833a30a69ea3bdcef316eccc740c87
# good: [e5aea7b49f2b1fd01f35ca7abeb76f5c56128a55] dm thin: relax external origin size constraints
git bisect good e5aea7b49f2b1fd01f35ca7abeb76f5c56128a55
# first bad commit: [8c081b52c6833a30a69ea3bdcef316eccc740c87] dm cache: simplify deferred set reference count increments

[-- Attachment #4: Type: text/plain, Size: 0 bytes --]

Re: dmcache RAID1 bug?

[Mike Snitzer]

On Wed, Nov 19 2014 at  4:39pm -0500,
Leonardo Santos <heiligerstein@gmail.com> wrote:

> After run regression tests using 'git bisect', I identify that the error
> was created after commit 8c081b52c6833a30a69ea3bdcef316eccc740c87
> 
> To reproduce this error just:
> - create a raid1 HDDs for origin device;
> - create a cache device with SSDs (could or not be raid)
> - create a metadata device with SSDs (could or not be raid)
> - create a cache device using prior devices
> - kernel crashes.
> 
> I attached the bitseclog and diff file!

Surprising considering I went over that commit multiple times (because
the changes weren't obvious relative to the "No functional change."
assertion in the commit's header).  The __cache_map and cache_map change
to centralize the inc_ds + cell_defer made the __cache_map changes
_seem_ like a difference was being introduced but they still look fine
to me.

Looking again I notice check_for_quiesced_migrations() switched to
an unconditional dm_deferred_entry_dec(); but that is fine because
earlier in check_for_quiesced_migrations() there is an early return if
pb->all_io_entry is NULL.

But could be a more trained eye will see some functional change that may
have been introduced (cc'ing Joe).

Mike

Re: dmcache RAID1 bug?

[Joe Thornber]

On Wed, Nov 19, 2014 at 07:39:44PM -0200, Leonardo Santos wrote:
> After run regression tests using 'git bisect', I identify that the error
> was created after commit 8c081b52c6833a30a69ea3bdcef316eccc740c87
> 
> To reproduce this error just:
> - create a raid1 HDDs for origin device;
> - create a cache device with SSDs (could or not be raid)
> - create a metadata device with SSDs (could or not be raid)
> - create a cache device using prior devices
> - kernel crashes.
> 
> @@ -1115,8 +1142,7 @@ static void check_for_quiesced_migrations(struct cache *cache,
>  		return;
>  
>  	INIT_LIST_HEAD(&work);
> -	if (pb->all_io_entry)
> -		dm_deferred_entry_dec(pb->all_io_entry, &work);
> +	dm_deferred_entry_dec(pb->all_io_entry, &work);
>  
>  	if (!list_empty(&work))
>  		queue_quiesced_migrations(cache, &work);

This looks suspicious, I believe the all_io_entry is not set if the io
covers a complete block.  Any chance you could test with this fragment
backed out please?

- Joe

Re: dmcache RAID1 bug?

[Joe Thornber]

On Thu, Nov 20, 2014 at 02:04:26PM +0000, Joe Thornber wrote:
> On Wed, Nov 19, 2014 at 07:39:44PM -0200, Leonardo Santos wrote:
> > After run regression tests using 'git bisect', I identify that the error
> > was created after commit 8c081b52c6833a30a69ea3bdcef316eccc740c87
> > 
> > To reproduce this error just:
> > - create a raid1 HDDs for origin device;
> > - create a cache device with SSDs (could or not be raid)
> > - create a metadata device with SSDs (could or not be raid)
> > - create a cache device using prior devices
> > - kernel crashes.
> > 
> > @@ -1115,8 +1142,7 @@ static void check_for_quiesced_migrations(struct cache *cache,
> >  		return;
> >  
> >  	INIT_LIST_HEAD(&work);
> > -	if (pb->all_io_entry)
> > -		dm_deferred_entry_dec(pb->all_io_entry, &work);
> > +	dm_deferred_entry_dec(pb->all_io_entry, &work);
> >  
> >  	if (!list_empty(&work))
> >  		queue_quiesced_migrations(cache, &work);
> 
> This looks suspicious, I believe the all_io_entry is not set if the io
> covers a complete block.  Any chance you could test with this fragment
> backed out please?

Ignore me, there's another check for !pb->all_io_entry.

Re: dmcache RAID1 bug?

[Mike Snitzer]

On Wed, Nov 19 2014 at  4:39pm -0500,
Leonardo Santos <heiligerstein@gmail.com> wrote:

> After run regression tests using 'git bisect', I identify that the error
> was created after commit 8c081b52c6833a30a69ea3bdcef316eccc740c87
> 
> To reproduce this error just:
> - create a raid1 HDDs for origin device;
> - create a cache device with SSDs (could or not be raid)
> - create a metadata device with SSDs (could or not be raid)
> - create a cache device using prior devices
> - kernel crashes.
> 
> I attached the bitseclog and diff file!

Hi, Joe recently fixed a couple issues in dm-cache that were only seen
when a DM raid device lost a raid member (while not exact as your
report, could resolve your issues).  Could you please retest with these
3 dm-cache commits applied to your kernel (all commits are in latest
3.19-rc kernel)?

9b1cc9f dm cache: share cache-metadata object across inactive and active DM tables
a59db67 dm cache: fix problematic dual use of a single migration count variable
766a788 dm cache: fix missing ERR_PTR returns and handling