[2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Paul Smith]

Hi all; we are seeing a problem where, when we pull a disk out of our
disk array (even one that's not actively being used), the entire IO
subsystem in Linux hangs.  Here are some details:

I have an IBM Bladecenter with an LSI EXP3000 SAS expander with 12 1TB
Seagate SAS disks.  Relevant lspci output for the SAS controllers:

        # lspci | grep LSI
        02:00.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064ET PCI-Express Fusion-MPT SAS (rev 02)
        08:01.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064 PCI-X Fusion-MPT SAS (rev 03)
        14:01.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064 PCI-X Fusion-MPT SAS (rev 03)

On this system we are running an embedded/custom version of Linux in a
ramdisk, based on Linux 2.6.27.25.  Unfortunately it's quite
difficult/impossible for us to upgrade to a newer kernel at this time,
however if this problem rings a bell I'm happy to backport patches,
fixes, etc.

As I mentioned, when we pull one of the disks from the EXP3000 the IO
subsystem completely hangs.  Since we're running on a ramdisk this
doesn't hang our system completely, but any attempt to do any disk IO
thereafter hangs, so we have to power-cycle the blade (because reboot
tries to write to the disks).  This quite reproducible in our
environment BUT it is very timing-sensitive, as shown below.  If we
enable too much logging, etc. it goes away.

We've been in touch with some driver folks at LSI and they seem to feel
that the problem is a SCSI midlayer race condition, rather than in the
mptlinux driver itself.  So I'm hoping someone here has ideas.

On a working disk pull we get log messages like this:

        mptscsih: ioc1: attempting host reset! (sc=ffff8804619e2640)
        mptscsih: ioc1: host reset: SUCCESS (sc=ffff8804619e2640)
        mptbase: ioc1: LogInfo(0x30030501): Originator={IOP}, Code={Invalid Page}, SubCode(0x0501)
        mptsas: ioc1: removing ssp device: fw_channel 0, fw_id 72, phy 11, sas_addr 0x5000c5000d2987b6
        sd 3:0:11:0: [sdx] Synchronizing SCSI cache
        sd 3:0:11:0: Device offlined - not ready after error recovery
        sg_cmd_done: device detached

Note that the "host reset: SUCCESS" message here comes BEFORE the
"Synchronizing SCSI cache" message.  On a hanging disk pull we get log
messages like this:

        mptscsih: ioc1: attempting host reset! (sc=ffff8804622b48c0)
        mptsas: ioc1: removing ssp device: fw_channel 0, fw_id 72, phy 11, sas_addr 0x5000c5000d2987b6
        sd 3:0:11:0: [sdx] Synchronizing SCSI cache

and it hangs right here.  In this situation the host reset does not
complete before we try to sync, and that appears to be the indicator of
the problem.  Here's a backtrace; note we're in sd_sync_cache():

        Call Trace:
         [<ffffffff8048d88f>] _spin_lock_irqsave+0x1f/0x50
         [<ffffffff8048daf2>] _spin_unlock_irqrestore+0x12/0x40
         [<ffffffffa00080fc>] scsi_get_command+0x8c/0xc0 [scsi_mod]
         [<ffffffff8048c11d>] schedule_timeout+0xad/0xf0
         [<ffffffff8034df1d>] elv_next_request+0x15d/0x290
         [<ffffffff8048b1ea>] wait_for_common+0xba/0x170
         [<ffffffff80237460>] default_wake_function+0x0/0x10
         [<ffffffff80353b77>] blk_execute_rq+0x67/0xa0
         [<ffffffff80350e71>] get_request_wait+0x21/0x1d0
         [<ffffffff8023e972>] vprintk+0x1f2/0x490
         [<ffffffff8048dab1>] _spin_unlock_irq+0x11/0x40
         [<ffffffffa000e5a4>] scsi_execute+0xf4/0x150 [scsi_mod]
         [<ffffffffa000e691>] scsi_execute_req+0x91/0x100 [scsi_mod]
         [<ffffffffa00f89bc>] sd_sync_cache+0xac/0x100 [sd_mod]
         [<ffffffff80360000>] compat_blkdev_ioctl+0x80/0x1740
         [<ffffffff80364062>] kobject_get+0x12/0x20
         [<ffffffffa00fac51>] sd_shutdown+0x71/0x160 [sd_mod]
         [<ffffffffa00fad7c>] sd_remove+0x3c/0x80 [sd_mod]
         [<ffffffffa0012122>] scsi_bus_remove+0x42/0x60 [scsi_mod]
         [<ffffffff803d8ba9>] __device_release_driver+0x99/0x100
         [<ffffffff803d8d08>] device_release_driver+0x28/0x40
         [<ffffffff803d8087>] bus_remove_device+0xb7/0xf0
         [<ffffffff803d66c9>] device_del+0x119/0x1a0
         [<ffffffffa001245c>] __scsi_remove_device+0x5c/0xb0 [scsi_mod]
         [<ffffffffa00124d8>] scsi_remove_device+0x28/0x40 [scsi_mod]
         [<ffffffffa00125a0>] __scsi_remove_target+0xa0/0xd0 [scsi_mod]
         [<ffffffffa0012640>] __remove_child+0x0/0x30 [scsi_mod]
         [<ffffffffa0012656>] __remove_child+0x16/0x30 [scsi_mod]
         [<ffffffff803d5c3b>] device_for_each_child+0x3b/0x60
         [<ffffffffa0012606>] scsi_remove_target+0x36/0x70 [scsi_mod]
         [<ffffffffa010c5f5>] sas_rphy_remove+0x75/0x80 [scsi_transport_sas]
         [<ffffffffa010c609>] sas_rphy_delete+0x9/0x20 [scsi_transport_sas]
         [<ffffffffa010c642>] sas_port_delete+0x22/0x140 [scsi_transport_sas]
         [<ffffffffa013c230>] mptsas_del_end_device+0x230/0x2c0 [mptsas]
         [<ffffffffa013c8a1>] mptsas_hotplug_work+0x291/0xb20 [mptsas]
         [<ffffffff80369c9a>] vsnprintf+0x2ea/0x7c0
         [<ffffffff80287dac>] free_hot_cold_page+0x1fc/0x2f0
         [<ffffffff80287ed8>] __pagevec_free+0x38/0x50
         [<ffffffff8028b730>] release_pages+0x180/0x1d0
         [<ffffffff80362789>] __next_cpu+0x19/0x30
         [<ffffffff802321ec>] find_busiest_group+0x1dc/0x960
         [<ffffffff80362789>] __next_cpu+0x19/0x30
         [<ffffffff802321ec>] find_busiest_group+0x1dc/0x960
         [<ffffffffa013e4a9>] mptsas_firmware_event_work+0xd29/0x1110 [mptsas]
         [<ffffffff8022dc94>] update_curr+0x84/0xd0
         [<ffffffff80230370>] __dequeue_entity+0x60/0x90
         [<ffffffff8048dab1>] _spin_unlock_irq+0x11/0x40
         [<ffffffff802364fb>] finish_task_switch+0x3b/0xd0
         [<ffffffff8048b911>] thread_return+0xa3/0x662
         [<ffffffffa013d780>] mptsas_firmware_event_work+0x0/0x1110 [mptsas]
         [<ffffffff80250e65>] run_workqueue+0x85/0x150
         [<ffffffff80250fcf>] worker_thread+0x9f/0x110
         [<ffffffff802553b0>] autoremove_wake_function+0x0/0x30
         [<ffffffff80250f30>] worker_thread+0x0/0x110
         [<ffffffff80254ef7>] kthread+0x47/0x90
         [<ffffffff80254eb0>] kthread+0x0/0x90
         [<ffffffff8020d5f9>] child_rip+0xa/0x11
         [<ffffffff80254eb0>] kthread+0x0/0x90
         [<ffffffff80254eb0>] kthread+0x0/0x90
         [<ffffffff8020d5ef>] child_rip+0x0/0x11

According to sd.c:sd_synch_cache() it's supposed to retry the
scsi_execute_req() three times then give up, but instead it never
returns.  It seems that if the host reset is not completed yet, then we
find this event on the workqueue and get into some kind of deadlock
situation.

We're kind of stuck on this and I was wondering if anyone has any
thoughts or avenues to look at to move us forward on resolving this?

Thanks!

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Mike Anderson]

