2.6.36-rc6 BUG at drivers/scsi/scsi_lib.c:1113
A message that is not in the archive (sent off-list or not yet received): [email protected]
Quoted 15 lines · George Spelvin
Quoted 7 lines
Would you mind enabling
CONFIG_SCSI_LOGGING=yin your kernel build and callingecho
0xffffffff>/proc/sys/dev/scsi/logging_levelso we can double check to see which CDBs are actually generating the issue..?
Thanks!
Here's a syslog starting at boot time for that (I also added verbose
SCSI errors, FWIW.) I did
echo0xffffffff>/proc/sys/dev/scsi/logging_level; echo check >/sys/block/md6/md/sync_actionto minimize time delay and resultany unrelated log spam.Note that md6 is mirrored across *every* drive on the machine. (It's the emergency recovery /boot partition.)
<SNIP>
Quoted 61 lines
23:56:29: md: data-check of RAID array md6
23:56:29: md: minimum _guaranteed_ speed: 1000 KB/sec/disk.
23:56:29: md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for data-check. 23:56:29: md: using 128k window, over a total of 1166912 blocks.
23:56:29: sd 0:0:0:0: [sda]sd_init_command: block=0, count=0
23:56:29: sd 0:0:0:0: [sda] block=0
23:56:29: sd 0:0:0:0: [sda] reading 0/0 512 byte blocks.
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
Quoted 8 lines
23:56:29: sd 0:0:0:0: [sda] Done:
0xffff88021984ed00SUCCESS 23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK 23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00 23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: sd 0:0:0:0: Notifying upper driver of completion (result 70000) 23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK 23:56:29: 0 sectors total, 0 bytes done.
23:56:29: leavingscsi_dispatch_cmnd()
Ok, it looks like my initial guess about FUA / BARRIER breakage was completely wrong here. So the issue is in fact being caused by a READ_10 with a transfer length of zero generated somewhere else UPL MD code (perhaps something to do with MD metadata..?)
Would you be able to 'git bisect' on your system with Linus'es linux-2.6.git tree from commit 9fe6206f400646a (v2.6.35) to HEAD at v2.6.36-rc6 to help us pinpoint which commit the breakage was introduced..?
Thanks!
--nab
Quoted 44 lines
23:56:29: ------------[ cut here ]------------
23:56:29: kernel BUG atdrivers/scsi/scsi_lib.c:1113!
23:56:29: invalid opcode: 0000 [#1] SMP
23:56:29: last sysfs file:/sys/devices/virtual/block/md6/md/sync_action
23:56:29: CPU 3
23:56:29: Modules linked in: ctrtwofish_generictwofish_x86_64twofish_commonserpent xcbcsha512_genericsha256_genericcrypto_nullipg 8250_pci 8250_pnp 8250serial_core23:56:29:
23:56:29: Pid: 5446, comm:md6_resyncNot tainted 2.6.36-rc6-00070-g44c064a #3 MS-7376/MS-7376
23:56:29: RIP: 0010:[<ffffffff812ac592>] [<ffffffff812ac592>]scsi_setup_fs_cmnd+0x4e/0xbb
23:56:29: RSP: 0018:ffff88021af05ab0 EFLAGS: 00010046
23:56:29: RAX: 0000000000000000 RBX:ffff88021f39cb88RCX:ffff88021f2ee960
23:56:29: RDX: 0000000000000000 RSI:ffff88021f39cb88RDI:ffff88021f65bc00
23:56:29: RBP:ffff88021af05ac0R08:00000000000003e8R09:ffff88021f677848
23:56:29: R10: 0000000000000000 R11:ffff88021f677848R12:ffff88021f65bc00
23:56:29: R13: 0000000000000000 R14:ffff88021f65bc48R15:ffff88021f2f7000
23:56:29: FS: 00007f096e6a27c0(0000) GS:ffff880028380000(0000) knlGS:0000000000000000
23:56:29: CS: 0010 DS: 0000 ES: 0000 CR0:000000008005003b
23:56:29: CR2:0000003a10c1e8f0CR3:000000021c612000CR4:00000000000006e0
23:56:29: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
23:56:29: DR3: 0000000000000000 DR6:00000000ffff0ff0DR7: 0000000000000400
23:56:29: Processmd6_resync(pid: 5446, threadinfoffff88021af04000, taskffff88021988ac00)
23:56:29: Stack:
23:56:29: 0000000000000000ffff88021f39cb88ffff88021af05b40ffffffff812b2af8
23:56:29: <0>ffff88021af05b40ffffffff8116b8e50000000000000200 0000000000000000
23:56:29: <0>ffff88021f511868ffff88021f2ee960ffff88021f511958ffff88021f65bc00
23:56:29: Call Trace:23:56:29: [<ffffffff812b2af8>] sd_prep_fn+0x252/0xb00 23:56:29: [<ffffffff8116b8e5>] ? cfq_dispatch_requests+0x6c3/0x7ec 23:56:29: [<ffffffff81160487>] blk_peek_request+0xb3/0x177 23:56:29: [<ffffffff812abc42>] scsi_request_fn+0x8b/0x4cb 23:56:29: [<ffffffff81160d9c>] __generic_unplug_device+0x32/0x37 23:56:29: [<ffffffff81160dcc>] generic_unplug_device+0x2b/0x3a 23:56:29: [<ffffffff8115f0de>] blk_unplug+0x12/0x14 23:56:29: [<ffffffff81308275>] unplug_slaves+0x69/0x9f 23:56:29: [<ffffffff813082c3>] raid1_unplug+0x18/0x28 23:56:29: [<ffffffff8115f0de>] blk_unplug+0x12/0x14 23:56:29: [<ffffffff8131c1b6>] md_unplug+0x1d/0x33 23:56:29: [<ffffffff8131cb18>] md_do_sync+0x94c/0xba6 23:56:29: [<ffffffff8102f88f>] ? finish_task_switch+0x34/0x74 23:56:29: [<ffffffff8131d17e>] md_thread+0xf6/0x114 23:56:29: [<ffffffff8131d088>] ? md_thread+0x0/0x114 23:56:29: [<ffffffff8131d088>] ? md_thread+0x0/0x114 23:56:29: [<ffffffff81049e4f>] kthread+0x7d/0x85 23:56:29: [<ffffffff81002c94>] kernel_thread_helper+0x4/0x10
Hi Neil,
Do you know if any of the recent changes into drivers/md/ code could starting causing zero-length bio READ to be generated to MD RAID1 backstores along the lines of what George is currently seeing w/ 10x RAID1 arrays during assembly..?
Thanks,
--nab
Quoted 153 lines · Nicholas A. Bellinger
Quoted 15 lines · George Spelvin
Quoted 7 lines
Would you mind enabling
CONFIG_SCSI_LOGGING=yin your kernel build and callingecho
0xffffffff>/proc/sys/dev/scsi/logging_levelso we can double check to see which CDBs are actually generating the issue..?
Thanks!
Here's a syslog starting at boot time for that (I also added verbose
SCSI errors, FWIW.) I did
echo0xffffffff>/proc/sys/dev/scsi/logging_level; echo check >/sys/block/md6/md/sync_actionto minimize time delay and resultany unrelated log spam.Note that md6 is mirrored across *every* drive on the machine. (It's the emergency recovery /boot partition.)
<SNIP>
Quoted 61 lines
23:56:29: md: data-check of RAID array md6
23:56:29: md: minimum _guaranteed_ speed: 1000 KB/sec/disk.
23:56:29: md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for data-check. 23:56:29: md: using 128k window, over a total of 1166912 blocks.
23:56:29: sd 0:0:0:0: [sda]sd_init_command: block=0, count=0
23:56:29: sd 0:0:0:0: [sda] block=0
23:56:29: sd 0:0:0:0: [sda] reading 0/0 512 byte blocks.
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()
23:56:29: sd 0:0:0:0: [sda] Done:0xffff88021984ed00RETRY
23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: Inserting commandffff88021984ed00into mlqueue
23:56:29: sd 0:0:0:0: [sda] Send:0xffff88021984ed00
23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00
23:56:29: buffer =0xffff88021984ee00, bufflen = 0, queuecommand0xffffffff812be49d23:56:29: ata1.00: WARNING: zero len r/w req
23:56:29: leavingscsi_dispatch_cmnd()Quoted 8 lines
23:56:29: sd 0:0:0:0: [sda] Done:
0xffff88021984ed00SUCCESS 23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK 23:56:29: sd 0:0:0:0: [sda] CDB: Read(10): 28 00 00 00 00 00 00 00 00 00 23:56:29: sd 0:0:0:0: [sda] scsi host busy 1 failed 0
23:56:29: sd 0:0:0:0: Notifying upper driver of completion (result 70000) 23:56:29: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK 23:56:29: 0 sectors total, 0 bytes done.
23:56:29: leavingscsi_dispatch_cmnd()Ok, it looks like my initial guess about FUA / BARRIER breakage was completely wrong here. So the issue is in fact being caused by a
READ_10with a transfer length of zero generated somewhere else UPL MD code (perhaps something to do with MD metadata..?)Would you be able to 'git bisect' on your system with Linus'es linux-2.6.git tree from commit
9fe6206f400646a(v2.6.35) to HEAD at v2.6.36-rc6 to help us pinpoint which commit the breakage was introduced..?Thanks!
--nab
Quoted 36 lines
23:56:29: ------------[ cut here ]------------
23:56:29: kernel BUG atdrivers/scsi/scsi_lib.c:1113!
23:56:29: invalid opcode: 0000 [#1] SMP
23:56:29: last sysfs file:/sys/devices/virtual/block/md6/md/sync_action
23:56:29: CPU 3
23:56:29: Modules linked in: ctrtwofish_generictwofish_x86_64twofish_commonserpent xcbcsha512_genericsha256_genericcrypto_nullipg 8250_pci 8250_pnp 8250serial_core23:56:29:
23:56:29: Pid: 5446, comm:md6_resyncNot tainted 2.6.36-rc6-00070-g44c064a #3 MS-7376/MS-7376
23:56:29: RIP: 0010:[<ffffffff812ac592>] [<ffffffff812ac592>]scsi_setup_fs_cmnd+0x4e/0xbb
23:56:29: RSP: 0018:ffff88021af05ab0 EFLAGS: 00010046
23:56:29: RAX: 0000000000000000 RBX:ffff88021f39cb88RCX:ffff88021f2ee960
23:56:29: RDX: 0000000000000000 RSI:ffff88021f39cb88RDI:ffff88021f65bc00
23:56:29: RBP:ffff88021af05ac0R08:00000000000003e8R09:ffff88021f677848
23:56:29: R10: 0000000000000000 R11:ffff88021f677848R12:ffff88021f65bc00
23:56:29: R13: 0000000000000000 R14:ffff88021f65bc48R15:ffff88021f2f7000
23:56:29: FS: 00007f096e6a27c0(0000) GS:ffff880028380000(0000) knlGS:0000000000000000
23:56:29: CS: 0010 DS: 0000 ES: 0000 CR0:000000008005003b
23:56:29: CR2:0000003a10c1e8f0CR3:000000021c612000CR4:00000000000006e0
23:56:29: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
23:56:29: DR3: 0000000000000000 DR6:00000000ffff0ff0DR7: 0000000000000400
23:56:29: Processmd6_resync(pid: 5446, threadinfoffff88021af04000, taskffff88021988ac00)
23:56:29: Stack:
23:56:29: 0000000000000000ffff88021f39cb88ffff88021af05b40ffffffff812b2af8
23:56:29: <0>ffff88021af05b40ffffffff8116b8e50000000000000200 0000000000000000
23:56:29: <0>ffff88021f511868ffff88021f2ee960ffff88021f511958ffff88021f65bc00
23:56:29: Call Trace:23:56:29: [<ffffffff812b2af8>] sd_prep_fn+0x252/0xb00 23:56:29: [<ffffffff8116b8e5>] ? cfq_dispatch_requests+0x6c3/0x7ec 23:56:29: [<ffffffff81160487>] blk_peek_request+0xb3/0x177 23:56:29: [<ffffffff812abc42>] scsi_request_fn+0x8b/0x4cb 23:56:29: [<ffffffff81160d9c>] __generic_unplug_device+0x32/0x37 23:56:29: [<ffffffff81160dcc>] generic_unplug_device+0x2b/0x3a 23:56:29: [<ffffffff8115f0de>] blk_unplug+0x12/0x14 23:56:29: [<ffffffff81308275>] unplug_slaves+0x69/0x9f 23:56:29: [<ffffffff813082c3>] raid1_unplug+0x18/0x28 23:56:29: [<ffffffff8115f0de>] blk_unplug+0x12/0x14Quoted 8 lines
23:56:29: [<ffffffff8131c1b6>] md_unplug+0x1d/0x33 23:56:29: [<ffffffff8131cb18>] md_do_sync+0x94c/0xba6 23:56:29: [<ffffffff8102f88f>] ? finish_task_switch+0x34/0x74 23:56:29: [<ffffffff8131d17e>] md_thread+0xf6/0x114 23:56:29: [<ffffffff8131d088>] ? md_thread+0x0/0x114 23:56:29: [<ffffffff8131d088>] ? md_thread+0x0/0x114 23:56:29: [<ffffffff81049e4f>] kthread+0x7d/0x85 23:56:29: [<ffffffff81002c94>] kernel_thread_helper+0x4/0x10--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Quoted 4 lines
Would you be able to 'git bisect' on your system with Linus'es linux-2.6.git tree from commit
9fe6206f400646a(v2.6.35) to HEAD at v2.6.36-rc6 to help us pinpoint which commit the breakage was introduced..?
It's tedious, but I can, HOWEVER...
any advice avoiding false positives from
https://bugzilla.kernel.org/show_bug.cgi?id=16275
introduced in 74450be123b6f3cb480c358a056be398cce6aa6e and fixed in 2c7d46ec192e4f2b350f67a0e185b9bce646cd6b?
I suppose I could cherry-pick the latter when in the vulnerable range...