Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Alejandro Riveira Fernández]

El Wed, 6 Apr 2011 15:57:06 +0100
Bruce Stenning <b.stenning@indigovision.com> escribió:


 Just CCing linux-ide

> Please accept my most humble apologies for the lack of line breaks in
> my previous email.  Here it is again, this time in a more readable
> format:
> 
> Hello,
> 
> We have a bespoke platform utilising a Marvell MV88SX6041 SATA controller
> on which we have been running Linux 2.6.26 and using the sata_mv driver.
> 
> We have noticed problems with SATA ports occasionally locking up (on
> hotplug events) and remaining unresponsive.  The normal kernel logging
> that occurs on hotplug events is no longer emitted for the locked ports
> (but will be emitted for the other sata ports that have not exhibited
> the problem.)  The disks attached to the locked ports are completely
> unresponsive.  The condition can be cleared by removing the sata_mv
> kernel module from memory and reloading it, after which the kernel
> logging becomes active (and the disks are usable) for all ports.
> 
> The following changeset was seen as a strong candidate for addressing
> this problem:
> 
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=933cb8e5fcdebd4b666165e3f039f814d62b0e52
> 
> We are now in the process of upgrading to the stable 2.6.38.2 kernel
> release, but initial testing of this on our platform exhibits the same
> hotplug behaviour.  Hotplug is possible, but occasionally the ports
> will lock up and not be responsive until sata_mv is removed and
> reinstalled.  Other than this, the new kernel and driver seem to be
> operating normally.
> 
> Has this problem been observed elsewhere with kernels that include the
> above patch?  Please CC me in replies.
> 
> Kind Regards,
> 
> Bruce Stenning,
> IndigoVision,
> b <dot> stenning <at> indigovision <dot> com
> 
> 
> Latest News at: http://www.indigovision.com/news2011.php
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Hi Mark,

> On 11-04-06 10:57 AM, Bruce Stenning wrote:
> > [...]
> >
> > The following changeset was seen as a strong candidate for addressing
> > this problem:
> >
> > http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=933cb8e5fcdebd4b666165e3f039f814d62b0e52
>
> That changeset is already in upstream kernels (kernel.org).
> Does the latest kernel (2.6.38) w/ sata_mv work ?

The 2.6.38.2 kernel still exhibits the same lockups that we see with the
2.6.26 kernel.

Alejandro Riveira Fernández kindly forwarded my email to the linux-ide list,
so I shall take the discussion there and away from the main kernel list.


Kind Regards,

Bruce Stenning,
IndigoVision,
b <dot> stenning <at> indigovision <dot> com


Latest News at: http://www.indigovision.com/news2011.php

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-08 08:43 AM, Bruce Stenning wrote:
> Hi Mark,
> 
>> On 11-04-06 10:57 AM, Bruce Stenning wrote:
>>> [...]
>>>
>>> The following changeset was seen as a strong candidate for addressing
>>> this problem:
>>>
>>> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commitdiff;h=933cb8e5fcdebd4b666165e3f039f814d62b0e52
>>
>> That changeset is already in upstream kernels (kernel.org).
>> Does the latest kernel (2.6.38) w/ sata_mv work ?
> 
> The 2.6.38.2 kernel still exhibits the same lockups that we see with the
> 2.6.26 kernel.

Okay.  Just to help narrow it down a bit, how does 2.6.32 behave ?

Thanks.

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> > The 2.6.38.2 kernel still exhibits the same lockups that we see with the
> > 2.6.26 kernel.
>
> Okay.  Just to help narrow it down a bit, how does 2.6.32 behave ?
>
> Thanks.

Hi Mark,

I have reproduced the issue with the 2.6.32 kernel.

In case it is of use, the silicon is rev 09 (i.e. C0 stepping) and I am using
gcc 4.4.2 to build the kernel and modules.

I am currently inserting tracing into 2.6.38.2 to try to work out what is going
on.  From mv_write_main_irq_mask I can see that the IRQ for each port is still
enabled, even when ports stop responding.  I see interrupts generated when I
hotplug or unplug disks on ports that are not locked up, but no interrupt is
generated at all for the ports that are locked (this is from tracing in
asm_do_IRQ in arch/arm/kernel/irq.c)

One thing I noticed was that there is no spinlock around the
mv_save_cached_regs/mv_edma_cfg in mv_hardreset (unlike mv_port_start and
mv_port_stop); why is this?


Kind Regards,

Bruce Stenning,
IndigoVision,
b <dot> stenning <at> indigovision <dot> com


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-12 06:30 AM, Bruce Stenning wrote:
>
> I have reproduced the issue with the 2.6.32 kernel.

Perfect.  This means that it probably wasn't broken by somebody else
since I last looked at the code two years ago.  :)
>
> In case it is of use, the silicon is rev 09 (i.e. C0 stepping) and I am using
> gcc 4.4.2 to build the kernel and modules.

"C0" is *good*.

> I am currently inserting tracing into 2.6.38.2 to try to work out what is going
> on.  From mv_write_main_irq_mask I can see that the IRQ for each port is still
> enabled, even when ports stop responding.  I see interrupts generated when I
> hotplug or unplug disks on ports that are not locked up, but no interrupt is
> generated at all for the ports that are locked (this is from tracing in
> asm_do_IRQ in arch/arm/kernel/irq.c)
> 
> One thing I noticed was that there is no spinlock around the
> mv_save_cached_regs/mv_edma_cfg in mv_hardreset (unlike mv_port_start and
> mv_port_stop); why is this?

The mv_hardreset path is run from a libata-eh thread,
and it assumes it has exclusive access to the hardware.

But by all means, stuff the spinlock around that pair of calls,
just to eliminate any possibility of my mis-thinking it there.

I'm going to take a few minutes now and try to re-understand
how hot-plug gets "armed" for use, and see if anything cries out at me.

Cheers

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-12 10:07 AM, Mark Lord wrote:
> On 11-04-12 06:30 AM, Bruce Stenning wrote:
..
>> I am currently inserting tracing into 2.6.38.2 to try to work out what is going
>> on.  From mv_write_main_irq_mask I can see that the IRQ for each port is still
>> enabled, even when ports stop responding.  I see interrupts generated when I
>> hotplug or unplug disks on ports that are not locked up, but no interrupt is
>> generated at all for the ports that are locked (this is from tracing in
>> asm_do_IRQ in arch/arm/kernel/irq.c)
>>
>> One thing I noticed was that there is no spinlock around the
>> mv_save_cached_regs/mv_edma_cfg in mv_hardreset (unlike mv_port_start and
>> mv_port_stop); why is this?
> 
> The mv_hardreset path is run from a libata-eh thread,
> and it assumes it has exclusive access to the hardware.


Mmm.. another suspect is sata_mv's ".sff_irq_clear" function.
I don't see any locking in libata-sff.c before calling that one.

Tejun -- should libata-sff grab ap->lock before calling .sff_irq_clear,
or is that up to the LLD to do?

Thanks.

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Sorry about delay.  -EWASTRAVELING

On Tue, Apr 12, 2011 at 10:55:55AM -0400, Mark Lord wrote:
> >> One thing I noticed was that there is no spinlock around the
> >> mv_save_cached_regs/mv_edma_cfg in mv_hardreset (unlike mv_port_start and
> >> mv_port_stop); why is this?
> > 
> > The mv_hardreset path is run from a libata-eh thread,
> > and it assumes it has exclusive access to the hardware.
> 
> Mmm.. another suspect is sata_mv's ".sff_irq_clear" function.
> I don't see any locking in libata-sff.c before calling that one.
> 
> Tejun -- should libata-sff grab ap->lock before calling .sff_irq_clear,
> or is that up to the LLD to do?

It depends.  The basic assumption is that inside a single port, most
of exclusions are achieved implicit either by command protocol or
freeze/thaw mechanism - ie. either the port is in known state and
accesses are interlocked or the port is frozen and irq handler won't
do anything interfering with EH until EH brings the port back to sane
state.  If something goes wrong in the process, the port will get
frozen and reset, so we should be able to survive most conditions.

Ports on the same host are a bit more complicated.  Only a single EH
can proceed on a host.  ie. EHs for two separate ports won't proceed
at the same time (ap->eh_owner); however, this doesn't prevent from
normal issue path of another path racing with EH of another port.  In
this case, the EH routine should grab the host lock explicitly.  The
latter case wasn't common so the compromise for simplicity.

Thanks.

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Hi Mark, Tejun,

> Sorry about delay.  -EWASTRAVELING

:-)

After further investigation it looks like there might be more than one thing
going on here. I have managed to lock up ports by unplugging and reinserting
just the sata data cable (thereby avoiding any potential issues with the
hotplug backplane/power.) Dumping the registers after such a lockup shows
clearly that the irq for the locked port is disabled.

I had previously reported that port lockups happened such that the irq for
every port was enabled. I suspect that this is due to the hotplug backplane
on the pre-production unit that I am testing with. Our production units have
proper surge protection on the backplanes, but the early pre-production
versions did not, and I think this is what causes this other mode of port
lockup. Of course, there may be something else going on here but for the
time being I have concentrated on investigating the lockups caused by removing
and reinserting just the sata data cable. The presence of a separate problem
may invalidate other investigations and assertions I had previously made.

I have been able to reproduce this port lockup both with and without the
additional spinlock in mv_set_main_irq_mask. If I add more than very
rudimentary tracing in mv_write_main_irq_mask, then the race is avoided
(as you had indicated, Mark.) I am able to reproduce the lockup with minimal
tracing in mv_write_main_irq_mask and with libata tracing enabled; I have
attached the patch and the tracing leading up to port lockup below (this
is with the additional spinlock in mv_set_main_irq_mask.)  Apologies for the
length...

Please note the warning generated by ata_sff_hsm_move on the line:

  WARN_ON_ONCE((qc->flags & ATA_QCFLAG_ACTIVE) == 0);

I have been looking at code paths in libata into sata_mv, but I'm afraid I am
not au fait with the libata architecture yet.

Tejun, what does it mean to limit a sata link to UDMA/100? I thought that this
was only for ata devices, and sata devices have the choice of 1.5Gbps, 3Gbps,
or 6 Gbps. Is that a false assumption? Is it related to early sata devices that
were still somewhat based on parallel ata designs?

I shall be out-of-office from Wednesday for the best part of the next three
weeks, but I shall endeavour to get back to you if you have any queries during
that time.

Kind Regards,

Bruce.


Bruce Stenning,
IndigoVision,
b <dot> stenning <at> indigovision <dot> com


@@ -1022,20 +1027,33 @@
        if (mask & (ALL_PORTS_COAL_DONE | PORTS_4_7_COAL_DONE))
                mask &= ~DONE_IRQ_4_7;
        writelfl(mask, hpriv->main_irq_mask_addr);
+#if 1
+       printk("%08x\n", mask);
+#endif
 }