Paul Smith <paul@mad-scientist.net> wrote:
> Hi all; we are seeing a problem where, when we pull a disk out of our
> disk array (even one that's not actively being used), the entire IO
> subsystem in Linux hangs.  Here are some details:
> 
> I have an IBM Bladecenter with an LSI EXP3000 SAS expander with 12 1TB
> Seagate SAS disks.  Relevant lspci output for the SAS controllers:
> 
>         # lspci | grep LSI
>         02:00.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064ET PCI-Express Fusion-MPT SAS (rev 02)
>         08:01.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064 PCI-X Fusion-MPT SAS (rev 03)
>         14:01.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064 PCI-X Fusion-MPT SAS (rev 03)
> 
> On this system we are running an embedded/custom version of Linux in a
> ramdisk, based on Linux 2.6.27.25.  Unfortunately it's quite
> difficult/impossible for us to upgrade to a newer kernel at this time,
> however if this problem rings a bell I'm happy to backport patches,
> fixes, etc.
> 
> As I mentioned, when we pull one of the disks from the EXP3000 the IO
> subsystem completely hangs.  Since we're running on a ramdisk this
> doesn't hang our system completely, but any attempt to do any disk IO
> thereafter hangs, so we have to power-cycle the blade (because reboot
> tries to write to the disks).  This quite reproducible in our
> environment BUT it is very timing-sensitive, as shown below.  If we
> enable too much logging, etc. it goes away.
> 

Have you tried a minimum level of logging like the following without the
error going away?
"sysctl -w dev.scsi.logging_level=4100"


> We've been in touch with some driver folks at LSI and they seem to feel
> that the problem is a SCSI midlayer race condition, rather than in the
> mptlinux driver itself.  So I'm hoping someone here has ideas.
> 
> On a working disk pull we get log messages like this:
> 
>         mptscsih: ioc1: attempting host reset! (sc=ffff8804619e2640)
>         mptscsih: ioc1: host reset: SUCCESS (sc=ffff8804619e2640)
>         mptbase: ioc1: LogInfo(0x30030501): Originator={IOP}, Code={Invalid Page}, SubCode(0x0501)
>         mptsas: ioc1: removing ssp device: fw_channel 0, fw_id 72, phy 11, sas_addr 0x5000c5000d2987b6
>         sd 3:0:11:0: [sdx] Synchronizing SCSI cache
>         sd 3:0:11:0: Device offlined - not ready after error recovery
>         sg_cmd_done: device detached
> 
> Note that the "host reset: SUCCESS" message here comes BEFORE the
> "Synchronizing SCSI cache" message.  On a hanging disk pull we get log
> messages like this:
> 
>         mptscsih: ioc1: attempting host reset! (sc=ffff8804622b48c0)
>         mptsas: ioc1: removing ssp device: fw_channel 0, fw_id 72, phy 11, sas_addr 0x5000c5000d2987b6
>         sd 3:0:11:0: [sdx] Synchronizing SCSI cache
> 
> and it hangs right here.  In this situation the host reset does not
> complete before we try to sync, and that appears to be the indicator of
> the problem.  Here's a backtrace; note we're in sd_sync_cache():
> 
>         Call Trace:
>          [<ffffffff8048d88f>] _spin_lock_irqsave+0x1f/0x50
>          [<ffffffff8048daf2>] _spin_unlock_irqrestore+0x12/0x40
>          [<ffffffffa00080fc>] scsi_get_command+0x8c/0xc0 [scsi_mod]
>          [<ffffffff8048c11d>] schedule_timeout+0xad/0xf0
>          [<ffffffff8034df1d>] elv_next_request+0x15d/0x290
>          [<ffffffff8048b1ea>] wait_for_common+0xba/0x170
>          [<ffffffff80237460>] default_wake_function+0x0/0x10
>          [<ffffffff80353b77>] blk_execute_rq+0x67/0xa0
>          [<ffffffff80350e71>] get_request_wait+0x21/0x1d0
>          [<ffffffff8023e972>] vprintk+0x1f2/0x490
>          [<ffffffff8048dab1>] _spin_unlock_irq+0x11/0x40
>          [<ffffffffa000e5a4>] scsi_execute+0xf4/0x150 [scsi_mod]
>          [<ffffffffa000e691>] scsi_execute_req+0x91/0x100 [scsi_mod]
>          [<ffffffffa00f89bc>] sd_sync_cache+0xac/0x100 [sd_mod]
>          [<ffffffff80360000>] compat_blkdev_ioctl+0x80/0x1740
>          [<ffffffff80364062>] kobject_get+0x12/0x20
>          [<ffffffffa00fac51>] sd_shutdown+0x71/0x160 [sd_mod]
>          [<ffffffffa00fad7c>] sd_remove+0x3c/0x80 [sd_mod]
>          [<ffffffffa0012122>] scsi_bus_remove+0x42/0x60 [scsi_mod]
>          [<ffffffff803d8ba9>] __device_release_driver+0x99/0x100
>          [<ffffffff803d8d08>] device_release_driver+0x28/0x40
>          [<ffffffff803d8087>] bus_remove_device+0xb7/0xf0
>          [<ffffffff803d66c9>] device_del+0x119/0x1a0
>          [<ffffffffa001245c>] __scsi_remove_device+0x5c/0xb0 [scsi_mod]
>          [<ffffffffa00124d8>] scsi_remove_device+0x28/0x40 [scsi_mod]
>          [<ffffffffa00125a0>] __scsi_remove_target+0xa0/0xd0 [scsi_mod]
>          [<ffffffffa0012640>] __remove_child+0x0/0x30 [scsi_mod]
>          [<ffffffffa0012656>] __remove_child+0x16/0x30 [scsi_mod]
>          [<ffffffff803d5c3b>] device_for_each_child+0x3b/0x60
>          [<ffffffffa0012606>] scsi_remove_target+0x36/0x70 [scsi_mod]
>          [<ffffffffa010c5f5>] sas_rphy_remove+0x75/0x80 [scsi_transport_sas]
>          [<ffffffffa010c609>] sas_rphy_delete+0x9/0x20 [scsi_transport_sas]
>          [<ffffffffa010c642>] sas_port_delete+0x22/0x140 [scsi_transport_sas]
>          [<ffffffffa013c230>] mptsas_del_end_device+0x230/0x2c0 [mptsas]
>          [<ffffffffa013c8a1>] mptsas_hotplug_work+0x291/0xb20 [mptsas]
>          [<ffffffff80369c9a>] vsnprintf+0x2ea/0x7c0
>          [<ffffffff80287dac>] free_hot_cold_page+0x1fc/0x2f0
>          [<ffffffff80287ed8>] __pagevec_free+0x38/0x50
>          [<ffffffff8028b730>] release_pages+0x180/0x1d0
>          [<ffffffff80362789>] __next_cpu+0x19/0x30
>          [<ffffffff802321ec>] find_busiest_group+0x1dc/0x960
>          [<ffffffff80362789>] __next_cpu+0x19/0x30
>          [<ffffffff802321ec>] find_busiest_group+0x1dc/0x960
>          [<ffffffffa013e4a9>] mptsas_firmware_event_work+0xd29/0x1110 [mptsas]
>          [<ffffffff8022dc94>] update_curr+0x84/0xd0
>          [<ffffffff80230370>] __dequeue_entity+0x60/0x90
>          [<ffffffff8048dab1>] _spin_unlock_irq+0x11/0x40
>          [<ffffffff802364fb>] finish_task_switch+0x3b/0xd0
>          [<ffffffff8048b911>] thread_return+0xa3/0x662
>          [<ffffffffa013d780>] mptsas_firmware_event_work+0x0/0x1110 [mptsas]
>          [<ffffffff80250e65>] run_workqueue+0x85/0x150
>          [<ffffffff80250fcf>] worker_thread+0x9f/0x110
>          [<ffffffff802553b0>] autoremove_wake_function+0x0/0x30
>          [<ffffffff80250f30>] worker_thread+0x0/0x110
>          [<ffffffff80254ef7>] kthread+0x47/0x90
>          [<ffffffff80254eb0>] kthread+0x0/0x90
>          [<ffffffff8020d5f9>] child_rip+0xa/0x11
>          [<ffffffff80254eb0>] kthread+0x0/0x90
>          [<ffffffff80254eb0>] kthread+0x0/0x90
>          [<ffffffff8020d5ef>] child_rip+0x0/0x11
> 
> According to sd.c:sd_synch_cache() it's supposed to retry the
> scsi_execute_req() three times then give up, but instead it never
> returns.  It seems that if the host reset is not completed yet, then we
> find this event on the workqueue and get into some kind of deadlock
> situation.
> 
> We're kind of stuck on this and I was wondering if anyone has any
> thoughts or avenues to look at to move us forward on resolving this?

Can you run "cat /sys/class/scsi_host/*/state" when you are in the hung
state?

If the host is in recovery no IOs will move forward. I assume if you can
get a run with the 4100 level of logging it will show a host reset sent,
but no waking up host to restart (unless the reset is being generated for
other reasons outside of the scsi error handler).

-andmike
--
Michael Anderson
andmike@linux.vnet.ibm.com

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Paul Smith]

On Thu, 2009-07-02 at 10:41 -0700, Mike Anderson wrote:
> > As I mentioned, when we pull one of the disks from the EXP3000 the IO
> > subsystem completely hangs.  Since we're running on a ramdisk this
> > doesn't hang our system completely, but any attempt to do any disk IO
> > thereafter hangs, so we have to power-cycle the blade (because reboot
> > tries to write to the disks).  This quite reproducible in our
> > environment BUT it is very timing-sensitive, as shown below.  If we
> > enable too much logging, etc. it goes away.
> 
> Have you tried a minimum level of logging like the following without the
> error going away?
> "sysctl -w dev.scsi.logging_level=4100"

We've been enabling some logging at the mptlinux driver level, but not
the generic SCSI level.  We'll give this a try.

> Can you run "cat /sys/class/scsi_host/*/state" when you are in the hung
> state?

We'll try this as well.  One thing we did discover was that the device
entry in /sys/class/scsi_device/* is already gone when the hang occurs
so we can't retrieve the state of the device that way.

> If the host is in recovery no IOs will move forward. I assume if you can
> get a run with the 4100 level of logging it will show a host reset sent,
> but no waking up host to restart (unless the reset is being generated for
> other reasons outside of the scsi error handler).

This seems likely but the question is, why isn't it waking up again?

Unfortunately one of the folks working on this with me left for the US
holiday weekend so we'll have to take it up again on Monday morning.
Thanks for your reply, Mike!

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Paul Smith]

On Thu, 2009-07-02 at 10:41 -0700, Mike Anderson wrote:
> Paul Smith <paul@mad-scientist.net> wrote:
> > Hi all; we are seeing a problem where, when we pull a disk out of our
> > disk array (even one that's not actively being used), the entire IO
> > subsystem in Linux hangs.  Here are some details:
> > 
> > I have an IBM Bladecenter with an LSI EXP3000 SAS expander with 12 1TB
> > Seagate SAS disks.  Relevant lspci output for the SAS controllers:
> > 
> >         # lspci | grep LSI
> >         02:00.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064ET PCI-Express Fusion-MPT SAS (rev 02)
> >         08:01.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064 PCI-X Fusion-MPT SAS (rev 03)
> >         14:01.0 SCSI storage controller: LSI Logic / Symbios Logic SAS1064 PCI-X Fusion-MPT SAS (rev 03)
> 
> Have you tried a minimum level of logging like the following without the
> error going away?
> "sysctl -w dev.scsi.logging_level=4100"

We enabled this and were able to reproduce the hang.  Please see the log
output below.

> Can you run "cat /sys/class/scsi_host/*/state" when you are in the hung
> state?
> 
> If the host is in recovery no IOs will move forward. I assume if you can
> get a run with the 4100 level of logging it will show a host reset sent,
> but no waking up host to restart (unless the reset is being generated for
> other reasons outside of the scsi error handler).

This seems to be the case, yes.  The output of the above-requested cat
is:

# cat /sys/class/scsi_host/host*/state
running
running
running
recovery
running

# cat /sys/class/scsi_host/host3/state
recovery

# ls -l /sys/class/scsi_host/host3/device
lrwxrwxrwx    1 root     root            0 Jul  6 13:27 /sys/class/scsi_host/host3/device -> ../../../devices/pci0000:00/0000:00:04.0/0000:11:00.0/0000:13:08.0/0000:14:01.0/host3

Note that host3 is ioc1.

Thanks for looking at this; it's really killing us.