[ra_145_82]$ insmod sata_mv.ko
sata_mv 0000:00:04.0: version 1.28
ata_host_alloc: ENTER
ata_port_alloc: ENTER
ata_port_alloc: ENTER
ata_port_alloc: ENTER
ata_port_alloc: ENTER
PCI: enabling device 0000:00:04.0 (0140 -> 0143)
mv_port_init: EDMA cfg=0x0000291f EDMA IRQ err cause/mask=0x00000000/0xfc1e9fff
mv_port_init: EDMA cfg=0x0000291f EDMA IRQ err cause/mask=0x00000000/0xfc1e9fff
mv_port_init: EDMA cfg=0x0000291f EDMA IRQ err cause/mask=0x00000000/0xfc1e9fff
mv_port_init: EDMA cfg=0x0000291f EDMA IRQ err cause/mask=0x00000000/0xfc1e9fff
mv_init_host: HC0: HC config=0x000100ff HC IRQ cause (before clear)=0x00000000
00040000
mv_dump_pci_cfg: 00: 604111ab 02b00143 01000009 00000008
mv_dump_pci_cfg: 10: 80000004 00000000 00001001 00000000
mv_dump_pci_cfg: 20: 00000000 00000000 00000000 11ab11ab
mv_dump_pci_cfg: 30: 00000000 00000040 00000000 0000011a
mv_dump_pci_cfg: 40: 00025001 00000000 00000000 00000000
mv_dump_pci_cfg: 50: 00806005 00000000 00000000 00000000
mv_dump_pci_cfg: 60: 00300007 0183fff8
sata_mv 0000:00:04.0: Gen-II 32 slots 4 ports SCSI mode IRQ via INTx
__ata_port_freeze: ata4294967295 port frozen
__ata_port_freeze: ata4294967295 port frozen
__ata_port_freeze: ata4294967295 port frozen
__ata_port_freeze: ata4294967295 port frozen
scsi0 : sata_mv
scsi1 : sata_mv
scsi2 : sata_mv
scsi3 : sata_mv
ata1: FORCE: PHY spd limit set to 1.5Gbps
ata1: SATA max UDMA/133 mmio m1048576@0x80000000 port 0x80022000 irq 26
ata2: FORCE: PHY spd limit set to 1.5Gbps
ata2: SATA max UDMA/133 mmio m1048576@0x80000000 port 0x80024000 irq 26
ata3: FORCE: PHY spd limit set to 1.5Gbps
ata3: SATA max UDMA/133 mmio m1048576@0x80000000 port 0x80026000 irq 26
ata4: FORCE: PHY spd limit set to 1.5Gbps
ata4: SATA max UDMA/133 mmio m1048576@0x80000000 port 0x80028000 irq 26
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_recover: ENTER
__ata_port_freeze: ata1 port frozen
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata1: bus reset via SRST
ata1: link is slow to respond, please be patient (ready=0)
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040001
ata_eh_thaw_port: ata1 port thawed
ata_std_postreset: ENTER
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata1: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata1: cmd 0xEC
ata_sff_hsm_move: ata1: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata1: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata1: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata1: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata1: cmd 0x27
ata_sff_hsm_move: ata1: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata1: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0407  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x007f  93==0x0000
ata1.00: ATA-8: ST31000525SV, CV11, max UDMA/133
ata1.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata_dev_set_xfermode: set features - xfer mode
ata1: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x46 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata1: cmd 0xEF
ata_sff_hsm_move: ata1: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata1: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata1: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata1: cmd 0xEC
ata_sff_hsm_move: ata1: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata1: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata1: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata1: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata1: cmd 0x27
ata_sff_hsm_move: ata1: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata1: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x407f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x46
ata1.00: configured for UDMA/133
ata_eh_recover: EXIT, rc=0
ata_scsi_error: EXIT
ata_scsi_dump_cdb: CDB (1:0,0,0) 12 00 00 00 24 00 00 00 00
ata_scsiop_inq_std: ENTER
ata_scsi_dump_cdb: CDB (1:0,0,0) 12 00 00 00 60 00 00 00 00
ata_scsiop_inq_std: ENTER
scsi 0:0:0:0: Direct-Access     ATA      ST31000525SV     CV11 PQ: 0 ANSI: 5
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_recover: ENTER
__ata_port_freeze: ata2 port frozen
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata2: bus reset via SRST
ata2: link is slow to respond, please be patient (ready=0)
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040005
ata_eh_thaw_port: ata2 port thawed
ata_std_postreset: ENTER
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata2: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata2: cmd 0xEC
ata_sff_hsm_move: ata2: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata2: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata2: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata2: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata2: cmd 0x27
ata_sff_hsm_move: ata2: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata2: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0407  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x007f  93==0x0000
ata2.00: ATA-8: ST31000525SV, CV11, max UDMA/133
ata2.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata_dev_set_xfermode: set features - xfer mode
ata2: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x46 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata2: cmd 0xEF
ata_sff_hsm_move: ata2: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata2: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata2: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata2: cmd 0xEC
ata_sff_hsm_move: ata2: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata2: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata2: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata2: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata2: cmd 0x27
ata_sff_hsm_move: ata2: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata2: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x407f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x46
ata2.00: configured for UDMA/133
ata_eh_recover: EXIT, rc=0
ata_scsi_error: EXIT
ata_scsi_dump_cdb: CDB (2:0,0,0) 12 00 00 00 24 00 00 00 00
ata_scsiop_inq_std: ENTER
ata_scsi_dump_cdb: CDB (2:0,0,0) 12 00 00 00 60 00 00 00 00
ata_scsiop_inq_std: ENTER
scsi 1:0:0:0: Direct-Access     ATA      ST31000525SV     CV11 PQ: 0 ANSI: 5
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_recover: ENTER
__ata_port_freeze: ata3 port frozen
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata3: bus reset via SRST
ata3: link is slow to respond, please be patient (ready=0)
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040015
ata_eh_thaw_port: ata3 port thawed
ata_std_postreset: ENTER
ata3: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata3: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata3: cmd 0xEC
ata_sff_hsm_move: ata3: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata3: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata3: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata3: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata3: cmd 0x27
ata_sff_hsm_move: ata3: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata3: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0407  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x007f  93==0x0000
ata3.00: ATA-8: ST31000525SV, CV11, max UDMA/133
ata3.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata_dev_set_xfermode: set features - xfer mode
ata3: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x46 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata3: cmd 0xEF
ata_sff_hsm_move: ata3: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata3: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata3: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata3: cmd 0xEC
ata_sff_hsm_move: ata3: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata3: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata3: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata3: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata3: cmd 0x27
ata_sff_hsm_move: ata3: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata3: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x407f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x46
ata3.00: configured for UDMA/133
ata_eh_recover: EXIT, rc=0
ata_scsi_error: EXIT
ata_scsi_dump_cdb: CDB (3:0,0,0) 12 00 00 00 24 00 00 00 00
ata_scsiop_inq_std: ENTER
ata_scsi_dump_cdb: CDB (3:0,0,0) 12 00 00 00 60 00 00 00 00
ata_scsiop_inq_std: ENTER
scsi 2:0:0:0: Direct-Access     ATA      ST31000525SV     CV11 PQ: 0 ANSI: 5
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata4: link is slow to respond, please be patient (ready=0)
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0407  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x007f  93==0x0000
ata4.00: ATA-8: ST31000525SV, CV11, max UDMA/133
ata4.00: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x46 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x407f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x46
ata4.00: configured for UDMA/133
ata_eh_recover: EXIT, rc=0
ata_scsi_error: EXIT
ata_scsi_dump_cdb: CDB (4:0,0,0) 12 00 00 00 24 00 00 00 00
ata_scsiop_inq_std: ENTER
ata_scsi_dump_cdb: CDB (4:0,0,0) 12 00 00 00 60 00 00 00 00
ata_scsiop_inq_std: ENTER
scsi 3:0:0:0: Direct-Access     ATA      ST31000525SV     CV11 PQ: 0 ANSI: 5
[ra_145_82]$
[ra_145_82]$
[ra_145_82]$
[ra_145_82]$
[ra_145_82]$
[ra_145_82]$ 00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x407f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x46 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x407f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x46
ata4.00: configured for UDMA/133
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata4.00: limiting speed to UDMA/100:PIO4
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x407f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x45 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x207f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x45
ata4.00: configured for UDMA/100
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata4.00: limiting speed to UDMA/33:PIO4
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
00040015
__ata_port_freeze: ata4 port frozen
ata_sff_flush_pio_task: ENTER
ata4.00: failed to IDENTIFY (I/O error, err_mask=0x100)
ata4.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x207f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
00040015
__ata_port_freeze: ata4 port frozen
ata_sff_flush_pio_task: ENTER
ata4.00: failed to read native max address (err_mask=0x1)
ata4.00: HPA support seems broken, skipping HPA handling
ata4.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
00040015
__ata_port_freeze: ata4 port frozen
ata_sff_flush_pio_task: ENTER
------------[ cut here ]------------
WARNING: at drivers/ata/libata-sff.c:1053 0xc01702b0()
Modules linked in: sata_mv
Backtrace:
Function entered at [<c003466c>] from [<c0034784>]
 r7:00000000 r6:c01702b0 r5:c0222698 r4:0000041d
Function entered at [<c003476c>] from [<c004052c>]
Function entered at [<c00404dc>] from [<c0040568>]
 r8:df91930c r7:df918060 r6:df91930c r5:c02820cb r4:00000001
Function entered at [<c0040544>] from [<c01702b0>]
Function entered at [<c0170244>] from [<c0170d98>]
Function entered at [<c0170bf4>] from [<c0052200>]
 r8:00000009 r7:df918060 r6:c024e320 r5:dfa2fd60 r4:decf6000
Function entered at [<c0051ff4>] from [<c0052530>]
Function entered at [<c0052364>] from [<c0056a2c>]
Function entered at [<c00569a8>] from [<c0042a28>]
 r6:c0042a28 r5:c00569a8 r4:df82df10
---[ end trace 2776da609f64b4f9 ]---
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x7F)
ata_sff_hsm_move: ata4: protocol 2 task_state 4 (dev_stat 0x7F)
ata4.00: failed to IDENTIFY (I/O error, err_mask=0x2)
ata4.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
00040015
__ata_port_freeze: ata4 port frozen
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=1
ata4.00: failed to IDENTIFY (I/O error, err_mask=0x40)
ata4.00: revalidation failed (errno=-5)
ata4.00: limiting speed to UDMA/33:PIO3
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEF
ata_sff_hsm_move: ata4: protocol 1 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata4: ata_dev_select: ENTER, device 0, wait 1
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xA0
ata_sff_exec_command: ata4: cmd 0xEC
ata_sff_hsm_move: ata4: protocol 2 task_state 2 (dev_stat 0x58)
ata_pio_sector: data read
ata_sff_hsm_move: ata4: protocol 2 task_state 3 (dev_stat 0x50)
ata_sff_hsm_move: ata4: dev 0 command complete, drv_stat 0x50
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
ata4: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { 10B8B Dispar }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
00040055
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
00040055
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
ata4.00: disabled
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
ata_scsi_hotplug: ENTER
ata4.00: detaching (SCSI 3:0:0:0)
ata_scsi_hotplug: EXIT


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