kernel log output:
------------------
Jul  6 13:31:18  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:18  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:27  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:27  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:35  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:35  user.info kernel: sd 3:0:1:0: [sdn] Result: hostbyte=0x02 driverbyte=0x00
Jul  6 13:31:35  user.warn kernel: device-mapper: multipath: Failing path 8:208.
Jul  6 13:31:35  daemon.notice multipathd: 8:208: mark as failed
Jul  6 13:31:35  daemon.notice multipathd: encl1Slot2: remaining active paths: 1
Jul  6 13:31:43  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:43  user.info kernel: sd 2:0:1:0: [sdb] <6>mptscsih: ioc0: attempting task abort! (sc=ffff8804623e4b40)
Jul  6 13:31:43  user.info kernel: sd 2:0:1:0: [sdb] CDB: cdb[0]=0x12: 12 01 80 00 fe 00
Jul  6 13:31:43  user.info kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff8804623e4b40)
Jul  6 13:31:43  user.warn kernel: Result: hostbyte=0x02 driverbyte=0x00
Jul  6 13:31:43  user.warn kernel: device-mapper: multipath: Failing path 8:16.
Jul  6 13:31:43  daemon.notice multipathd: 8:16: mark as failed
Jul  6 13:31:43  daemon.notice multipathd: encl1Slot2: remaining active paths: 0
Jul  6 13:31:51  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:51  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:51  user.info kernel: mptscsih: ioc0: attempting task abort! (sc=ffff880463a6b680)
Jul  6 13:31:51  user.info kernel: sd 2:0:1:0: [sdb] CDB: 
Jul  6 13:31:51  user.info kernel: cdb[0]=0x12
Jul  6 13:31:51  user.info kernel: : 12
Jul  6 13:31:51  user.info kernel:  01
Jul  6 13:31:51  user.info kernel:  80 00
Jul  6 13:31:51  user.info kernel:  fe 00
Jul  6 13:31:51  user.info kernel: 
Jul  6 13:31:51  user.info kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff880463a6b680)
Jul  6 13:31:59  daemon.notice multipathd: sdn: readsector0 checker reports path is down
Jul  6 13:31:59  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:59  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:31:59  user.info kernel: mptscsih: ioc0: attempting target reset! (sc=ffff8804623e4b40)
Jul  6 13:31:59  user.info kernel: sd 2:0:1:0: [sdb] CDB: cdb[0]=0x12
Jul  6 13:31:59  user.info kernel: : 12
Jul  6 13:31:59  user.info kernel:  01 80
Jul  6 13:31:59  user.info kernel:  00 fe
Jul  6 13:31:59  user.info kernel:  00
Jul  6 13:31:59  user.info kernel: 
Jul  6 13:31:59  user.info kernel: mptscsih: ioc0: target reset: SUCCESS (sc=ffff8804623e4b40)
Jul  6 13:32:07  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:32:07  user.info kernel: mptscsih: ioc0: attempting bus reset! (sc=ffff8804623e4b40)
Jul  6 13:32:07  user.info kernel: sd 2:0:1:0: [sdb] CDB: 
Jul  6 13:32:07  user.info kernel: cdb[0]=0x12
Jul  6 13:32:07  user.info kernel: : 12
Jul  6 13:32:07  user.info kernel:  01
Jul  6 13:32:07  user.info kernel:  80 00
Jul  6 13:32:07  user.info kernel:  fe
Jul  6 13:32:07  user.info kernel:  00
Jul  6 13:32:11  user.info kernel: mptscsih: ioc0: bus reset: SUCCESS (sc=ffff8804623e4b40)
Jul  6 13:32:23  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:32:31  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:32:31  user.info kernel: mptscsih: ioc0: attempting host reset! (sc=ffff8804623e4b40)
Jul  6 13:32:42  user.info kernel: mptscsih: ioc0: host reset: SUCCESS (sc=ffff8804623e4b40)
Jul  6 13:32:43  user.info kernel: mptbase: ioc0: LogInfo(0x30030501): Originator={IOP}, Code={Invalid Page}, SubCode(0x0501)
Jul  6 13:32:43  user.info kernel: mptsas: ioc0: removing ssp device: fw_channel 0, fw_id 27, phy 1, sas_addr 0x5000c5000d298821
Jul  6 13:32:43  user.debug kernel:  phy-2:2:79: mptsas: ioc0: delete phy 1, phy-obj (0xffff88046a5e6800)
Jul  6 13:32:43  user.debug kernel:  port-2:2:1: mptsas: ioc0: delete port 1, sas_addr (0x5000c5000d298821)
Jul  6 13:32:43  user.notice kernel: sd 2:0:1:0: [sdb] Synchronizing SCSI cache
Jul  6 13:32:52  user.info kernel: sd 2:0:1:0: Device offlined - not ready after error recovery
Jul  6 13:32:53  user.info kernel: sd 2:0:1:0: [sdb] md: super_written gets error=-5, uptodate=0
Jul  6 13:32:53  user.alert kernel: raid1: Disk failure on dm-13, disabling device.
Jul  6 13:32:53  user.alert kernel: raid1: Operation continuing on 1 devices.
Jul  6 13:32:53  daemon.notice multipathd: sdb: readsector0 checker reports path is down
Jul  6 13:32:53  user.warn kernel: Result: hostbyte=0x01 driverbyte=0x00
Jul  6 13:32:53  user.info kernel: mptbase: ioc0: LogInfo(0x30030501): Originator={IOP}, Code={Invalid Page}, SubCode(0x0501)
Jul  6 13:32:53  user.warn kernel: RAID1 conf printout:
Jul  6 13:32:53  user.warn kernel:  --- wd:1 rd:2
Jul  6 13:32:53  user.warn kernel:  disk 0, wo:0, o:1, dev:dm-6
Jul  6 13:32:53  user.warn kernel:  disk 1, wo:1, o:0, dev:dm-13
Jul  6 13:32:53  user.warn kernel: RAID1 conf printout:
Jul  6 13:32:53  user.warn kernel:  --- wd:1 rd:2
Jul  6 13:32:53  user.warn kernel:  disk 0, wo:0, o:1, dev:dm-6
Jul  6 13:32:55  daemon.notice multipathd: sdn: readsector0 checker reports path is down
Jul  6 13:32:55  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:33:02  user.info kernel: mptscsih: ioc1: attempting task abort! (sc=ffff880461f6a280)
Jul  6 13:33:02  user.info kernel: sd 3:0:1:0: CDB: 
Jul  6 13:33:02  user.info kernel: cdb[0]=0x12
Jul  6 13:33:02  user.info kernel: :
Jul  6 13:33:02  user.info kernel:  12
Jul  6 13:33:02  user.info kernel:  00 00
Jul  6 13:33:02  user.info kernel:  00 24
Jul  6 13:33:02  user.info kernel:  00
Jul  6 13:33:02  user.info kernel: 
Jul  6 13:33:02  user.info kernel: mptbase: ioc1: LogInfo(0x31130000): Originator={PL}, Code={IO Not Yet Executed}, SubCode(0x0000)
Jul  6 13:33:02  user.info kernel: mptscsih: ioc1: task abort: SUCCESS (sc=ffff880461f6a280)
Jul  6 13:33:03  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:33:03  user.info kernel: mptscsih: ioc1: attempting task abort! (sc=ffff88046c04a000)
Jul  6 13:33:03  user.info kernel: sd 3:0:1:0: [sdn] CDB: 
Jul  6 13:33:03  user.info kernel: cdb[0]=0x12
Jul  6 13:33:03  user.info kernel: : 12
Jul  6 13:33:03  user.info kernel:  01
Jul  6 13:33:03  user.info kernel:  80 00
Jul  6 13:33:03  user.info kernel:  fe
Jul  6 13:33:03  user.info kernel:  00
Jul  6 13:33:03  user.info kernel: 
Jul  6 13:33:03  user.info kernel: mptscsih: ioc1: task abort: SUCCESS (sc=ffff88046c04a000)
Jul  6 13:33:04  user.err kernel: scsi 2:0:1:0: rejecting I/O to dead device
Jul  6 13:33:04  daemon.notice multipathd: sdb: readsector0 checker reports path is down
Jul  6 13:33:11  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:33:11  user.info kernel: mptscsih: ioc1: attempting task abort! (sc=ffff880463a6adc0)
Jul  6 13:33:11  user.info kernel: sd 3:0:1:0: [sdn] CDB: 
Jul  6 13:33:11  user.info kernel: cdb[0]=0x12
Jul  6 13:33:11  user.info kernel: : 12
Jul  6 13:33:11  user.info kernel:  01
Jul  6 13:33:11  user.info kernel:  80 00
Jul  6 13:33:11  user.info kernel:  fe
Jul  6 13:33:11  user.info kernel:  00
Jul  6 13:33:11  user.info kernel: mptscsih: ioc1: task abort: SUCCESS (sc=ffff880463a6adc0)
Jul  6 13:33:19  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:33:19  user.info kernel: mptscsih: ioc1: attempting target reset! (sc=ffff880461f6a280)
Jul  6 13:33:19  user.info kernel: sd 3:0:1:0: CDB: 
Jul  6 13:33:19  user.info kernel: cdb[0]=0x12
Jul  6 13:33:19  user.info kernel: : 12
Jul  6 13:33:19  user.info kernel:  00 00
Jul  6 13:33:19  user.info kernel:  00 24
Jul  6 13:33:19  user.info kernel:  00
Jul  6 13:33:19  user.info kernel: 
Jul  6 13:33:19  user.info kernel: mptscsih: ioc1: target reset: SUCCESS (sc=ffff880461f6a280)
Jul  6 13:33:27  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
Jul  6 13:33:27  user.info kernel: mptscsih: ioc1: attempting bus reset! (sc=ffff880461f6a280)
Jul  6 13:33:27  user.info kernel: sd 3:0:1:0: CDB: 
Jul  6 13:33:27  user.info kernel: cdb[0]=0x12
Jul  6 13:33:27  user.info kernel: :
Jul  6 13:33:27  user.info kernel:  12
Jul  6 13:33:27  user.info kernel:  00
Jul  6 13:33:27  user.info kernel:  24
Jul  6 13:33:27  user.info kernel:  00
Jul  6 13:33:27  user.info kernel: 
Jul  6 13:33:31  user.info kernel: mptscsih: ioc1: bus reset: SUCCESS (sc=ffff880461f6a280)
Jul  6 13:33:42  user.info kernel: mptbase: ioc1: LogInfo(0x31130000): Originator={PL}, Code={IO Not Yet Executed}, SubCode(0x0000)
Jul  6 13:33:42  user.info kernel: mptscsih: ioc1: attempting host reset! (sc=ffff880461f6a280)
Jul  6 13:33:42  user.info kernel: mptsas: ioc1: removing ssp device: fw_channel 0, fw_id 62, phy 1, sas_addr 0x5000c5000d298822
Jul  6 13:33:42  user.debug kernel:  phy-3:2:79: mptsas: ioc1: delete phy 1, phy-obj (0xffff88046de9dc00)
Jul  6 13:33:42  user.debug kernel:  port-3:2:1: mptsas: ioc1: delete port 1, sas_addr (0x5000c5000d298822)
Jul  6 13:33:42  user.notice kernel: sd 3:0:1:0: [sdn] Synchronizing SCSI cache

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Mike Anderson]

Paul Smith <paul@mad-scientist.net> wrote:
> 

I was expecting a little more output from the error handler thread, but
the log does show a few things.

It would be good if in the failing case you could provide a sysrq "t"
output so I could understand where the reset handler is waiting.

It appears there are a few things going on.
1.) The dm deactivate calling blk_abort_queue is leading to error handler
activation. Similar to a previously described issue.
http://permalink.gmane.org/gmane.linux.kernel.device-mapper.devel/8543
	- This kernel does not have DID_TRANSPORT_DISRUPTED so that
	  avoidance method cannot be used.
2.) The task aborts are completing, but the tur is most likely being
failed with a response of DID_BUS_BUSY leading to continued recovery.
3.) We appear to be inside mpt_HardResetHandler, but need more info to
understand where in the call chain.

T
> kernel log output:
> ------------------
> Jul  6 13:31:18  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:18  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:27  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:27  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:35  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:35  user.info kernel: sd 3:0:1:0: [sdn] Result: hostbyte=0x02 driverbyte=0x00
> Jul  6 13:31:35  user.warn kernel: device-mapper: multipath: Failing path 8:208.
> Jul  6 13:31:35  daemon.notice multipathd: 8:208: mark as failed
> Jul  6 13:31:35  daemon.notice multipathd: encl1Slot2: remaining active paths: 1
> Jul  6 13:31:43  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:43  user.info kernel: sd 2:0:1:0: [sdb] <6>mptscsih: ioc0: attempting task abort! (sc=ffff8804623e4b40)
> Jul  6 13:31:43  user.info kernel: sd 2:0:1:0: [sdb] CDB: cdb[0]=0x12: 12 01 80 00 fe 00
> Jul  6 13:31:43  user.info kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff8804623e4b40)
> Jul  6 13:31:43  user.warn kernel: Result: hostbyte=0x02 driverbyte=0x00
> Jul  6 13:31:43  user.warn kernel: device-mapper: multipath: Failing path 8:16.
> Jul  6 13:31:43  daemon.notice multipathd: 8:16: mark as failed
> Jul  6 13:31:43  daemon.notice multipathd: encl1Slot2: remaining active paths: 0
> Jul  6 13:31:51  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:51  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:51  user.info kernel: mptscsih: ioc0: attempting task abort! (sc=ffff880463a6b680)
> Jul  6 13:31:51  user.info kernel: sd 2:0:1:0: [sdb] CDB: 
> Jul  6 13:31:51  user.info kernel: cdb[0]=0x12
> Jul  6 13:31:51  user.info kernel: : 12
> Jul  6 13:31:51  user.info kernel:  01
> Jul  6 13:31:51  user.info kernel:  80 00
> Jul  6 13:31:51  user.info kernel:  fe 00
> Jul  6 13:31:51  user.info kernel: 
> Jul  6 13:31:51  user.info kernel: mptscsih: ioc0: task abort: SUCCESS (sc=ffff880463a6b680)
> Jul  6 13:31:59  daemon.notice multipathd: sdn: readsector0 checker reports path is down
> Jul  6 13:31:59  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:59  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:31:59  user.info kernel: mptscsih: ioc0: attempting target reset! (sc=ffff8804623e4b40)
> Jul  6 13:31:59  user.info kernel: sd 2:0:1:0: [sdb] CDB: cdb[0]=0x12
> Jul  6 13:31:59  user.info kernel: : 12
> Jul  6 13:31:59  user.info kernel:  01 80
> Jul  6 13:31:59  user.info kernel:  00 fe
> Jul  6 13:31:59  user.info kernel:  00
> Jul  6 13:31:59  user.info kernel: 
> Jul  6 13:31:59  user.info kernel: mptscsih: ioc0: target reset: SUCCESS (sc=ffff8804623e4b40)
> Jul  6 13:32:07  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:32:07  user.info kernel: mptscsih: ioc0: attempting bus reset! (sc=ffff8804623e4b40)
> Jul  6 13:32:07  user.info kernel: sd 2:0:1:0: [sdb] CDB: 
> Jul  6 13:32:07  user.info kernel: cdb[0]=0x12
> Jul  6 13:32:07  user.info kernel: : 12
> Jul  6 13:32:07  user.info kernel:  01
> Jul  6 13:32:07  user.info kernel:  80 00
> Jul  6 13:32:07  user.info kernel:  fe
> Jul  6 13:32:07  user.info kernel:  00
> Jul  6 13:32:11  user.info kernel: mptscsih: ioc0: bus reset: SUCCESS (sc=ffff8804623e4b40)
> Jul  6 13:32:23  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:32:31  user.info kernel: mptbase: ioc0: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:32:31  user.info kernel: mptscsih: ioc0: attempting host reset! (sc=ffff8804623e4b40)
> Jul  6 13:32:42  user.info kernel: mptscsih: ioc0: host reset: SUCCESS (sc=ffff8804623e4b40)
> Jul  6 13:32:43  user.info kernel: mptbase: ioc0: LogInfo(0x30030501): Originator={IOP}, Code={Invalid Page}, SubCode(0x0501)
> Jul  6 13:32:43  user.info kernel: mptsas: ioc0: removing ssp device: fw_channel 0, fw_id 27, phy 1, sas_addr 0x5000c5000d298821
> Jul  6 13:32:43  user.debug kernel:  phy-2:2:79: mptsas: ioc0: delete phy 1, phy-obj (0xffff88046a5e6800)
> Jul  6 13:32:43  user.debug kernel:  port-2:2:1: mptsas: ioc0: delete port 1, sas_addr (0x5000c5000d298821)
> Jul  6 13:32:43  user.notice kernel: sd 2:0:1:0: [sdb] Synchronizing SCSI cache
> Jul  6 13:32:52  user.info kernel: sd 2:0:1:0: Device offlined - not ready after error recovery
> Jul  6 13:32:53  user.info kernel: sd 2:0:1:0: [sdb] md: super_written gets error=-5, uptodate=0
> Jul  6 13:32:53  user.alert kernel: raid1: Disk failure on dm-13, disabling device.
> Jul  6 13:32:53  user.alert kernel: raid1: Operation continuing on 1 devices.
> Jul  6 13:32:53  daemon.notice multipathd: sdb: readsector0 checker reports path is down
> Jul  6 13:32:53  user.warn kernel: Result: hostbyte=0x01 driverbyte=0x00
> Jul  6 13:32:53  user.info kernel: mptbase: ioc0: LogInfo(0x30030501): Originator={IOP}, Code={Invalid Page}, SubCode(0x0501)
> Jul  6 13:32:53  user.warn kernel: RAID1 conf printout:
> Jul  6 13:32:53  user.warn kernel:  --- wd:1 rd:2
> Jul  6 13:32:53  user.warn kernel:  disk 0, wo:0, o:1, dev:dm-6
> Jul  6 13:32:53  user.warn kernel:  disk 1, wo:1, o:0, dev:dm-13
> Jul  6 13:32:53  user.warn kernel: RAID1 conf printout:
> Jul  6 13:32:53  user.warn kernel:  --- wd:1 rd:2
> Jul  6 13:32:53  user.warn kernel:  disk 0, wo:0, o:1, dev:dm-6
> Jul  6 13:32:55  daemon.notice multipathd: sdn: readsector0 checker reports path is down
> Jul  6 13:32:55  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:33:02  user.info kernel: mptscsih: ioc1: attempting task abort! (sc=ffff880461f6a280)
> Jul  6 13:33:02  user.info kernel: sd 3:0:1:0: CDB: 
> Jul  6 13:33:02  user.info kernel: cdb[0]=0x12
> Jul  6 13:33:02  user.info kernel: :
> Jul  6 13:33:02  user.info kernel:  12
> Jul  6 13:33:02  user.info kernel:  00 00
> Jul  6 13:33:02  user.info kernel:  00 24
> Jul  6 13:33:02  user.info kernel:  00
> Jul  6 13:33:02  user.info kernel: 
> Jul  6 13:33:02  user.info kernel: mptbase: ioc1: LogInfo(0x31130000): Originator={PL}, Code={IO Not Yet Executed}, SubCode(0x0000)
> Jul  6 13:33:02  user.info kernel: mptscsih: ioc1: task abort: SUCCESS (sc=ffff880461f6a280)
> Jul  6 13:33:03  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:33:03  user.info kernel: mptscsih: ioc1: attempting task abort! (sc=ffff88046c04a000)
> Jul  6 13:33:03  user.info kernel: sd 3:0:1:0: [sdn] CDB: 
> Jul  6 13:33:03  user.info kernel: cdb[0]=0x12
> Jul  6 13:33:03  user.info kernel: : 12
> Jul  6 13:33:03  user.info kernel:  01
> Jul  6 13:33:03  user.info kernel:  80 00
> Jul  6 13:33:03  user.info kernel:  fe
> Jul  6 13:33:03  user.info kernel:  00
> Jul  6 13:33:03  user.info kernel: 
> Jul  6 13:33:03  user.info kernel: mptscsih: ioc1: task abort: SUCCESS (sc=ffff88046c04a000)
> Jul  6 13:33:04  user.err kernel: scsi 2:0:1:0: rejecting I/O to dead device
> Jul  6 13:33:04  daemon.notice multipathd: sdb: readsector0 checker reports path is down
> Jul  6 13:33:11  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:33:11  user.info kernel: mptscsih: ioc1: attempting task abort! (sc=ffff880463a6adc0)
> Jul  6 13:33:11  user.info kernel: sd 3:0:1:0: [sdn] CDB: 
> Jul  6 13:33:11  user.info kernel: cdb[0]=0x12
> Jul  6 13:33:11  user.info kernel: : 12
> Jul  6 13:33:11  user.info kernel:  01
> Jul  6 13:33:11  user.info kernel:  80 00
> Jul  6 13:33:11  user.info kernel:  fe
> Jul  6 13:33:11  user.info kernel:  00
> Jul  6 13:33:11  user.info kernel: mptscsih: ioc1: task abort: SUCCESS (sc=ffff880463a6adc0)
> Jul  6 13:33:19  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:33:19  user.info kernel: mptscsih: ioc1: attempting target reset! (sc=ffff880461f6a280)
> Jul  6 13:33:19  user.info kernel: sd 3:0:1:0: CDB: 
> Jul  6 13:33:19  user.info kernel: cdb[0]=0x12
> Jul  6 13:33:19  user.info kernel: : 12
> Jul  6 13:33:19  user.info kernel:  00 00
> Jul  6 13:33:19  user.info kernel:  00 24
> Jul  6 13:33:19  user.info kernel:  00
> Jul  6 13:33:19  user.info kernel: 
> Jul  6 13:33:19  user.info kernel: mptscsih: ioc1: target reset: SUCCESS (sc=ffff880461f6a280)
> Jul  6 13:33:27  user.info kernel: mptbase: ioc1: LogInfo(0x31170000): Originator={PL}, Code={IO Device Missing Delay Retry}, SubCode(0x0000)
> Jul  6 13:33:27  user.info kernel: mptscsih: ioc1: attempting bus reset! (sc=ffff880461f6a280)
> Jul  6 13:33:27  user.info kernel: sd 3:0:1:0: CDB: 
> Jul  6 13:33:27  user.info kernel: cdb[0]=0x12
> Jul  6 13:33:27  user.info kernel: :
> Jul  6 13:33:27  user.info kernel:  12
> Jul  6 13:33:27  user.info kernel:  00
> Jul  6 13:33:27  user.info kernel:  24
> Jul  6 13:33:27  user.info kernel:  00
> Jul  6 13:33:27  user.info kernel: 
> Jul  6 13:33:31  user.info kernel: mptscsih: ioc1: bus reset: SUCCESS (sc=ffff880461f6a280)
> Jul  6 13:33:42  user.info kernel: mptbase: ioc1: LogInfo(0x31130000): Originator={PL}, Code={IO Not Yet Executed}, SubCode(0x0000)
> Jul  6 13:33:42  user.info kernel: mptscsih: ioc1: attempting host reset! (sc=ffff880461f6a280)
> Jul  6 13:33:42  user.info kernel: mptsas: ioc1: removing ssp device: fw_channel 0, fw_id 62, phy 1, sas_addr 0x5000c5000d298822
> Jul  6 13:33:42  user.debug kernel:  phy-3:2:79: mptsas: ioc1: delete phy 1, phy-obj (0xffff88046de9dc00)
> Jul  6 13:33:42  user.debug kernel:  port-3:2:1: mptsas: ioc1: delete port 1, sas_addr (0x5000c5000d298822)
> Jul  6 13:33:42  user.notice kernel: sd 3:0:1:0: [sdn] Synchronizing SCSI cache
> 
> 
> 