On Mon, Apr 25, 2011 at 12:07:04PM +0100, Bruce Stenning wrote:
> Tejun, what does it mean to limit a sata link to UDMA/100? I thought that this
> was only for ata devices, and sata devices have the choice of 1.5Gbps, 3Gbps,
> or 6 Gbps. Is that a false assumption? Is it related to early sata devices that
> were still somewhat based on parallel ata designs?

Yeap, devices behind SATA-PATA bridge were still affected by the
transfer mode so libata tries to slow them down too along with link
speed when limiting speed due to errors.  Shouldn't affect native SATA
devices.

-- 
tejun

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-25 07:30 AM, Tejun Heo wrote:
> On Mon, Apr 25, 2011 at 12:07:04PM +0100, Bruce Stenning wrote:
>> Tejun, what does it mean to limit a sata link to UDMA/100? I thought that this
>> was only for ata devices, and sata devices have the choice of 1.5Gbps, 3Gbps,
>> or 6 Gbps. Is that a false assumption? Is it related to early sata devices that
>> were still somewhat based on parallel ata designs?
> 
> Yeap, devices behind SATA-PATA bridge were still affected by the
> transfer mode so libata tries to slow them down too along with link
> speed when limiting speed due to errors.  Shouldn't affect native SATA
> devices.


Yeah, what he said.  :)

First generation SATA devices were merely PATA transports
with a SATA-to-PATA converter chip onboard.  Some of those
require that we set the transfer modes.

Ditto for various more modern setups, where CF-cards, PATA drives,
and other weirdos are connected through a discrete SATA bridge device.

Cheers

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Tejun wrote:

> Yeap, devices behind SATA-PATA bridge were still affected by the transfer
> mode so libata tries to slow them down too along with link speed when
> limiting speed due to errors.  Shouldn't affect native SATA devices.

Thanks.

I wrote:

> 00040055
> 00040015
> __ata_port_freeze: ata4 port frozen
> ata_port_schedule_eh: port EH scheduled
> ata_eh_thaw_port: ata4 port thawed
> ata_std_postreset: ENTER
> ata4: SATA link down (SStatus 0 SControl 310)
> ata_std_postreset: EXIT
> ata_eh_revalidate_and_attach: ENTER
> ata_eh_revalidate_and_attach: EXIT rc=-5
> ata4.00: disabled
> ata_eh_revalidate_and_attach: ENTER
> ata_eh_recover: EXIT, rc=0
> ata4: EH complete
> ata_scsi_error: EXIT
> ata_scsi_hotplug: ENTER
> ata4.00: detaching (SCSI 3:0:0:0)
> ata_scsi_hotplug: EXIT

Okay, so the ata_eh_thaw_port has raced (and won) against whatever was in the
process of masking off the irq (the __ata_port_freeze?), which then completes
leaving libata/sata_mv thinking the port is thawed while no further irqs get
generated.

Could ata_port_freeze or __ata_port_freeze (which don't claim the ap's lock)
have been invoked and then slept while ata_eh_thaw_port runs?


Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

I haven't followed the trace but,

> > __ata_port_freeze: ata4 port frozen
> > ata_port_schedule_eh: port EH scheduled
> > ata_eh_thaw_port: ata4 port thawed
> > ata_std_postreset: ENTER
> > ata4: SATA link down (SStatus 0 SControl 310)
> > ata_std_postreset: EXIT
> > ata_eh_revalidate_and_attach: ENTER
> > ata_eh_revalidate_and_attach: EXIT rc=-5
> > ata4.00: disabled
> > ata_eh_revalidate_and_attach: ENTER
> > ata_eh_recover: EXIT, rc=0
> > ata4: EH complete
> > ata_scsi_error: EXIT
> > ata_scsi_hotplug: ENTER
> > ata4.00: detaching (SCSI 3:0:0:0)
> > ata_scsi_hotplug: EXIT
> 
> Okay, so the ata_eh_thaw_port has raced (and won) against whatever was in the
> process of masking off the irq (the __ata_port_freeze?), which then completes
> leaving libata/sata_mv thinking the port is thawed while no further irqs get
> generated.
> 
> Could ata_port_freeze or __ata_port_freeze (which don't claim the ap's lock)
> have been invoked and then slept while ata_eh_thaw_port runs?

ata4 is reporting link down and the device is detached and port
disabled afterwards.  Doesn't seem to have much to do with
freezing/thawing?

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Tejun wrote:
> ata4 is reporting link down and the device is detached and port
> disabled afterwards.  Doesn't seem to have much to do with
> freezing/thawing?

After all processing of a normal unplug event has completed, the port is left
thawed (and the irq enabled) to allow future hotplug events on this port to be
actioned.  In the case of the port lockups that I have seen the port appears
to be left frozen, with the irq disabled, and I am hypothesising that this is
due to a race between the freeze and the thaw.

Below is some additional tracing leading up to a port lockup, with some more
DPRINTK statements added.  The port freeze appears to be happening after the
port thaw.  The irq mask writes that are output by mv_set_main_irq_mask seem
to show the irqs left masked off.

...
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
mv_set_main_irq_mask: skipped write in mv_set_main_irq_mask: 00040015, 00040015
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
mv_eh_thaw: ENTER
00040055
mv_eh_thaw: EXIT
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
00040015
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_revalidate_and_attach: EXIT rc=-5
ata4.00: disabled
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
ata_scsi_hotplug: ENTER
ata4.00: detaching (SCSI 3:0:0:0)
ata_scsi_hotplug: EXIT

The port is unresponsive at this point.


And another lockup, with tracing showing entering and leaving mv_eh_freeze:

...
ata_sff_tf_load: hob: feat 0x0 nsect 0x0, lba 0x0 0x0 0x0
ata_sff_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x0
ata_sff_tf_load: device 0xE0
ata_sff_exec_command: ata4: cmd 0x27
mv_eh_freeze: ENTER
00040015
mv_eh_freeze: EXIT
__ata_port_freeze: ata4 port frozen
ata_sff_flush_pio_task: ENTER
ata4.00: failed to read native max address (err_mask=0x1)
ata4.00: HPA support seems broken, skipping HPA handling
ata4.00: revalidation failed (errno=-5)
ata4.00: disabled
mv_eh_freeze: ENTER
mv_set_main_irq_mask: skipped write in mv_set_main_irq_mask: 00040015, 00040015
mv_eh_freeze: EXIT
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
mv_eh_thaw: ENTER
00040055
mv_eh_thaw: EXIT
mv_eh_freeze: ENTER
00040015
mv_eh_freeze: EXIT
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link down (SStatus 0 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
ata_scsi_hotplug: ENTER
ata4.00: detaching (SCSI 3:0:0:0)
ata_scsi_hotplug: EXIT

The port is unresponsive at this point.

The output shows "ata_eh_thaw_port: ata4 port thawed" after the
"__ata_port_freeze: ata4 port frozen", but the tracing suggests that the actual
work enabling the irqs has been carried out before the irqs are subsequently
disabled.


Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

On Tue, Apr 26, 2011 at 02:13:22PM +0100, Bruce Stenning wrote:
> Tejun wrote:
> > ata4 is reporting link down and the device is detached and port
> > disabled afterwards.  Doesn't seem to have much to do with
> > freezing/thawing?
> 
> After all processing of a normal unplug event has completed, the port is left
> thawed (and the irq enabled) to allow future hotplug events on this port to be
> actioned.  In the case of the port lockups that I have seen the port appears
> to be left frozen, with the irq disabled, and I am hypothesising that this is
> due to a race between the freeze and the thaw.
> 
> Below is some additional tracing leading up to a port lockup, with some more
> DPRINTK statements added.  The port freeze appears to be happening after the
> port thaw.  The irq mask writes that are output by mv_set_main_irq_mask seem
> to show the irqs left masked off.

Does the following patch resolve the problem?

Thanks.

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index 88cd22f..73f0589 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2802,19 +2802,6 @@ int ata_eh_reset(struct ata_link *link, int classify,
 	}
 
 	/*
-	 * Some controllers can't be frozen very well and may set
-	 * spuruious error conditions during reset.  Clear accumulated
-	 * error information.  As reset is the final recovery action,
-	 * nothing is lost by doing this.
-	 */
-	spin_lock_irqsave(link->ap->lock, flags);
-	memset(&link->eh_info, 0, sizeof(link->eh_info));
-	if (slave)
-		memset(&slave->eh_info, 0, sizeof(link->eh_info));
-	ap->pflags &= ~ATA_PFLAG_EH_PENDING;
-	spin_unlock_irqrestore(link->ap->lock, flags);
-
-	/*
 	 * Make sure onlineness and classification result correspond.
 	 * Hotplug could have happened during reset and some
 	 * controllers fail to wait while a drive is spinning up after

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Tejun wrote:
> Does the following patch resolve the problem?
>
> Thanks.

I have applied that patch, keeping Mark's mv_set_main_irq_mask spinlock patch
in place.  I would not like to commit absolutely, for obvious reasons, but I
have abused the port considerably and have not been able to coax it into
locking up.


Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

On Tue, Apr 26, 2011 at 04:41:25PM +0100, Bruce Stenning wrote:
> Tejun wrote:
> > Does the following patch resolve the problem?
> 
> I have applied that patch, keeping Mark's mv_set_main_irq_mask spinlock patch
> in place.  I would not like to commit absolutely, for obvious reasons, but I
> have abused the port considerably and have not been able to coax it into
> locking up.

Yeah, it makes sense.  Hmm... it seems I wasn't thinking straight when
I added that work around.  Not sure how to fix it properly at this
moment.  I'll think about it.  Can you please keep me posted if you
find something while testing?

Thanks.

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> Yeah, it makes sense.  Hmm... it seems I wasn't thinking straight when
> I added that work around.  Not sure how to fix it properly at this
> moment.  I'll think about it.  Can you please keep me posted if you
> find something while testing?

I'm away for two and a bit weeks so I'm not sure what progress (if any)
I will make during that time.  But yes, I shall certainly keep you posted
as soon as I find anything else.  Thank you very much for your inputs.

Cheers,

Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

On Tue, Apr 26, 2011 at 05:05:45PM +0100, Bruce Stenning wrote:
> > Yeah, it makes sense.  Hmm... it seems I wasn't thinking straight when
> > I added that work around.  Not sure how to fix it properly at this
> > moment.  I'll think about it.  Can you please keep me posted if you
> > find something while testing?
> 
> I'm away for two and a bit weeks so I'm not sure what progress (if any)
> I will make during that time.  But yes, I shall certainly keep you posted
> as soon as I find anything else.  Thank you very much for your inputs.

So, here's the patch which should fix the problem you're seeing and
doesn't break the controllers which generate spurious hotplug events
during reset.  Please test this when you come back and let me know the
result.

Thank you.

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index f26f2fe..a57845d 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2802,10 +2802,11 @@ int ata_eh_reset(struct ata_link *link, int classify,
 	}
 
 	/*
-	 * Some controllers can't be frozen very well and may set
-	 * spuruious error conditions during reset.  Clear accumulated
-	 * error information.  As reset is the final recovery action,
-	 * nothing is lost by doing this.
+	 * Some controllers can't be frozen very well and may set spuruious
+	 * error conditions during reset.  Clear accumulated error
+	 * information and re-thaw the port if frozen.  As reset is the
+	 * final recovery action and we cross check link onlineness against
+	 * device classification later, no hotplug event is lost by this.
 	 */
 	spin_lock_irqsave(link->ap->lock, flags);
 	memset(&link->eh_info, 0, sizeof(link->eh_info));
@@ -2814,6 +2815,9 @@ int ata_eh_reset(struct ata_link *link, int classify,
 	ap->pflags &= ~ATA_PFLAG_EH_PENDING;
 	spin_unlock_irqrestore(link->ap->lock, flags);
 
+	if (ap->pflags & ATA_PFLAG_FROZEN)
+		ata_eh_thaw_port(ap);
+
 	/*
 	 * Make sure onlineness and classification result correspond.
 	 * Hotplug could have happened during reset and some

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Hi Tejun,

> So, here's the patch which should fix the problem you're seeing and
> doesn't break the controllers which generate spurious hotplug events
> during reset.  Please test this when you come back and let me know the
> result.

I have tested this patch out a fair amount, and it seemed to make things
much more reliable, but I have managed to lock up the port again this
afternoon. Below is some tracing showing ata4 being frozen and not thawed:

__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
ata4: COMRESET failed (errno=-32)
sata_link_hardreset: EXIT, rc=-32
ata4: reset failed (errno=-32), retrying in 33 secs
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
ata4: COMRESET failed (errno=-32)
sata_link_hardreset: EXIT, rc=-32
ata4: reset failed, giving up
ata_eh_recover: EXIT, rc=-32
ata4.00: disabled
ata4: EH complete
ata_scsi_error: EXIT

The IRQ for that port is masked off afterwards.


Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello, sorry about the long delay.

On Tue, May 17, 2011 at 04:30:20PM +0100, Bruce Stenning wrote:
> __ata_port_freeze: ata4 port frozen
> ata4: hard resetting link
> sata_link_hardreset: ENTER
> ata4: COMRESET failed (errno=-32)
> sata_link_hardreset: EXIT, rc=-32
> ata4: reset failed (errno=-32), retrying in 33 secs
> __ata_port_freeze: ata4 port frozen
> ata4: hard resetting link
> sata_link_hardreset: ENTER
> ata4: COMRESET failed (errno=-32)
> sata_link_hardreset: EXIT, rc=-32
> ata4: reset failed, giving up
> ata_eh_recover: EXIT, rc=-32
> ata4.00: disabled
> ata4: EH complete
> ata_scsi_error: EXIT
> 
> The IRQ for that port is masked off afterwards.

This is a different issue.  libata EH plugs the port if reset fails
repeatedly.  This behavior was implemented to avoid causing continuous
resets on a port in case it has flaky PHY state reporting; however, it
seems to cause more trouble than fixing issues - ie. plugging in a
broken device may end up plugging the port even after the offending
device is removed until manual rescan or reboot.  I've been pondering
about changing the behavior like the following.

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index dfb6e9d..05797fe 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -2885,8 +2885,17 @@ int ata_eh_reset(struct ata_link *link, int classify,
 	    sata_scr_read(link, SCR_STATUS, &sstatus))
 		rc = -ERESTART;
 
-	if (rc == -ERESTART || try >= max_tries)
+	if (rc == -ERESTART || try >= max_tries) {
+		/*
+		 * Thaw host port even if reset failed, so that the port
+		 * can be retried on the next phy event.  This risks
+		 * repeated EH runs but seems to be a better tradeoff than
+		 * shutting down a port after a botched hotplug attempt.
+		 */
+		if (ata_is_host_link(link))
+			ata_eh_thaw_port(ap);
 		goto out;
+	}
 
 	now = jiffies;
 	if (time_before(now, deadline)) {

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> This is a different issue.  libata EH plugs the port if reset fails
> repeatedly.  This behavior was implemented to avoid causing continuous
> resets on a port in case it has flaky PHY state reporting; however, it
> seems to cause more trouble than fixing issues - ie. plugging in a
> broken device may end up plugging the port even after the offending
> device is removed until manual rescan or reboot.  I've been pondering
> about changing the behavior like the following.

Thanks for the explanation, Tejun, and for sending those changes upstream.
I shall incorporate these patches into my kernel and keep you informed as
to how they behave.

Mark, did you get a chance to clean up the sata_mv spinlock addition in
mv_set_main_irq_mask?

Many Thanks,

Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-05-25 09:36 AM, Bruce Stenning wrote:
>> This is a different issue.  libata EH plugs the port if reset fails
>> repeatedly.  This behavior was implemented to avoid causing continuous
>> resets on a port in case it has flaky PHY state reporting; however, it
>> seems to cause more trouble than fixing issues - ie. plugging in a
>> broken device may end up plugging the port even after the offending
>> device is removed until manual rescan or reboot.  I've been pondering
>> about changing the behavior like the following.
> 
> Thanks for the explanation, Tejun, and for sending those changes upstream.
> I shall incorporate these patches into my kernel and keep you informed as
> to how they behave.
> 
> Mark, did you get a chance to clean up the sata_mv spinlock addition in
> mv_set_main_irq_mask?

Not yet.  I've been waiting to hear back from you as to
whether they visibly fix anything or not.

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> > Mark, did you get a chance to clean up the sata_mv spinlock addition in
> > mv_set_main_irq_mask?
>
> Not yet.  I've been waiting to hear back from you as to
> whether they visibly fix anything or not.

Having now tested with Tejun's two patches and without the spinlock in
mv_set_main_irq_mask for a reasonable time, the hotplug seems to be very
reliable.  So I think it's probably best to leave the spinlock out and
continue to observe the behaviour with further testing.

Thanks,
Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-05-30 09:07 AM, Bruce Stenning wrote:
>>> Mark, did you get a chance to clean up the sata_mv spinlock addition in
>>> mv_set_main_irq_mask?
>>
>> Not yet.  I've been waiting to hear back from you as to
>> whether they visibly fix anything or not.
> 
> Having now tested with Tejun's two patches and without the spinlock in
> mv_set_main_irq_mask for a reasonable time, the hotplug seems to be very
> reliable.  So I think it's probably best to leave the spinlock out and
> continue to observe the behaviour with further testing.

Peachy.  I'll have another look at some point -- I think I thought
the spinlock was still needed for ATAPI under some conditions.
Gotta look closer to make sure.

Thanks.

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-05-25 05:41 AM, Tejun Heo wrote:
> Hello, sorry about the long delay.
> 
> On Tue, May 17, 2011 at 04:30:20PM +0100, Bruce Stenning wrote:
>> __ata_port_freeze: ata4 port frozen
>> ata4: hard resetting link
>> sata_link_hardreset: ENTER
>> ata4: COMRESET failed (errno=-32)
>> sata_link_hardreset: EXIT, rc=-32
>> ata4: reset failed (errno=-32), retrying in 33 secs
>> __ata_port_freeze: ata4 port frozen
>> ata4: hard resetting link
>> sata_link_hardreset: ENTER
>> ata4: COMRESET failed (errno=-32)
>> sata_link_hardreset: EXIT, rc=-32
>> ata4: reset failed, giving up
>> ata_eh_recover: EXIT, rc=-32
>> ata4.00: disabled
>> ata4: EH complete
>> ata_scsi_error: EXIT
>>
>> The IRQ for that port is masked off afterwards.
> 
> This is a different issue.  libata EH plugs the port if reset fails
> repeatedly.  This behavior was implemented to avoid causing continuous
> resets on a port in case it has flaky PHY state reporting; however, it
> seems to cause more trouble than fixing issues - ie. plugging in a
> broken device may end up plugging the port even after the offending
> device is removed until manual rescan or reboot.  I've been pondering
> about changing the behavior like the following.
> 
> diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
> index dfb6e9d..05797fe 100644
> --- a/drivers/ata/libata-eh.c
> +++ b/drivers/ata/libata-eh.c
> @@ -2885,8 +2885,17 @@ int ata_eh_reset(struct ata_link *link, int classify,
>  	    sata_scr_read(link, SCR_STATUS, &sstatus))
>  		rc = -ERESTART;
>  
> -	if (rc == -ERESTART || try >= max_tries)
> +	if (rc == -ERESTART || try >= max_tries) {
> +		/*
> +		 * Thaw host port even if reset failed, so that the port
> +		 * can be retried on the next phy event.  This risks
> +		 * repeated EH runs but seems to be a better tradeoff than
> +		 * shutting down a port after a botched hotplug attempt.
> +		 */
> +		if (ata_is_host_link(link))
> +			ata_eh_thaw_port(ap);
>  		goto out;
> +	}
>  
>  	now = jiffies;
>  	if (time_before(now, deadline)) {


Tejun, did this ever go upstream and to -stable ??
I'm asking because I see the same issue with other SATA controllers,
in particular with sata_sil boards.  Hot plug generally works _once_
per port, and then stops working.

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

(cc'ing Jeff)

On Fri, Jun 10, 2011 at 08:28:51AM -0400, Mark Lord wrote:
> Tejun, did this ever go upstream and to -stable ??
> I'm asking because I see the same issue with other SATA controllers,
> in particular with sata_sil boards.  Hot plug generally works _once_
> per port, and then stops working.

The patch is still pending,

 http://article.gmane.org/gmane.linux.ide/49613

I don't think it would be wise to include the patch for -stable tho.
It's not a regression fix and has some possibility of introducing
regressions, so....

Thanks.

-- 
tejun

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-06-10 10:01 AM, Tejun Heo wrote:
> Hello,
> 
> (cc'ing Jeff)
> 
> On Fri, Jun 10, 2011 at 08:28:51AM -0400, Mark Lord wrote:
>> Tejun, did this ever go upstream and to -stable ??
>> I'm asking because I see the same issue with other SATA controllers,
>> in particular with sata_sil boards.  Hot plug generally works _once_
>> per port, and then stops working.
> 
> The patch is still pending,
> 
>  http://article.gmane.org/gmane.linux.ide/49613
> 
> I don't think it would be wise to include the patch for -stable tho.
> It's not a regression fix and has some possibility of introducing
> regressions, so....

Not a regression fix?  Excuse me?
SATA hotplug always used to work fine,
and is more or less essential to reboot-free operations.

Cheers

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Jeff Garzik]

On 06/10/2011 01:32 PM, Mark Lord wrote:
> On 11-06-10 10:01 AM, Tejun Heo wrote:
>> Hello,
>>
>> (cc'ing Jeff)
>>
>> On Fri, Jun 10, 2011 at 08:28:51AM -0400, Mark Lord wrote:
>>> Tejun, did this ever go upstream and to -stable ??
>>> I'm asking because I see the same issue with other SATA controllers,
>>> in particular with sata_sil boards.  Hot plug generally works _once_
>>> per port, and then stops working.
>>
>> The patch is still pending,
>>
>>   http://article.gmane.org/gmane.linux.ide/49613
>>
>> I don't think it would be wise to include the patch for -stable tho.
>> It's not a regression fix and has some possibility of introducing
>> regressions, so....
>
> Not a regression fix?  Excuse me?
> SATA hotplug always used to work fine,
> and is more or less essential to reboot-free operations.

I can move it from #upstream (linux-next) to #upstream-fixes, if we feel 
it is sufficient urgent.  It seemed like it needed more testing, but 
maybe the best way to do that is #upstream-fixes?

Was mainly a -rc question, to me.

	Jeff

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-06-10 01:39 PM, Jeff Garzik wrote:
> On 06/10/2011 01:32 PM, Mark Lord wrote:
>> On 11-06-10 10:01 AM, Tejun Heo wrote:
>>> Hello,
>>>
>>> (cc'ing Jeff)
>>>
>>> On Fri, Jun 10, 2011 at 08:28:51AM -0400, Mark Lord wrote:
>>>> Tejun, did this ever go upstream and to -stable ??
>>>> I'm asking because I see the same issue with other SATA controllers,
>>>> in particular with sata_sil boards.  Hot plug generally works _once_
>>>> per port, and then stops working.
>>>
>>> The patch is still pending,
>>>
>>>   http://article.gmane.org/gmane.linux.ide/49613
>>>
>>> I don't think it would be wise to include the patch for -stable tho.
>>> It's not a regression fix and has some possibility of introducing
>>> regressions, so....
>>
>> Not a regression fix?  Excuse me?
>> SATA hotplug always used to work fine,
>> and is more or less essential to reboot-free operations.
> 
> I can move it from #upstream (linux-next) to #upstream-fixes, if we feel it is
> sufficient urgent.  It seemed like it needed more testing, but maybe the best
> way to do that is #upstream-fixes?
> 
> Was mainly a -rc question, to me.

Well, it's not getting any testing sitting outside of the kernel right now.

Cheers

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Jeff Garzik]

On 06/10/2011 04:49 PM, Mark Lord wrote:
> Well, it's not getting any testing sitting outside of the kernel right now.

It gets whatever testing linux-next gets...

	Jeff

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

On Fri, Jun 10, 2011 at 01:32:22PM -0400, Mark Lord wrote:
> > I don't think it would be wise to include the patch for -stable tho.
> > It's not a regression fix and has some possibility of introducing
> > regressions, so....
> 
> Not a regression fix?  Excuse me?
> SATA hotplug always used to work fine,
> and is more or less essential to reboot-free operations.

There are two separate patches.  One is a fix which got pushed to
Linus by Jeff early yesterday.  The other changes behavior which has
been like that since the beginning of EH.  The former is marked
properly w/ -stable.  The latter shouldn't be in -stable.

Thanks.

-- 
tejun

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-06-11 08:19 AM, Tejun Heo wrote:
> On Fri, Jun 10, 2011 at 01:32:22PM -0400, Mark Lord wrote:
>>> I don't think it would be wise to include the patch for -stable tho.
>>> It's not a regression fix and has some possibility of introducing
>>> regressions, so....
>>
>> Not a regression fix?  Excuse me?
>> SATA hotplug always used to work fine,
>> and is more or less essential to reboot-free operations.
> 
> There are two separate patches.  One is a fix which got pushed to
> Linus by Jeff early yesterday.  The other changes behavior which has
> been like that since the beginning of EH.  The former is marked
> properly w/ -stable.  The latter shouldn't be in -stable.

Peachy.  Got links for each of those?
I may try them with the sata_sil board that was having issues earlier.

Cheers

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

On Sun, Jun 12, 2011 at 01:10:35PM -0400, Mark Lord wrote:
> On 11-06-11 08:19 AM, Tejun Heo wrote:
> > On Fri, Jun 10, 2011 at 01:32:22PM -0400, Mark Lord wrote:
> >>> I don't think it would be wise to include the patch for -stable tho.
> >>> It's not a regression fix and has some possibility of introducing
> >>> regressions, so....
> >>
> >> Not a regression fix?  Excuse me?
> >> SATA hotplug always used to work fine,
> >> and is more or less essential to reboot-free operations.
> > 
> > There are two separate patches.  One is a fix which got pushed to
> > Linus by Jeff early yesterday.  The other changes behavior which has
> > been like that since the beginning of EH.  The former is marked
> > properly w/ -stable.  The latter shouldn't be in -stable.
> 
> Peachy.  Got links for each of those?
> I may try them with the sata_sil board that was having issues earlier.

The fix is

 http://article.gmane.org/gmane.linux.ide/49615

and the behavior change is

 http://article.gmane.org/gmane.linux.ide/49613

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Hi guys,

While the hotplug is now far more reliable, I have recently been able to coax
it into locking up SATA ports again while the device is heavily loaded.  This
looks very similar to the previous lockups, with the SATA port left frozen.
I have pasted some tracing below; at the end of the trace ata4 is no longer
responsive to hotplug events.  I have attempted to add further tracing to find
out where the freeze is occurring, but so far this has just prevented me from
triggering the condition.  I am currently trying to locate the problem by
inspecting the sources, but you may have some intuition that could shortcut
my efforts.

I should mention that we are now working on kernel 2.6.39.4 (and are choosing
not to go with 3.x to limit changes as we progress towards final testing.)

Kind Regards,

Bruce.


[...]
ata4.00: configured for UDMA/33
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
ata_scsiop_noop: ENTER
ata_scsiop_read_cap: ENTER
ata_scsiop_mode_sense: ENTER
ata_scsiop_mode_sense: ENTER
ata_scsiop_mode_sense: ENTER
__ata_port_freeze: ata4 port frozen
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_error: ENTER
ata_sff_flush_pio_task: ENTER
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata4.00: exception Emask 0x10 SAct 0x0 SErr 0x190002 action 0xe frozen
ata4.00: edma_err_cause=00000020 pp_flags=00000000, SError=00180000
ata4: SError: { RecovComm PHYRdyChg 10B8B Dispar }
ata4.00: failed command: FLUSH CACHE EXT
ata4.00: cmd ea/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         res 50/00:00:30:5a:27/00:08:00:00:00/a0 Emask 0x10 (ATA bus error)
ata4.00: status: { DRDY }
ata_eh_recover: ENTER
__ata_port_freeze: ata4 port frozen
ata4: hard resetting link
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=0
ata_sff_softreset: ENTER
ata_sff_softreset: about to softreset, devmask=1
ata_bus_softreset: ata4: bus reset via SRST
ata_dev_classify: found ATA device by sig
ata_sff_softreset: EXIT, classes[0]=1 [1]=0
ata_eh_thaw_port: ata4 port thawed
ata_std_postreset: ENTER
ata4: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_sff_flush_pio_task: ENTER
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_xfermode: set features - xfer mode
ata_sff_flush_pio_task: ENTER
ata_dev_set_xfermode: EXIT, err_mask=0
ata_sff_flush_pio_task: ENTER
ata_sff_flush_pio_task: ENTER
ata_dump_id: 49==0x2f00  53==0x0007  63==0x0007  64==0x0003  75==0x001f
ata_dump_id: 80==0x01f0  81==0x0029  82==0x346b  83==0x7d61  84==0x4133
ata_dump_id: 88==0x047f  93==0x0000
ata_dev_set_mode: xfer_shift=12, xfer_mode=0x42
ata4.00: configured for UDMA/33
ata4.00: retrying FLUSH 0xea Emask 0x10
ata_sff_flush_pio_task: ENTER
ata_eh_recover: EXIT, rc=0
ata4: EH complete
ata_scsi_error: EXIT
__ata_port_freeze: ata4 port frozen
ata_port_schedule_eh: port EH scheduled
ata_scsiop_noop: ENTER
ata_scsiop_read_cap: ENTER
ata_scsiop_mode_sense: ENTER
ata_scsiop_mode_sense: ENTER
ata_scsiop_mode_sense: ENTER

Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

On Mon, Aug 29, 2011 at 04:49:29PM +0100, Bruce Stenning wrote:
> I should mention that we are now working on kernel 2.6.39.4 (and are choosing
> not to go with 3.x to limit changes as we progress towards final testing.)

I don't think it would make any difference.  The core EH hasn't
changed for some time now.

> [...]
> ata4: EH complete
> ata_scsi_error: EXIT
> __ata_port_freeze: ata4 port frozen
> ata_port_schedule_eh: port EH scheduled
> ata_scsiop_noop: ENTER
> ata_scsiop_read_cap: ENTER
> ata_scsiop_mode_sense: ENTER
> ata_scsiop_mode_sense: ENTER
> ata_scsiop_mode_sense: ENTER

That's weird.  Another EH is scheduled after one completes but EH
doesn't kick in.  Hmmm... can't see how that can happen.  How easily
can you reproduce the problem?

Thanks.

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> That's weird.  Another EH is scheduled after one completes but EH
> doesn't kick in.  Hmmm... can't see how that can happen.  How easily
> can you reproduce the problem?
>
> Thanks.

Hi Tejun,

I hope you are well :-)

I have been trying to determine if the problem is that it is failing to
schedule the EH, or whether it is correctly scheduling it but for some
reason it is getting blocked or lost.

Unfortunately it has so far been quite difficult to reproduce when specifically
attempting to.  In normal use cases I reproduced it twice by unplugging a drive
from a RAID array with redundancy intact.  This was out of around a dozen
cycles of waiting until redundancy was restored while the unit was under load,
popping the disk, reinserting, and triggering a RAID rebuild.

I have only twice managed to trigger a lockup deliberately.  In both cases the
tracing showed a scheduled EH which was subsequently not enacted.

How long could it take for the EH to be enacted?  In the lockups that I
have reproduced it did not seem to have recovered minutes later, but perhaps
if I had waited longer...?  I have noticed that error recovery sometimes backs
off for 8s and even 33s, but it always warns when that sort of delay is coming
up.

I shall continue to try to track down why the scheduled EH does not happen.

Kind Regards,

Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

On Fri, Sep 02, 2011 at 05:22:38PM +0100, Bruce Stenning wrote:
> Unfortunately it has so far been quite difficult to reproduce when specifically
> attempting to.  In normal use cases I reproduced it twice by unplugging a drive
> from a RAID array with redundancy intact.  This was out of around a dozen
> cycles of waiting until redundancy was restored while the unit was under load,
> popping the disk, reinserting, and triggering a RAID rebuild.

Hmm... that's unfortunate.

> I have only twice managed to trigger a lockup deliberately.  In both cases the
> tracing showed a scheduled EH which was subsequently not enacted.
> 
> How long could it take for the EH to be enacted?  In the lockups that I
> have reproduced it did not seem to have recovered minutes later, but perhaps
> if I had waited longer...?  I have noticed that error recovery sometimes backs
> off for 8s and even 33s, but it always warns when that sort of delay is coming
> up.

It should happen pretty quickly.  In such cases, fastdrain is
activated and all pending commands are aborted if they complete in 3
secs and then EH should kick in.  The backoff is from reset path only
to give breathing time for devices which take long time to spin up and
doesn't apply in this case.

> I shall continue to try to track down why the scheduled EH does not happen.

Can you please add some debug printk's to scsi_schedule_eh() and see
whether scsi_eh_wakeup() is invoked from there?  It seems likely that
the problem is caused by race conditions around
SHOST_[CANCEL_]RECOVERY flags.

Thanks.

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> Can you please add some debug printk's to scsi_schedule_eh() and see
> whether scsi_eh_wakeup() is invoked from there?  It seems likely that
> the problem is caused by race conditions around
> SHOST_[CANCEL_]RECOVERY flags.

I did manage to reproduce the lockup again yesterday with a slightly
different mix of tracing, including adding tracing to scsi_eh_wakeup()
and scsi_schedule_eh().  It looks like the EH is being scheduled, but
the EH thread goes immediately back to sleep and doesn't wake up:

ata4: EH complete
Waking error handler thread
scsi_eh_wakeup: succeeded
scsi_schedule_eh: succeeded
scsi_restart_operations: waking up host to restart
Error handler scsi_eh_3 sleeping

Is it attempting to wake the scsi_eh_3 thread while scsi_error_handler
is still processing an EH, which then calls scsi_restart_operations and
puts the scsi_eh_3 thread back to sleep again?

Some while after the lockup, there was some tracing relating to SCSI
operations timing out, but the port was still unresponsive.  The unit
is not entirely stable in this state, and our application software was
no longer able to strobe softdog, so the unit rebooted.  Enough was
running for the serial console to be responsive before the reboot,
however.

Thanks,

Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

On Tue, Sep 06, 2011 at 01:19:44PM +0100, Bruce Stenning wrote:
> ata4: EH complete
> Waking error handler thread
> scsi_eh_wakeup: succeeded
> scsi_schedule_eh: succeeded
> scsi_restart_operations: waking up host to restart
> Error handler scsi_eh_3 sleeping

I think the following should fix the problem.  The code there is from
the time when libata shared scsi_host->host_lock.  libata no longer
does that so, in the current state, host_eh_scheduled can be cleared
with actual pending EH condition.

You should be able to reproduce the problem more easily by adding
delay (something like mdelay(5)) before host_eh_scheduled clearing
without the following patch applied.

Thanks.

diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c
index ed16fbe..e971784 100644
--- a/drivers/ata/libata-eh.c
+++ b/drivers/ata/libata-eh.c
@@ -771,6 +771,14 @@ void ata_scsi_port_error_handler(struct Scsi_Host *host, struct ata_port *ap)
 		/* process port suspend request */
 		ata_eh_handle_port_suspend(ap);
 
+		/*
+		 * Single iteration complete.  Clear SCSI EH scheduled
+		 * state and check whether another iteration is necessary.
+		 */
+		spin_lock_irqsave(host->host_lock, flags);
+		host->host_eh_scheduled = 0;
+		spin_unlock_irqrestore(host->host_lock, flags);
+
 		/* Exception might have happened after ->error_handler
 		 * recovered the port but before this point.  Repeat
 		 * EH in such case.
@@ -792,13 +800,6 @@ void ata_scsi_port_error_handler(struct Scsi_Host *host, struct ata_port *ap)
 		ata_for_each_link(link, ap, HOST_FIRST)
 			memset(&link->eh_info, 0, sizeof(link->eh_info));
 
-		/* Clear host_eh_scheduled while holding ap->lock such
-		 * that if exception occurs after this point but
-		 * before EH completion, SCSI midlayer will
-		 * re-initiate EH.
-		 */
-		host->host_eh_scheduled = 0;
-
 		spin_unlock_irqrestore(ap->lock, flags);
 		ata_eh_release(ap);
 	} else {

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

On Wed, Sep 07, 2011 at 01:33:55AM +0900, Tejun Heo wrote:
> Hello,
> 
> On Tue, Sep 06, 2011 at 01:19:44PM +0100, Bruce Stenning wrote:
> > ata4: EH complete
> > Waking error handler thread
> > scsi_eh_wakeup: succeeded
> > scsi_schedule_eh: succeeded
> > scsi_restart_operations: waking up host to restart
> > Error handler scsi_eh_3 sleeping
> 
> I think the following should fix the problem.  The code there is from
> the time when libata shared scsi_host->host_lock.  libata no longer
> does that so, in the current state, host_eh_scheduled can be cleared
> with actual pending EH condition.

Hmmm... maybe not.  Such race condition exists iff host_eh_scheduled
is incremented outside of ap->lock, which I can't see how.  Weird.
Can you please instrument the followings?

* print the caller of scsi_eh_wakeup().  "%pF" w/ (void *)_RET_IP_
  should do it.

* print why scsi_eh is going back to sleep immediately.
  ie. shost->host_failed, host_eh_scheduled, host_busy in
  scsi_error_handler().  It would also be nice to add some printks
  around schedule() and enable PRINTK_TIME.

Thanks.

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

Hi Tejun,

Sorry for sending so many emails yesterday; I blame the dental anaesthetic
I received in the morning for being so jumpy on the send button ;-)

> Can you please instrument the followings?
>
> * print the caller of scsi_eh_wakeup().  "%pF" w/ (void *)_RET_IP_
>   should do it.
>
> * print why scsi_eh is going back to sleep immediately.
>   ie. shost->host_failed, host_eh_scheduled, host_busy in
>   scsi_error_handler().  It would also be nice to add some printks
>   around schedule() and enable PRINTK_TIME.

I can certainly try this.  Could you confirm whether my thoughts about a race
between the scsi_eh thread and the wake-up are plausible?  I backtracked
yesterday because I thought the scsi_eh thread would get rescheduled naturally,
not realising that when the task state is TASK_INTERRUPTIBLE schedule() takes
the task off the run queue (so it needs to be explicitly woken.)

Here is my thinking again:

shost->host_eh_scheduled is read here in scsi_error_handler:

        set_current_state(TASK_INTERRUPTIBLE);
        while (!kthread_should_stop()) {
                if ((shost->host_failed == 0 && shost->host_eh_scheduled == 0) ||

There's no locking in scsi_error_handler (though functions it calls probably
claim locks.)

When scheduling an EH, scsi_schedule_eh takes the shost->host_lock, increments
shost->host_eh_scheduled, and then wakes the EH thread.  If this happens
between the scsi_eh thread reading host_eh_scheduled and sending itself back
to sleep (when the scsi_eh thread's state is TASK_INTERRUPTIBLE) nothing will
wake up the thread again and host_eh_scheduled will not get inspected.
host_eh_scheduled is stuck at 1 with the scsi_eh thread asleep, and it won't
get woken again because the ata port has been frozen and irqs are masked off.

Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

Hello,

On Wed, Sep 07, 2011 at 01:09:10PM +0100, Bruce Stenning wrote:
> Sorry for sending so many emails yesterday; I blame the dental anaesthetic
> I received in the morning for being so jumpy on the send button ;-)

Oh the fun. :)

> I can certainly try this.  Could you confirm whether my thoughts about a race
> between the scsi_eh thread and the wake-up are plausible?  I backtracked
> yesterday because I thought the scsi_eh thread would get rescheduled naturally,
> not realising that when the task state is TASK_INTERRUPTIBLE schedule() takes
> the task off the run queue (so it needs to be explicitly woken.)
> 
> Here is my thinking again:
> 
> shost->host_eh_scheduled is read here in scsi_error_handler:
> 
>         set_current_state(TASK_INTERRUPTIBLE);
>         while (!kthread_should_stop()) {
>                 if ((shost->host_failed == 0 && shost->host_eh_scheduled == 0) ||
> 
> There's no locking in scsi_error_handler (though functions it calls probably
> claim locks.)
> 
> When scheduling an EH, scsi_schedule_eh takes the shost->host_lock, increments
> shost->host_eh_scheduled, and then wakes the EH thread.  If this happens
> between the scsi_eh thread reading host_eh_scheduled and sending itself back
> to sleep (when the scsi_eh thread's state is TASK_INTERRUPTIBLE) nothing will
> wake up the thread again and host_eh_scheduled will not get inspected.
> host_eh_scheduled is stuck at 1 with the scsi_eh thread asleep, and it won't
> get woken again because the ata port has been frozen and irqs are masked off.

I don't think there's a race condition there.  set_current_state()
implies memory barrier and wake_up_process() implies wmb().  host_eh
either sees the inrecremented eh_scheduled count or TASK_RUNNING set
by wake_up_process(), so it can't miss an event.

Thanks.

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

I wrote:
> ata4: EH complete
> Waking error handler thread
> scsi_eh_wakeup: succeeded
> scsi_schedule_eh: succeeded
> scsi_restart_operations: waking up host to restart
> Error handler scsi_eh_3 sleeping

Sorry, I hit 'send' before thinking fully.  A short while before the above,
the following was logged:

Waking error handler thread
scsi_eh_wakeup: succeeded
Error handler scsi_eh_3 waking up

This suggests that scsi_error_handler was indeed running when the subsequent
wake-up was attempted.

Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

I wrote:
> Is it attempting to wake the scsi_eh_3 thread while scsi_error_handler
> is still processing an EH, which then calls scsi_restart_operations and
> puts the scsi_eh_3 thread back to sleep again?

It does look to me as if there is a potential race between the scsi_eh thread
and the wake-up mechanism.

host_eh_scheduled is read here in scsi_error_handler:

        set_current_state(TASK_INTERRUPTIBLE);
        while (!kthread_should_stop()) {
                if ((shost->host_failed == 0 && shost->host_eh_scheduled == 0) ||

For scheduling an EH, scsi_schedule_eh takes the shost->host_lock, increments
shost->host_eh_scheduled, and then wakes the EH thread.  If this happens
between the scsi_eh thread reading host_eh_scheduled and sending itself to
sleep, then nothing will wake up the thread and host_eh_scheduled will not
be inspected again.

Is there some mechanism that I've missed to prevent this from happening?


Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> Is there some mechanism that I've missed to prevent this from happening?

Okay, no, I guess the thread will naturally be rescheduled at some point,
at which point the shost->host_eh_scheduled will be re-inspected.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-26 11:41 AM, Bruce Stenning wrote:
> Tejun wrote:
>> Does the following patch resolve the problem?
>>
>> Thanks.
> 
> I have applied that patch, keeping Mark's mv_set_main_irq_mask spinlock patch
> in place.  I would not like to commit absolutely, for obvious reasons, but I
> have abused the port considerably and have not been able to coax it into
> locking up.

I'm thinking perhaps I should dust off that spinlock patch
and send something more proper like that upstream.

With that mask register shared among the ports, it is really
hard to keep track of when we're locked and when not.
So having a lock just for the shared part of the chip
has got to be a less error-prone way to do it.

I'll pull down a recent -git to patch against first.

Cheers

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

[-- Attachment #1: Type: text/plain, Size: 1885 bytes --]

On 11-04-12 06:30 AM, Bruce Stenning wrote:
..
> I am currently inserting tracing into 2.6.38.2 to try to work out what is going
> on.  From mv_write_main_irq_mask I can see that the IRQ for each port is still
> enabled, even when ports stop responding.
..
> One thing I noticed was that there is no spinlock around the
> mv_save_cached_regs/mv_edma_cfg in mv_hardreset (unlike mv_port_start and
> mv_port_stop); why is this?

Yeah, I'm suspecting there's a loophole in the logic there somewhere.

I dusted off the 6041 reference card I have here, and played with the cables
for a while.  Managed to get one port to stop responding to hot plug fairly
quickly, though I'm not sure how/why.

Then I added a debug printk() to mv_write_main_irq_mask(),
with no other changes, and that appears to have been enough
to change the race timing so that I could no longer produce
the problem.

Bruce, here's a slightly-ugly patch that should remove all
doubt about races in the irq_mask.  Please apply it, test with it,
and let me know here if the issue goes away.

Thanks

--- old/drivers/ata/sata_mv.c	2011-04-13 11:03:07.442481426 -0400
+++ linux/drivers/ata/sata_mv.c	2011-04-13 11:07:55.224249621 -0400
@@ -1027,15 +1027,19 @@
 static void mv_set_main_irq_mask(struct ata_host *host,
 				 u32 disable_bits, u32 enable_bits)
 {
+	static spinlock_t irq_mask_lock = __SPIN_LOCK_UNLOCKED(irq_mask_lock); //
FIXME: per-host would be nicer
 	struct mv_host_priv *hpriv = host->private_data;
 	u32 old_mask, new_mask;
+	unsigned long flags;

+	spin_lock_irqsave(&irq_mask_lock, flags);
 	old_mask = hpriv->main_irq_mask;
 	new_mask = (old_mask & ~disable_bits) | enable_bits;
 	if (new_mask != old_mask) {
 		hpriv->main_irq_mask = new_mask;
 		mv_write_main_irq_mask(new_mask, hpriv);
 	}
+	spin_unlock_irqrestore(&irq_mask_lock, flags);
 }

 static void mv_enable_port_irqs(struct ata_port *ap,

[-- Attachment #2: sata_mv_irq_mask_lock.patch --]
[-- Type: text/x-patch, Size: 824 bytes --]

--- old/drivers/ata/sata_mv.c	2011-04-13 11:03:07.442481426 -0400
+++ linux/drivers/ata/sata_mv.c	2011-04-13 11:07:55.224249621 -0400
@@ -1027,15 +1027,19 @@
 static void mv_set_main_irq_mask(struct ata_host *host,
 				 u32 disable_bits, u32 enable_bits)
 {
+	static spinlock_t irq_mask_lock = __SPIN_LOCK_UNLOCKED(irq_mask_lock); // FIXME: per-host would be nicer
 	struct mv_host_priv *hpriv = host->private_data;
 	u32 old_mask, new_mask;
+	unsigned long flags;
 
+	spin_lock_irqsave(&irq_mask_lock, flags);
 	old_mask = hpriv->main_irq_mask;
 	new_mask = (old_mask & ~disable_bits) | enable_bits;
 	if (new_mask != old_mask) {
 		hpriv->main_irq_mask = new_mask;
 		mv_write_main_irq_mask(new_mask, hpriv);
 	}
+	spin_unlock_irqrestore(&irq_mask_lock, flags);
 }
 
 static void mv_enable_port_irqs(struct ata_port *ap,

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> Yeah, I'm suspecting there's a loophole in the logic there somewhere.
>
> I dusted off the 6041 reference card I have here, and played with the cables for a while.  Managed to > get one port to stop responding to hot plug fairly quickly, though I'm not sure how/why.
>
> Then I added a debug printk() to mv_write_main_irq_mask(), with no other changes, and that appears to > have been enough to change the race timing so that I could no longer produce the problem.
>
> Bruce, here's a slightly-ugly patch that should remove all doubt about races in the irq_mask.  Please > apply it, test with it, and let me know here if the issue goes away.
>
> Thanks

Thanks Mark. I was about to try out some tracing in writelfl because I
suspected the irq mask was getting clobbered somewhere along the way, but
I'd been distracted by other work.  I shall try your patch out as soon as
I can, and report back.

Cheers,

Bruce.


Bruce Stenning,
IndigoVision,
b <dot> stenning <at> indigovision <dot> com


Latest News at: http://www.indigovision.com/index.php/en/news.html

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> > One thing I noticed was that there is no spinlock around the
> > mv_save_cached_regs/mv_edma_cfg in mv_hardreset (unlike mv_port_start
> > and mv_port_stop); why is this?
>
> Yeah, I'm suspecting there's a loophole in the logic there somewhere.
>
> I dusted off the 6041 reference card I have here, and played with the cables
> for a while.  Managed to get one port to stop responding to hot plug fairly
> quickly, though I'm not sure how/why.
>
> Then I added a debug printk() to mv_write_main_irq_mask(), with no other
> changes, and that appears to have been enough to change the race timing
> so that I could no longer produce the problem.
>
> Bruce, here's a slightly-ugly patch that should remove all doubt about races
> in the irq_mask.  Please apply it, test with it, and let me know here if the
> issue goes away.
>
> Thanks
>
> [patch]


Hi Mark,

I have tried the patch out and I was able to reproduce the port lockup with it.

I also tried out my tracing in writelfl (without any other changes) and I was
able to lock up a port without any apparent unusual changes to the register
containing the irq masks.  Are there other routes to disabling the irqs?

I shall continue looking.

Cheers,

Bruce.


Bruce Stenning,
IndigoVision,
b <dot> stenning <at> indigovision <dot> com


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-14 12:50 PM, Bruce Stenning wrote:
..
> I have tried the patch out and I was able to reproduce the port lockup with it.

Bummer.

> I also tried out my tracing in writelfl (without any other changes) and I was
> able to lock up a port without any apparent unusual changes to the register
> containing the irq masks.  Are there other routes to disabling the irqs?


Mmm.. presumably you are NOT using MSI interrupts, right?

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> > I also tried out my tracing in writelfl (without any other changes) and I was
> > able to lock up a port without any apparent unusual changes to the register
> > containing the irq masks.  Are there other routes to disabling the irqs?
>
> Mmm.. presumably you are NOT using MSI interrupts, right?

Hi Mark,

That is correct:

sata_mv 0000:00:04.0: Gen-II 32 slots 4 ports SCSI mode IRQ via INTx

I am building with CONFIG_ARCH_SUPPORTS_MSI=y, but also with CONFIG_PCI_MSI
not set.

With all this discussion of SATA link speed, I ought to say that we limit our
SATA links to 1.5Gbps with the following kernel parameter:

libata.force=1.5g

I had noticed occasional messages similar to the following earlier in the week:

ata4.00: limiting speed to UDMA/100:PIO4

I was surprised to see them, and thought they might be related to the hotplug
issues, but I was able to reproduce the lockups without these messages being
generated.  In some cases (but not all) both sata_down_spd_limit and
ata_down_xfermask_limit are called when backing off the link speed.

Mark, I was intrigued by your comment from the following message:

http://www.spinics.net/lists/linux-ide/msg36922.html
> If it's like their non-AHCI controllers (sata_mv), then the chipset/phy
> could be very particular about the sequence/timing used when changing speeds.

Is it possible that the driver is doing some of the work to change the link
speed (even though it has nowhere to go) and clobbering the link entirely?
I shall take another closer look at the source code and tracing around hotplug
w.r.t. link speed.


Cheers,

Bruce.


Bruce Stenning,
IndigoVision,
b <dot> stenning <at> indigovision <dot> com


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-15 09:21 AM, Bruce Stenning wrote:
..
> sata_mv 0000:00:04.0: Gen-II 32 slots 4 ports SCSI mode IRQ via INTx
..
> 
> I had noticed occasional messages similar to the following earlier in the week:
> 
> ata4.00: limiting speed to UDMA/100:PIO4

Ugh.   Tejun:  that's just plain silly.
Why would we EVER EVER EVER fall back to "PIO" for SATA ???


> I am building with CONFIG_ARCH_SUPPORTS_MSI=y, but also with CONFIG_PCI_MSI
> not set.
> 
> With all this discussion of SATA link speed, I ought to say that we limit our
> SATA links to 1.5Gbps with the following kernel parameter:
> 
> libata.force=1.5g

Mmm... I suppose it could be getting stuck at 1.5g,
and not transitioning back to "auto detect" or something.

That part of sata_mv involves a bit of voo-doo,
because I was reluctant to cut/paste the 200 lines or so
of generic code just for the sake of changing five lines.

Perhaps the generic code has changed since this was originally working,
and now no longer always works for sata_mv..

I suppose you have a good reason for using "libata.force=1.5g" there?

Cheers

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Bruce Stenning]

> > libata.force=1.5g
>
> Mmm... I suppose it could be getting stuck at 1.5g,
> and not transitioning back to "auto detect" or something.
>
> That part of sata_mv involves a bit of voo-doo,
> because I was reluctant to cut/paste the 200 lines or so
> of generic code just for the sake of changing five lines.
>
> Perhaps the generic code has changed since this was originally working,
> and now no longer always works for sata_mv..
>
> I suppose you have a good reason for using "libata.force=1.5g" there?

Hi Mark,

I hope you had a good weekend.

The SATA speed was limited because there were concerns over signal integrity at
3Gbps early on in our product development, and even at 1.5Gbps the SATA links
are not a bottleneck in our platform.  The signal integrity issues have been
addressed, and we would like to remove the limit, but this obviously has an
additional test overhead and it is low down on our priorities.

Out of interest I examined the behaviour of the hotplug with the 1.5Gbps limit
removed, but I saw no change in the port lockup behaviour.


Cheers,

Bruce.


Latest News at: http://www.indigovision.com/index.php/en/news.html

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Tejun Heo]

On Fri, Apr 15, 2011 at 11:36:38AM -0400, Mark Lord wrote:
> On 11-04-15 09:21 AM, Bruce Stenning wrote:
> ..
> > sata_mv 0000:00:04.0: Gen-II 32 slots 4 ports SCSI mode IRQ via INTx
> ..
> > 
> > I had noticed occasional messages similar to the following earlier in the week:
> > 
> > ata4.00: limiting speed to UDMA/100:PIO4
> 
> Ugh.   Tejun:  that's just plain silly.
> Why would we EVER EVER EVER fall back to "PIO" for SATA ???

Nah, it's just printing both DMA and PIO speed settings.  It's limited
to UDMA/100 not PIO4.

Thanks.

-- 
tejun

RE: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mikael Abrahamsson]

On Fri, 8 Apr 2011, Bruce Stenning wrote:

> The 2.6.38.2 kernel still exhibits the same lockups that we see with the 
> 2.6.26 kernel.

Hi.

I have some input on this. I have one of these controllers and had 
problems with one channel where if I had a drive in that hotswap bay, the 
controller wouldn't even POST at boot. It just stuck in the detection 
phase in the controller BIOS.

When I tested hotplugging into that bay when the system was running, I 
received a kernel warning (it's not powered on at the moment so I can't 
provide the output, if it's important I can get it).

My point is that there might be a problem with this controller hw or 
firmware that doesn't handle all behaviour/situations properly. I 
re-seated the SATA cable at both ends and after that couldn't reproduce 
the problem (which was reproduced with two different make harddrives 
several times before re-seating the cable).

This was with the 2.6.32 debian stable kernel, AMD64 version.

-- 
Mikael Abrahamsson    email: swmike@swm.pp.se

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-14 11:15 PM, Mikael Abrahamsson wrote:
> On Fri, 8 Apr 2011, Bruce Stenning wrote:
> 
>> The 2.6.38.2 kernel still exhibits the same lockups that we see with the
>> 2.6.26 kernel.
> 
> Hi.
> 
> I have some input on this. I have one of these controllers and had problems with
> one channel where if I had a drive in that hotswap bay, the controller wouldn't
> even POST at boot. It just stuck in the detection phase in the controller BIOS.
> 
> When I tested hotplugging into that bay when the system was running, I received
> a kernel warning (it's not powered on at the moment so I can't provide the
> output, if it's important I can get it).

I would like to see the output, next time you can get it.

The thing with the 6041 chip, is that I actually have all of the Marvell
documentation and errata info for the chip.  So in theory, we know everything
about it, and there are no secret failure modes yet to be discovered.
The sata_mv driver does not depend on the board's BIOS for anything either.

That's the theory, anyway.  :)

Cheers

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mikael Abrahamsson]

On Thu, 14 Apr 2011, Mark Lord wrote:

> I would like to see the output, next time you can get it.

Apr 14 18:39:54 host kernel: [  137.276051] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Apr 14 18:39:54 host kernel: [  137.284557] ------------[ cut here ]------------
Apr 14 18:39:54 host kernel: [  137.284626] WARNING: at /build/buildd-linux-2.6_2.6.32-31-amd64-vrfdM4/linux-2.6-2.6.32/debian/build/source_amd64_none/drivers/ata/libata-sff.c:1208 ata_sff_hsm_move+0x47/0x642 [libata]()
Apr 14 18:39:54 host kernel: [  137.284733] Hardware name: P5E WS Pro
Apr 14 18:39:54 host kernel: [  137.284797] Modules linked in: ext2 loop snd_pcm snd_timer snd soundcore snd_page_alloc i2c_i801 i2c_core evdev pcspkr asus_atk0110 x38_edac shpchp pci_hotplug edac_core button processor ext3 jbd mbcache sha256_generic aes_x86_64 aes_generic cbc dm_crypt dm_mod usbhid hid sd_mod crc_t10dif sata_mv uhci_hcd sata_sil24 ahci mpt2sas libata sky2 scsi_transport_sas thermal ehci_hcd thermal_sys scsi_mod usbcore nls_base [last unloaded: scsi_wait_scan]
Apr 14 18:39:54 host kernel: [  137.286426] Pid: 240, comm: ata/1 Not tainted 2.6.32-5-amd64 #1
Apr 14 18:39:54 host kernel: [  137.286482] Call Trace:
Apr 14 18:39:54 host kernel: [  137.286536]  [<ffffffffa00b1438>] ? ata_sff_hsm_move+0x47/0x642 [libata]
Apr 14 18:39:54 host kernel: [  137.286597]  [<ffffffffa00b1438>] ? ata_sff_hsm_move+0x47/0x642 [libata]
Apr 14 18:39:54 host kernel: [  137.286658]  [<ffffffff8104df00>] ? warn_slowpath_common+0x77/0xa3
Apr 14 18:39:54 host kernel: [  137.286718]  [<ffffffffa00b1438>] ? ata_sff_hsm_move+0x47/0x642 [libata]
Apr 14 18:39:54 host kernel: [  137.286780]  [<ffffffffa00b1d87>] ? ata_pio_task+0x9a/0xa6 [libata]
Apr 14 18:39:54 host kernel: [  137.286838]  [<ffffffff8106186b>] ? worker_thread+0x188/0x21d
Apr 14 18:39:54 host kernel: [  137.286897]  [<ffffffffa00b1ced>] ? ata_pio_task+0x0/0xa6 [libata]
Apr 14 18:39:54 host kernel: [  137.286955]  [<ffffffff81064e96>] ? autoremove_wake_function+0x0/0x2e
Apr 14 18:39:54 host kernel: [  137.287012]  [<ffffffff810616e3>] ? worker_thread+0x0/0x21d
Apr 14 18:39:54 host kernel: [  137.287068]  [<ffffffff81064bc9>] ? kthread+0x79/0x81
Apr 14 18:39:54 host kernel: [  137.287124]  [<ffffffff81011baa>] ? child_rip+0xa/0x20
Apr 14 18:39:54 host kernel: [  137.292927]  [<ffffffff81064b50>] ? kthread+0x0/0x81
Apr 14 18:39:54 host kernel: [  137.292984]  [<ffffffff81011ba0>] ? child_rip+0x0/0x20
Apr 14 18:39:54 host kernel: [  137.293041] ---[ end trace 0ce5491cb936fb17 ]---
Apr 14 18:39:54 host kernel: [  137.306180] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x2)

-- 
Mikael Abrahamsson    email: swmike@swm.pp.se

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-15 03:43 AM, Mikael Abrahamsson wrote:
> On Thu, 14 Apr 2011, Mark Lord wrote:
>
>> I would like to see the output, next time you can get it.
>

>Apr 14 18:39:54 host kernel: [  137.276051] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
>Apr 14 18:39:54 host kernel: [  137.284557] ------------[ cut here ]------------
>Apr 14 18:39:54 host kernel: [  137.284626] WARNING: at /build/buildd-linux-2.6_2.6.32-31-amd64-vrfdM4/linux-2.6-2.6.32/debian/build/source_amd64_none/drivers/ata/libata-sff.c:1208 ata_sff_hsm_move+0x47/0x642 [libata]()
>Apr 14 18:39:54 host kernel: [  137.284733] Hardware name: P5E WS Pro
>Apr 14 18:39:54 host kernel: [  137.284797] Modules linked in: ext2 loop snd_pcm snd_timer snd soundcore snd_page_alloc i2c_i801 i2c_core evdev pcspkr asus_atk0110 x38_edac shpchp pci_hotplug edac_core button processor ext3 jbd mbcache sha256_generic aes_x86_64 aes_generic cbc dm_crypt dm_mod usbhid hid sd_mod crc_t10dif sata_mv uhci_hcd sata_sil24 ahci mpt2sas libata sky2 scsi_transport_sas thermal ehci_hcd thermal_sys scsi_mod usbcore nls_base [last unloaded: scsi_wait_scan]
>Apr 14 18:39:54 host kernel: [  137.286426] Pid: 240, comm: ata/1 Not tainted 2.6.32-5-amd64 #1
>Apr 14 18:39:54 host kernel: [  137.286482] Call Trace:
>Apr 14 18:39:54 host kernel: [  137.286536]  [<ffffffffa00b1438>] ? ata_sff_hsm_move+0x47/0x642 [libata]
>Apr 14 18:39:54 host kernel: [  137.286597]  [<ffffffffa00b1438>] ? ata_sff_hsm_move+0x47/0x642 [libata]
>Apr 14 18:39:54 host kernel: [  137.286658]  [<ffffffff8104df00>] ? warn_slowpath_common+0x77/0xa3
>Apr 14 18:39:54 host kernel: [  137.286718]  [<ffffffffa00b1438>] ? ata_sff_hsm_move+0x47/0x642 [libata]
>Apr 14 18:39:54 host kernel: [  137.286780]  [<ffffffffa00b1d87>] ? ata_pio_task+0x9a/0xa6 [libata]
>Apr 14 18:39:54 host kernel: [  137.286838]  [<ffffffff8106186b>] ? worker_thread+0x188/0x21d
>Apr 14 18:39:54 host kernel: [  137.286897]  [<ffffffffa00b1ced>] ? ata_pio_task+0x0/0xa6 [libata]
>Apr 14 18:39:54 host kernel: [  137.286955]  [<ffffffff81064e96>] ? autoremove_wake_function+0x0/0x2e
>Apr 14 18:39:54 host kernel: [  137.287012]  [<ffffffff810616e3>] ? worker_thread+0x0/0x21d
>Apr 14 18:39:54 host kernel: [  137.287068]  [<ffffffff81064bc9>] ? kthread+0x79/0x81
>Apr 14 18:39:54 host kernel: [  137.287124]  [<ffffffff81011baa>] ? child_rip+0xa/0x20
>Apr 14 18:39:54 host kernel: [  137.292927]  [<ffffffff81064b50>] ? kthread+0x0/0x81
>Apr 14 18:39:54 host kernel: [  137.292984]  [<ffffffff81011ba0>] ? child_rip+0x0/0x20
>Apr 14 18:39:54 host kernel: [  137.293041] ---[ end trace 0ce5491cb936fb17 ]---
>Apr 14 18:39:54 host kernel: [  137.306180] ata9.00: failed to IDENTIFY (I/O error, err_mask=0x2)

That's interesting.  It really appears have not a lot to do with sata_mv,
though there's no guarantee there.

Tejun -- this is 2.6.32, libata trying to identify a newly hot-plugged drive,
and hitting a warning in libata-sff.c.  Looks self-inflicted to me!  :)

Mikael -- any chance you could someday retry this on 2.6.38.2 ?

Thanks

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mikael Abrahamsson]

On Fri, 15 Apr 2011, Mark Lord wrote:

> Mikael -- any chance you could someday retry this on 2.6.38.2 ?

Well, since the problem went away after I re-seated the SATA cable, I 
don't think I'll even be able to reproduce it with 2.6.32.

-- 
Mikael Abrahamsson    email: swmike@swm.pp.se

Re: sata_mv port lockup on hotplug (kernel 2.6.38.2)

[Mark Lord]

On 11-04-15 10:04 AM, Mikael Abrahamsson wrote:
> On Fri, 15 Apr 2011, Mark Lord wrote:
> 
>> Mikael -- any chance you could someday retry this on 2.6.38.2 ?
> 
> Well, since the problem went away after I re-seated the SATA cable, I don't
> think I'll even be able to reproduce it with 2.6.32.


Right.  Thanks.