-andmike
--
Michael Anderson
andmike@linux.vnet.ibm.com

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[James Bottomley]

On Mon, 2009-07-06 at 23:25 -0700, Mike Anderson wrote:
> Paul Smith <paul@mad-scientist.net> wrote:
> > 
> 
> I was expecting a little more output from the error handler thread, but
> the log does show a few things.
> 
> It would be good if in the failing case you could provide a sysrq "t"
> output so I could understand where the reset handler is waiting.
> 
> It appears there are a few things going on.
> 1.) The dm deactivate calling blk_abort_queue is leading to error handler
> activation. Similar to a previously described issue.
> http://permalink.gmane.org/gmane.linux.kernel.device-mapper.devel/8543
> 	- This kernel does not have DID_TRANSPORT_DISRUPTED so that
> 	  avoidance method cannot be used.
> 2.) The task aborts are completing, but the tur is most likely being
> failed with a response of DID_BUS_BUSY leading to continued recovery.
> 3.) We appear to be inside mpt_HardResetHandler, but need more info to
> understand where in the call chain.

Actually, isn't the problem much simpler?

The mptsas driver calls sas_port_delete() when the event occurs.  This
deletes the rphy and invokes scsi_remove_target().  It looks like the
device had a write back cache, so part of scsi_remove_target() goes to
scsi_remove_device() which triggers sd_remove() which tries to flush the
cache with SYNCHRONIZE CACHE.

This is the point at which the hang occurs.  It seems that the mptsas
goes out to lunch when it sees a command to a device on a deleted port.
The remainder of the log is error handling trying to get the attention
of the mptsas firmware back again.

This is a pretty huge problem because any set of commands can be racing
with surprise ejection ... there's no way we can gate it in the mid
layer.  The behaviour we expect is that after surprise ejection, a
driver/device will automatically error (with something like
DID_NO_CONNECT) all commands for the ejected device.

James

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Paul Smith]

Hi James; thanks for that examination; it's very helpful.

Unfortunately Eric is on vacation until the middle of the month and we
really need to resolve this issue this week if possible.  I'm forwarding
your message to the LSI developers we've been working with.

MikeA: we're working on getting the sysrq "t" output in the meantime,
just in case it's revealing.

On Tue, 2009-07-07 at 08:58 -0500, James Bottomley wrote:
> On Mon, 2009-07-06 at 23:25 -0700, Mike Anderson wrote:
> > Paul Smith <paul@mad-scientist.net> wrote:
> > > 
> > 
> > I was expecting a little more output from the error handler thread, but
> > the log does show a few things.
> > 
> > It would be good if in the failing case you could provide a sysrq "t"
> > output so I could understand where the reset handler is waiting.
> > 
> > It appears there are a few things going on.
> > 1.) The dm deactivate calling blk_abort_queue is leading to error handler
> > activation. Similar to a previously described issue.
> > http://permalink.gmane.org/gmane.linux.kernel.device-mapper.devel/8543
> > 	- This kernel does not have DID_TRANSPORT_DISRUPTED so that
> > 	  avoidance method cannot be used.
> > 2.) The task aborts are completing, but the tur is most likely being
> > failed with a response of DID_BUS_BUSY leading to continued recovery.
> > 3.) We appear to be inside mpt_HardResetHandler, but need more info to
> > understand where in the call chain.
> 
> Actually, isn't the problem much simpler?
> 
> The mptsas driver calls sas_port_delete() when the event occurs.  This
> deletes the rphy and invokes scsi_remove_target().  It looks like the
> device had a write back cache, so part of scsi_remove_target() goes to
> scsi_remove_device() which triggers sd_remove() which tries to flush the
> cache with SYNCHRONIZE CACHE.
> 
> This is the point at which the hang occurs.  It seems that the mptsas
> goes out to lunch when it sees a command to a device on a deleted port.
> The remainder of the log is error handling trying to get the attention
> of the mptsas firmware back again.
> 
> This is a pretty huge problem because any set of commands can be racing
> with surprise ejection ... there's no way we can gate it in the mid
> layer.  The behaviour we expect is that after surprise ejection, a
> driver/device will automatically error (with something like
> DID_NO_CONNECT) all commands for the ejected device.
> 
> James
> 
> 

RE: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Desai, Kashyap]

Regarding Jame's comment I want to add some info.
When we enter sd_remove() which tries to flush the
cache with SYNCHRONIZE CACHE We are seeing system hung. In my guess, MPT driver is not even receiving command for synchronize cache. (If I refer back trace provided in first mail, scsi_dispatch_cmd() might not be called. Back trace suggests hang in scsi_get_command() just before scsi_dispatch_cmd() )
 

Even if synchronize cache command reaches to mptsas, mptsas will return with DID_NO_CONNECT since hostdata is no more valid. 
Here is snippet of mptsas code.

------------------------------------------------------
mptsas_qcmd(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_cmnd *))
{
        VirtDevice      *vdevice = SCpnt->device->hostdata;
 
        if (!vdevice || !vdevice->vtarget || vdevice->vtarget->deleted) {
                SCpnt->result = DID_NO_CONNECT << 16;
                done(SCpnt);
                return 0;
        }
------------------------------------------------------
Thanks,
Kashyap

-----Original Message-----
From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-owner@vger.kernel.org] On Behalf Of Paul Smith
Sent: Tuesday, July 07, 2009 8:04 PM
To: James Bottomley
Cc: Mike Anderson; linux-scsi@vger.kernel.org; Mike Christie; Moore, Eric
Subject: Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

Hi James; thanks for that examination; it's very helpful.

Unfortunately Eric is on vacation until the middle of the month and we
really need to resolve this issue this week if possible.  I'm forwarding
your message to the LSI developers we've been working with.

MikeA: we're working on getting the sysrq "t" output in the meantime,
just in case it's revealing.

On Tue, 2009-07-07 at 08:58 -0500, James Bottomley wrote:
> On Mon, 2009-07-06 at 23:25 -0700, Mike Anderson wrote:
> > Paul Smith <paul@mad-scientist.net> wrote:
> > > 
> > 
> > I was expecting a little more output from the error handler thread, but
> > the log does show a few things.
> > 
> > It would be good if in the failing case you could provide a sysrq "t"
> > output so I could understand where the reset handler is waiting.
> > 
> > It appears there are a few things going on.
> > 1.) The dm deactivate calling blk_abort_queue is leading to error handler
> > activation. Similar to a previously described issue.
> > http://permalink.gmane.org/gmane.linux.kernel.device-mapper.devel/8543
> > 	- This kernel does not have DID_TRANSPORT_DISRUPTED so that
> > 	  avoidance method cannot be used.
> > 2.) The task aborts are completing, but the tur is most likely being
> > failed with a response of DID_BUS_BUSY leading to continued recovery.
> > 3.) We appear to be inside mpt_HardResetHandler, but need more info to
> > understand where in the call chain.
> 
> Actually, isn't the problem much simpler?
> 
> The mptsas driver calls sas_port_delete() when the event occurs.  This
> deletes the rphy and invokes scsi_remove_target().  It looks like the
> device had a write back cache, so part of scsi_remove_target() goes to
> scsi_remove_device() which triggers sd_remove() which tries to flush the
> cache with SYNCHRONIZE CACHE.
> 
> This is the point at which the hang occurs.  It seems that the mptsas
> goes out to lunch when it sees a command to a device on a deleted port.
> The remainder of the log is error handling trying to get the attention
> of the mptsas firmware back again.
> 
> This is a pretty huge problem because any set of commands can be racing
> with surprise ejection ... there's no way we can gate it in the mid
> layer.  The behaviour we expect is that after surprise ejection, a
> driver/device will automatically error (with something like
> DID_NO_CONNECT) all commands for the ejected device.
> 
> James
> 
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Mike Anderson]

Desai, Kashyap <Kashyap.Desai@lsi.com> wrote:
> Regarding Jame's comment I want to add some info.
> When we enter sd_remove() which tries to flush the
> cache with SYNCHRONIZE CACHE We are seeing system hung. In my guess, MPT driver is not even receiving command for synchronize cache. (If I refer back trace provided in first mail, scsi_dispatch_cmd() might not be called. Back trace suggests hang in scsi_get_command() just before scsi_dispatch_cmd() )
>  
> 
The SYNCHRONIZE CACHE is blocked by the host being in error recovery.
Since the SYNCHRONIZE CACHE is being driven off the mpt work queue it will
block the scsi error handler thread from completing as the
mptscsih_host_reset leads to calling flush_workqueue which leads to this
deadlock.

In my previous email I listed the lead up events. 

We start with blk_abort_queue scheduling error recovery (Issue previous reported). In theory the hang issue could occur in other error handler / device delete scenarios, but with much less probability. The Linux version also does not contain support for DID_TRANSPORT_DISRUPTED so this work around cannot be used.

The second issue is that we continue through progressive error handling
steps when we do not need to as we believe the device needs further error
recovery. Leading the host reset routine being called.

> Even if synchronize cache command reaches to mptsas, mptsas will return with DID_NO_CONNECT since hostdata is no more valid. 
> Here is snippet of mptsas code.
> 
> ------------------------------------------------------
> mptsas_qcmd(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_cmnd *))
> {
>         VirtDevice      *vdevice = SCpnt->device->hostdata;
>  
>         if (!vdevice || !vdevice->vtarget || vdevice->vtarget->deleted) {
>                 SCpnt->result = DID_NO_CONNECT << 16;
>                 done(SCpnt);
>                 return 0;
>         }
> ------------------------------------------------------
> Thanks,
> Kashyap
> 
> -----Original Message-----
> From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-owner@vger.kernel.org] On Behalf Of Paul Smith
> Sent: Tuesday, July 07, 2009 8:04 PM
> To: James Bottomley
> Cc: Mike Anderson; linux-scsi@vger.kernel.org; Mike Christie; Moore, Eric
> Subject: Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?
> 
> Hi James; thanks for that examination; it's very helpful.
> 
> Unfortunately Eric is on vacation until the middle of the month and we
> really need to resolve this issue this week if possible.  I'm forwarding
> your message to the LSI developers we've been working with.
> 
> MikeA: we're working on getting the sysrq "t" output in the meantime,
> just in case it's revealing.
> 
> On Tue, 2009-07-07 at 08:58 -0500, James Bottomley wrote:
> > On Mon, 2009-07-06 at 23:25 -0700, Mike Anderson wrote:
> > > Paul Smith <paul@mad-scientist.net> wrote:
> > > > 
> > > 
> > > I was expecting a little more output from the error handler thread, but
> > > the log does show a few things.
> > > 
> > > It would be good if in the failing case you could provide a sysrq "t"
> > > output so I could understand where the reset handler is waiting.
> > > 
> > > It appears there are a few things going on.
> > > 1.) The dm deactivate calling blk_abort_queue is leading to error handler
> > > activation. Similar to a previously described issue.
> > > http://permalink.gmane.org/gmane.linux.kernel.device-mapper.devel/8543
> > > 	- This kernel does not have DID_TRANSPORT_DISRUPTED so that
> > > 	  avoidance method cannot be used.
> > > 2.) The task aborts are completing, but the tur is most likely being
> > > failed with a response of DID_BUS_BUSY leading to continued recovery.
> > > 3.) We appear to be inside mpt_HardResetHandler, but need more info to
> > > understand where in the call chain.
> > 
> > Actually, isn't the problem much simpler?
> > 
> > The mptsas driver calls sas_port_delete() when the event occurs.  This
> > deletes the rphy and invokes scsi_remove_target().  It looks like the
> > device had a write back cache, so part of scsi_remove_target() goes to
> > scsi_remove_device() which triggers sd_remove() which tries to flush the
> > cache with SYNCHRONIZE CACHE.
> > 
> > This is the point at which the hang occurs.  It seems that the mptsas
> > goes out to lunch when it sees a command to a device on a deleted port.
> > The remainder of the log is error handling trying to get the attention
> > of the mptsas firmware back again.
> > 
> > This is a pretty huge problem because any set of commands can be racing
> > with surprise ejection ... there's no way we can gate it in the mid
> > layer.  The behaviour we expect is that after surprise ejection, a
> > driver/device will automatically error (with something like
> > DID_NO_CONNECT) all commands for the ejected device.
> > 
> > James
> > 
> > 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

-andmike
--
Michael Anderson
andmike@linux.vnet.ibm.com

Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Mike Anderson]

Mike Anderson <andmike@linux.vnet.ibm.com> wrote:
> Desai, Kashyap <Kashyap.Desai@lsi.com> wrote:
> > Regarding Jame's comment I want to add some info.
> > When we enter sd_remove() which tries to flush the
> > cache with SYNCHRONIZE CACHE We are seeing system hung. In my guess, MPT driver is not even receiving command for synchronize cache. (If I refer back trace provided in first mail, scsi_dispatch_cmd() might not be called. Back trace suggests hang in scsi_get_command() just before scsi_dispatch_cmd() )
> >  
> > 
> The SYNCHRONIZE CACHE is blocked by the host being in error recovery.
> Since the SYNCHRONIZE CACHE is being driven off the mpt work queue it will
> block the scsi error handler thread from completing as the
> mptscsih_host_reset leads to calling flush_workqueue which leads to this
> deadlock.
> 
> In my previous email I listed the lead up events. 
> 
> We start with blk_abort_queue scheduling error recovery (Issue previous reported). In theory the hang issue could occur in other error handler / device delete scenarios, but with much less probability. The Linux version also does not contain support for DID_TRANSPORT_DISRUPTED so this work around cannot be used.
> 

One solution would be to correct the problem of blk_abort_queue getting
called in these transport cases. I wanted to try and utilize the request
information now that we have request based dm-mp (and once we settle on a
proper mapping of the codes) , but that would not be an option in this
kernel. A short term solution could also be looked into.

Another option it appears would be to return DID_IMM_RETRY instead of
DID_BUS_BUSY in fusion/mptscsih.c (SAS_LOGINFO_NEXUS_LOSS). It appears
that this could come close to DID_TRANSPORT_DISRUPTED behavior in this
kernel release.

Or we can continue to look into solutions of not dead locking in recovery.

> The second issue is that we continue through progressive error handling
> steps when we do not need to as we believe the device needs further error
> recovery. Leading the host reset routine being called.
> 
> > Even if synchronize cache command reaches to mptsas, mptsas will return with DID_NO_CONNECT since hostdata is no more valid. 
> > Here is snippet of mptsas code.
> > 
> > ------------------------------------------------------
> > mptsas_qcmd(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_cmnd *))
> > {
> >         VirtDevice      *vdevice = SCpnt->device->hostdata;
> >  
> >         if (!vdevice || !vdevice->vtarget || vdevice->vtarget->deleted) {
> >                 SCpnt->result = DID_NO_CONNECT << 16;
> >                 done(SCpnt);
> >                 return 0;
> >         }
> > ------------------------------------------------------
> > Thanks,
> > Kashyap
> > 
> > -----Original Message-----
> > From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-owner@vger.kernel.org] On Behalf Of Paul Smith
> > Sent: Tuesday, July 07, 2009 8:04 PM
> > To: James Bottomley
> > Cc: Mike Anderson; linux-scsi@vger.kernel.org; Mike Christie; Moore, Eric
> > Subject: Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?
> > 
> > Hi James; thanks for that examination; it's very helpful.
> > 
> > Unfortunately Eric is on vacation until the middle of the month and we
> > really need to resolve this issue this week if possible.  I'm forwarding
> > your message to the LSI developers we've been working with.
> > 
> > MikeA: we're working on getting the sysrq "t" output in the meantime,
> > just in case it's revealing.
> > 
> > On Tue, 2009-07-07 at 08:58 -0500, James Bottomley wrote:
> > > On Mon, 2009-07-06 at 23:25 -0700, Mike Anderson wrote:
> > > > Paul Smith <paul@mad-scientist.net> wrote:
> > > > > 
> > > > 
> > > > I was expecting a little more output from the error handler thread, but
> > > > the log does show a few things.
> > > > 
> > > > It would be good if in the failing case you could provide a sysrq "t"
> > > > output so I could understand where the reset handler is waiting.
> > > > 
> > > > It appears there are a few things going on.
> > > > 1.) The dm deactivate calling blk_abort_queue is leading to error handler
> > > > activation. Similar to a previously described issue.
> > > > http://permalink.gmane.org/gmane.linux.kernel.device-mapper.devel/8543
> > > > 	- This kernel does not have DID_TRANSPORT_DISRUPTED so that
> > > > 	  avoidance method cannot be used.
> > > > 2.) The task aborts are completing, but the tur is most likely being
> > > > failed with a response of DID_BUS_BUSY leading to continued recovery.
> > > > 3.) We appear to be inside mpt_HardResetHandler, but need more info to
> > > > understand where in the call chain.
> > > 
> > > Actually, isn't the problem much simpler?
> > > 
> > > The mptsas driver calls sas_port_delete() when the event occurs.  This
> > > deletes the rphy and invokes scsi_remove_target().  It looks like the
> > > device had a write back cache, so part of scsi_remove_target() goes to
> > > scsi_remove_device() which triggers sd_remove() which tries to flush the
> > > cache with SYNCHRONIZE CACHE.
> > > 
> > > This is the point at which the hang occurs.  It seems that the mptsas
> > > goes out to lunch when it sees a command to a device on a deleted port.
> > > The remainder of the log is error handling trying to get the attention
> > > of the mptsas firmware back again.
> > > 
> > > This is a pretty huge problem because any set of commands can be racing
> > > with surprise ejection ... there's no way we can gate it in the mid
> > > layer.  The behaviour we expect is that after surprise ejection, a
> > > driver/device will automatically error (with something like
> > > DID_NO_CONNECT) all commands for the ejected device.
> > > 
> > > James
> > > 
> > > 
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> -andmike
> --
> Michael Anderson
> andmike@linux.vnet.ibm.com
> --
> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

-andmike
--
Michael Anderson
andmike@linux.vnet.ibm.com

RE: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

[Desai, Kashyap]

Yes we have alternate solution which will not lead deadlock with SCSI midlayer. I will send patch for this solution. Firewall at my network is not allowing connecting mutt client. Once I have access to mutt client I will post patch for this issue.

Thanks,
Kashyap

-----Original Message-----
From: Mike Anderson [mailto:andmike@linux.vnet.ibm.com] 
Sent: Wednesday, July 08, 2009 2:40 AM
To: Desai, Kashyap
Cc: paul@mad-scientist.net; James Bottomley; linux-scsi@vger.kernel.org; Mike Christie; Moore, Eric
Subject: Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?

Mike Anderson <andmike@linux.vnet.ibm.com> wrote:
> Desai, Kashyap <Kashyap.Desai@lsi.com> wrote:
> > Regarding Jame's comment I want to add some info.
> > When we enter sd_remove() which tries to flush the
> > cache with SYNCHRONIZE CACHE We are seeing system hung. In my guess, MPT driver is not even receiving command for synchronize cache. (If I refer back trace provided in first mail, scsi_dispatch_cmd() might not be called. Back trace suggests hang in scsi_get_command() just before scsi_dispatch_cmd() )
> >  
> > 
> The SYNCHRONIZE CACHE is blocked by the host being in error recovery.
> Since the SYNCHRONIZE CACHE is being driven off the mpt work queue it will
> block the scsi error handler thread from completing as the
> mptscsih_host_reset leads to calling flush_workqueue which leads to this
> deadlock.
> 
> In my previous email I listed the lead up events. 
> 
> We start with blk_abort_queue scheduling error recovery (Issue previous reported). In theory the hang issue could occur in other error handler / device delete scenarios, but with much less probability. The Linux version also does not contain support for DID_TRANSPORT_DISRUPTED so this work around cannot be used.
> 

One solution would be to correct the problem of blk_abort_queue getting
called in these transport cases. I wanted to try and utilize the request
information now that we have request based dm-mp (and once we settle on a
proper mapping of the codes) , but that would not be an option in this
kernel. A short term solution could also be looked into.

Another option it appears would be to return DID_IMM_RETRY instead of
DID_BUS_BUSY in fusion/mptscsih.c (SAS_LOGINFO_NEXUS_LOSS). It appears
that this could come close to DID_TRANSPORT_DISRUPTED behavior in this
kernel release.

Or we can continue to look into solutions of not dead locking in recovery.

> The second issue is that we continue through progressive error handling
> steps when we do not need to as we believe the device needs further error
> recovery. Leading the host reset routine being called.
> 
> > Even if synchronize cache command reaches to mptsas, mptsas will return with DID_NO_CONNECT since hostdata is no more valid. 
> > Here is snippet of mptsas code.
> > 
> > ------------------------------------------------------
> > mptsas_qcmd(struct scsi_cmnd *SCpnt, void (*done)(struct scsi_cmnd *))
> > {
> >         VirtDevice      *vdevice = SCpnt->device->hostdata;
> >  
> >         if (!vdevice || !vdevice->vtarget || vdevice->vtarget->deleted) {
> >                 SCpnt->result = DID_NO_CONNECT << 16;
> >                 done(SCpnt);
> >                 return 0;
> >         }
> > ------------------------------------------------------
> > Thanks,
> > Kashyap
> > 
> > -----Original Message-----
> > From: linux-scsi-owner@vger.kernel.org [mailto:linux-scsi-owner@vger.kernel.org] On Behalf Of Paul Smith
> > Sent: Tuesday, July 07, 2009 8:04 PM
> > To: James Bottomley
> > Cc: Mike Anderson; linux-scsi@vger.kernel.org; Mike Christie; Moore, Eric
> > Subject: Re: [2.6.27.25] Hang in SCSI sync cache when a disk is removed--?
> > 
> > Hi James; thanks for that examination; it's very helpful.
> > 
> > Unfortunately Eric is on vacation until the middle of the month and we
> > really need to resolve this issue this week if possible.  I'm forwarding
> > your message to the LSI developers we've been working with.
> > 
> > MikeA: we're working on getting the sysrq "t" output in the meantime,
> > just in case it's revealing.
> > 
> > On Tue, 2009-07-07 at 08:58 -0500, James Bottomley wrote:
> > > On Mon, 2009-07-06 at 23:25 -0700, Mike Anderson wrote:
> > > > Paul Smith <paul@mad-scientist.net> wrote:
> > > > > 
> > > > 
> > > > I was expecting a little more output from the error handler thread, but
> > > > the log does show a few things.
> > > > 
> > > > It would be good if in the failing case you could provide a sysrq "t"
> > > > output so I could understand where the reset handler is waiting.
> > > > 
> > > > It appears there are a few things going on.
> > > > 1.) The dm deactivate calling blk_abort_queue is leading to error handler
> > > > activation. Similar to a previously described issue.
> > > > http://permalink.gmane.org/gmane.linux.kernel.device-mapper.devel/8543
> > > > 	- This kernel does not have DID_TRANSPORT_DISRUPTED so that
> > > > 	  avoidance method cannot be used.
> > > > 2.) The task aborts are completing, but the tur is most likely being
> > > > failed with a response of DID_BUS_BUSY leading to continued recovery.
> > > > 3.) We appear to be inside mpt_HardResetHandler, but need more info to
> > > > understand where in the call chain.
> > > 
> > > Actually, isn't the problem much simpler?
> > > 
> > > The mptsas driver calls sas_port_delete() when the event occurs.  This
> > > deletes the rphy and invokes scsi_remove_target().  It looks like the
> > > device had a write back cache, so part of scsi_remove_target() goes to
> > > scsi_remove_device() which triggers sd_remove() which tries to flush the
> > > cache with SYNCHRONIZE CACHE.
> > > 
> > > This is the point at which the hang occurs.  It seems that the mptsas
> > > goes out to lunch when it sees a command to a device on a deleted port.
> > > The remainder of the log is error handling trying to get the attention
> > > of the mptsas firmware back again.
> > > 
> > > This is a pretty huge problem because any set of commands can be racing
> > > with surprise ejection ... there's no way we can gate it in the mid
> > > layer.  The behaviour we expect is that after surprise ejection, a
> > > driver/device will automatically error (with something like
> > > DID_NO_CONNECT) all commands for the ejected device.
> > > 
> > > James
> > > 
> > > 
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> -andmike
> --
> Michael Anderson
> andmike@linux.vnet.ibm.com
> --
> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

-andmike
--
Michael Anderson
andmike@linux.vnet.ibm.com