Patchwork SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller

login
register
mail settings
Submitter Tejun Heo
Date June 10, 2011, 10:24 a.m.
Message ID <20110610102403.GE15235@htj.dyndns.org>
Download mbox | patch
Permalink /patch/99874/
State Not Applicable
Delegated to: David Miller
Headers show

Comments

Tejun Heo - June 10, 2011, 10:24 a.m.
Hello,

Cc'ing marvell people.  The original thread can be read from the
following URL.

  http://thread.gmane.org/gmane.linux.ide/49658

On Thu, Jun 09, 2011 at 10:11:27PM +0100, Tim Small wrote:
> Thanks very much for your patch - I gave it a spin (against Debian's
> 2.6.38 kernel) - it's apparently working better than before, but still a
> bit wonky...
...
> Unplugging from the 3132 (and waiting for things to settle), then
> plugging into the 88SE9123 gives the following...
> 
> 541.610033] ata14: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action
> 0xe frozen
> 541.610166] ata14: irq_stat 0x80400040, connection status changed
> 541.610277] ata14: SError: { PHYRdyChg CommWake DevExch }
> 541.610391] ata14: hard resetting link
> 543.288743] ata14: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
> 543.289086] ata14.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
> feat 0x1/0x9
> 543.289220] ahci 0000:01:00.0: FBS is enabled.
> 543.289418] ata14.00: hard resetting link
> 543.608852] ata14.00: SATA link up 1.5 Gbps (SStatus 113 SControl 320)
> 543.609031] ata14.01: hard resetting link
> 543.928756] ata14.01: SATA link down (SStatus 0 SControl 320)
> 543.928943] ata14.02: hard resetting link
> 544.248663] ata14.02: SATA link down (SStatus 0 SControl 320)
> 544.248856] ata14.03: hard resetting link
> 544.568553] ata14.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> 544.880294] ata14.05: no reset method available, skipping reset
> 544.880594] ata14.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> 544.881914] ata14.03: ATA-7: Hitachi HUA721010KLA330, GKAOAB0A, max UDMA/133
> 544.882099] ata14.03: 1953525168 sectors, multi 0: LBA48 NCQ (depth
> 31/32), AA
> 544.883774] ata14.03: configured for UDMA/133
> 544.883987] ata14: EH complete
> 544.884213] scsi 13:3:0:0: Direct-Access     ATA      Hitachi HUA72101
> GKAO PQ: 0 ANSI: 5
> 544.884750] sd 13:3:0:0: [sdb] 1953525168 512-byte logical blocks: (1.00
> TB/931 GiB)
> 544.884879] sd 13:3:0:0: [sdb] Write Protect is off
> 544.884892] sd 13:3:0:0: [sdb] Mode Sense: 00 3a 00 00
> 544.884957] sd 13:3:0:0: [sdb] Write cache: enabled, read cache:
> enabled, doesn't support DPO or FUA
> 544.897087]  sdb: sdb1 sdb2 < sdb5 >
> 544.897519] sd 13:3:0:0: [sdb] Attached SCSI disk
> 
> ... so definitely some progress, but the Maxtor drive on PMP port zero
> hasn't been found...

That's weird.  Link is up but EH is detected to be up but EH didn't
probe it.  Is the behavior reproducible?

> I then hot-un-plugged the Maxtor from the pmp and got this lot:
> 
>  709.515101] ata14.15: PMP product ID mismatch
>  709.515256] ata14.15: hard resetting link
>  715.043716] ata14.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
>  715.044020] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
>  715.044191] ata14.15: PMP revalidation failed (errno=-19)
>  715.044352] ata14.15: limiting SATA link speed to 1.5 Gbps
>  720.042049] ata14.15: hard resetting link
>  725.572222] ata14.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
>  725.572595] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
>  725.572767] ata14.15: PMP revalidation failed (errno=-19)
>  730.570649] ata14.15: hard resetting link
>  736.100725] ata14.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
>  736.101093] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
>  736.101259] ata14.15: PMP revalidation failed (errno=-19)
>  736.101417] ata14.15: failed to recover PMP after 5 tries, giving up
>  736.101578] ata14.15: Port Multiplier detaching

This shouldn't happen and seems to be the same problem which triggered
before.  I don't think this is caused by 3726.  The problem is likely
on the controller side.

>  741.099118] ata14: hard resetting link
>  746.629228] ata14: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
>  746.629636] ata14.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
> feat 0x1/0x9

So, detaching & re-attaching the PMP brings it back.  Maybe the
controller requires flipping PORT_CMD_PMP after an exception?

> Plugging the Maxtor back in then gave:
> 
> 813.046630] ata14.15: PMP product ID mismatch
> 813.046787] ata14.15: hard resetting link
> 814.766608] ata14.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
> 814.766916] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
> 814.767080] ata14.15: PMP revalidation failed (errno=-19)
...

Ths same problem triggering again.

> 833.208478] ata14: hard resetting link
> 834.931910] ata14: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
> 834.932300] ata14.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
> feat 0x1/0x9
...
> 837.323334] sd 13:0:0:0: [sdb] 240121728 512-byte logical blocks: (122
> GB/114 GiB)
> 837.324358] sd 13:3:0:0: [sdc] 1953525168 512-byte logical blocks: (1.00
> TB/931 GiB)

And after re-attaching, at least detection worked, so that's
something.

> .... and reading from each disk individually works, but reading from
> both at the same time doesn't (I/Os time-out, and then the whole lot
> gets reset).

Maybe FBS support doesn't work as advertised?  Can you please try the
following patch?


Thanks.
Tim Small - June 10, 2011, 4:43 p.m.
On 10/06/11 11:24, Tejun Heo wrote:
> That's weird.  Link is up but EH is detected to be up but EH didn't
> probe it.  Is the behavior reproducible?
>   

I think-so, yes.  I'll double-check.

> Maybe FBS support doesn't work as advertised?  Can you please try the
> following patch?
>
> diff --git a/drivers/ata/libahci.c b/drivers/ata/libahci.c
> index d38c40f..a2f4b68 100644
> --- a/drivers/ata/libahci.c
> +++ b/drivers/ata/libahci.c
> @@ -444,6 +444,7 @@ void ahci_save_initial_config(struct device *dev,
>  			   "controller can do FBS, turning on CAP_FBS\n");
>  		cap |= HOST_CAP_FBS;
>  	}
> +	cap &= ~HOST_CAP_FBS;
>  
>  	if (force_port_map && port_map != force_port_map) {
>  		dev_printk(KERN_INFO, dev, "forcing port_map 0x%x -> 0x%x\n",
>
>   

OK, will do thanks - I assume this'll force command based switching,
with it's associated crappy performance tho'...

I've ordered an 88SE9128 card (Hightpoint RocketRaid 620) as well, so
I'll be able to compare the two, as well as a sata_mv 88SX7042 as well.

Cheers,

Tim.
--
To unsubscribe from this list: send the line "unsubscribe linux-ide" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Tim Small - July 6, 2011, 8:34 p.m.
On 10/06/11 17:43, Tim Small wrote:
>
> I've ordered an 88SE9128 card (Hightpoint RocketRaid 620) as well, so
> I'll be able to compare the two, as well as a sata_mv 88SX7042 as well.
>   

OK, so in fact it seems that I'd ordered a RocketRaid 620WDA - which has
an 88SE9125 on it, not a 88SE9128 (as the 620 has).

If I remember correctly (it was a couple of weeks ago now - just before
I went on holiday) the 620WDA did actually work with the SiI 3726 PMP in
FSC mode, when I was using the original HighPoint firmware which it
shipped with, but it doesn't when I use the Marvell Firmware (I didn't
want to try the Marvell firmware on the 620WDA, but the Marvell firmware
update utility I had "upgraded" it - and now I can't put the Highpoint
firmware back on it - partly because I don't have a copy of it anywhere).

I was actually trying to upgrade the 88SE9123 firmware at the time -
that turned out to be quite a lot more difficult than I was expecting:

http://buttersideup.com/files/flashrom/lycom-pe115-flashrom-buspirate-2.jpg

http://buttersideup.com/files/flashrom/at26f004-support.patch

Marvell guys - can you tell whoever writes your DOS "mvf.exe" firmware
updater for the 88SExxxx cards, that the update process fails to
unprotect sectors on Atmel AT26F004 SPI flash chips - it also fails to
check for protected sectors prior to attempting programming - so that
you end up with part of one firmware version together with parts (which
were in protected sectors) of whatever was there before.  Also -
actually automatically backing up the previous firmware would be nice,
as well as some instructions for going back to the previous version in a
README file (PLEASE PLEASE PLEASE), instead of leaving the users to
scour the Internet for solutions to restoring non-working cards:

http://www.station-drivers.com/forum/viewtopic.php?p=11162#p11163

... oh, and whilst I think about it, when upgrading the flash on a
machine with multiple adaptors - if the updater fails to successfully
update one adaptor, maybe it should then STOP, rather than steaming on
and breaking the rest of the cards in the same machine one after the other?


Anyway, after all that I didn't actually get working PMP support with
either card - at least not with that particular firmware image (which
contains the version string: 1.0.0.1028 and is in "U3S6R0.zip" from
http://www.station-drivers.com/page/marvell.htm ) the 88SE9125 seems to
read successfully, but gives extremely slow read speeds - around 1
megabyte per second for simultaneous drive accesses in FBS mode, whereas
the 88SE9123 gives the same behaviour as it did with the original
firmware i.e. timeouts + resets during simultaneous reads in FBS mode.



Is there a different firmware version which I should be trying with this
card?  Any chance of an actual changelog for the different firmware
versions?

Anyone have a 620WDA and wouldn't mind backing up the firmware from it
for me?

Is there a datasheet for the 88SE91xx chips around that I can get hold
of - NDA or otherwise?

Thanks,

Tim.
--
To unsubscribe from this list: send the line "unsubscribe linux-ide" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Tim Small - July 7, 2011, 12:13 p.m.
A few more data points on this issue:

I've tried the 88SE9123 and the 88SE9125 card in a Windows XP machine (a
relatively slow PCI-e gen1 box), and have these results:

2x 2G Hitachi drives connected via a SiI 3726, and to a SiI 3132: works
for simultaneous reads with hdparm (for Windows -
http://hdparm-win32.dyndns.org/hdparm/ - simultaneous read done with
"start /b hdparm -t /dev/sdb & hdparm -t /dev/sdc" at windows command
prompt) - read speeds at 60M per second on both drives.  Reads from a
single drive at 115M per second.  Reads from a single drive (direct to
host, not via PMP) at 117M per second.


2x 2G Hitachi drives connected via a SiI 3726, and to a SiI 3132 (Debian
6.0 2.6.32 NCQ depth any) - works for simultaneous reads with hdparm -
read speeds at 60M per second on both drives.  Reads from a single drive
at 122M per second.  Reads from a single drive (direct to host, not via
PMP) at 121M per second.



2x 2G Hitachi drives connected via a SiI 3726, and to the 88SE9123 card
(Windows XP mv91xx.sys v1.1.0.6 14-Feb-2011 ) - works for simultaneous
reads with hdparm - read speeds at 60M per second on both drives.  Reads
from a single drive at 117M per second.  Reads from a single drive
(direct to host, not via PMP) at 130M per second.


2x 2G Hitachi drives connected via a SiI 3726, and to the 88SE9123 card
( Debian 6.0  2.6.32 NCQ depth 31 - same with any value between 2 and 31
) - works for simultaneous reads with hdparm - read speeds at 30M per
second on both drives.  Reads from a single drive at 130M per second. 
Reads from a single drive (direct to host, not via PMP) at 130M per second.


2x 2G Hitachi drives connected via a SiI 3726, and to the 88SE9123 card
( Debian 6.0  2.6.32 NCQ depth 1 ) - works for simultaneous reads with
hdparm - read speeds at 60M per second on both drives.  Reads from a
single drive at 130M per second.  Reads from a single drive (direct to
host, not via PMP) at 130M per second.



2x 2G Hitachi drives connected via a SiI 3726, and to the 88SE9125 card
( Debian 6.0  2.6.32 NCQ depth 31  - same with any value between 2 and
31 ) - works for simultaneous reads with hdparm - read speeds at 31M per
second on both drives.  Reads from a single drive at between 19M per
second and 130M per second with NCQ depth = 31 (most often 130M), but
reads from a single drive with NCQ depth = 2 varied between 5M per
second and 54M per second.  Reads from a single drive (direct to host,
not via PMP) at 130M per second (127M per second with depth = 2).


2x 2G Hitachi drives connected via a SiI 3726, and to the 88SE9125 card
( Debian 6.0  2.6.32 NCQ 1 ) - works for simultaneous reads with hdparm
- read speeds at 60M per second on both drives.  Reads from a single
drive at 130M per second.  Reads from a single drive (direct to host,
not via PMP) at 126M per second (consistantly 3M per second slower than
via PMP!).


Gotta dash, more testing later...

Tim.
Tim Small - July 7, 2011, 6:30 p.m.
On 07/07/11 13:13, Tim Small wrote:
> 2x 2G Hitachi drives connected via a SiI 3726, and to the 88SE9125 card
> ( Debian 6.0  2.6.32 NCQ depth 31  - same with any value between 2 and
> 31 ) - works for simultaneous reads with hdparm - read speeds at 31M per
> second on both drives.  Reads from a single drive at between 19M per
> second and 130M per second with NCQ depth = 31 (most often 130M), but
> reads from a single drive with NCQ depth = 2 varied between 5M per
> second and 54M per second.  Reads from a single drive (direct to host,
> not via PMP) at 130M per second (127M per second with depth = 2).
>   

In the same machine, but with 2.6.38 (debian squeeze backports kernel):

NCQ 31, two drives connected to 3726 behind the **88SE9125** :

root@netboot:~# hdparm -t /dev/sdb

/dev/sdb:
 Timing buffered disk reads: 386 MB in  3.00 seconds = 128.59 MB/sec
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads:  38 MB in  7.01 seconds =   5.42 MB/sec
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads: read(2097152) returned 823296 bytes
BLKFLSBUF failed: No such device

This coincides with the following dmesg:

[  102.880043] ata3.00: failed to read SCR 1 (Emask=0x40)
[  102.884798] ata3.01: failed to read SCR 1 (Emask=0x40)
[  102.889604] ata3.02: failed to read SCR 1 (Emask=0x40)
[  102.894352] ata3.03: failed to read SCR 1 (Emask=0x40)
[  102.899057] ata3.04: failed to read SCR 1 (Emask=0x40)
[  102.903730] ata3.05: failed to read SCR 1 (Emask=0x40)
[  102.908365] ata3.15: exception Emask 0x4 SAct 0x0 SErr 0x400000
action 0x6 frozen
[  102.913067] ata3.15: SError: { Handshk }
[  102.917727] ata3.00: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.922460] ata3.01: exception Emask 0x100 SAct 0x7 SErr 0x0 action
0x6 frozen
[  102.927107] ata3.01: failed command: READ FPDMA QUEUED
[  102.931757] ata3.01: cmd 60/98:00:00:47:02/00:00:00:00:00/40 tag 0
ncq 77824 in
[  102.931761]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[  102.941055] ata3.01: status: { DRDY }
[  102.945643] ata3.01: failed command: READ FPDMA QUEUED
[  102.950234] ata3.01: cmd 60/68:08:98:47:02/00:00:00:00:00/40 tag 1
ncq 53248 in
[  102.950238]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[  102.959550] ata3.01: status: { DRDY }
[  102.964223] ata3.01: failed command: READ FPDMA QUEUED
[  102.968945] ata3.01: cmd 60/b8:10:48:46:02/00:00:00:00:00/40 tag 2
ncq 94208 in
[  102.968949]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[  102.978510] ata3.01: status: { DRDY }
[  102.983270] ata3.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.988128] ata3.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.992942] ata3.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.997719] ata3.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  103.002468] ata3.15: hard resetting link
[  103.720029] ata3.15: SATA link up 3.0 Gbps (SStatus 123 SControl 330)
[  103.725058] ata3.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[  103.729797] ata3.15: PMP revalidation failed (errno=-19)
[  108.724032] ata3.15: hard resetting link
[  109.444033] ata3.15: SATA link up 3.0 Gbps (SStatus 123 SControl 330)
[  109.448924] ata3.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[  109.453679] ata3.15: PMP revalidation failed (errno=-19)
[  109.458399] ata3.15: limiting SATA link speed to 1.5 Gbps
[  114.448029] ata3.15: hard resetting link
[  115.168034] ata3.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[  115.173007] ata3.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[  115.177781] ata3.15: PMP revalidation failed (errno=-19)
[  115.182541] ata3.15: failed to recover PMP after 5 tries, giving up
[  115.187291] ata3.15: Port Multiplier detaching
[  115.191959] ata3.00: disabled
[  115.196572] ata3.01: disabled
[  115.201115] ata3.00: disabled
[  120.172024] ata3: hard resetting link
[  120.892037] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 330)
[  120.896695] ata3.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x1/0x9
[  120.901169] ahci 0000:01:00.0: FBS is enabled.
[  120.905800] ata3.00: hard resetting link
[  121.228222] ata3.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[  121.232855] ata3.01: hard resetting link
[  121.556224] ata3.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[  121.560862] ata3.02: hard resetting link
[  121.884223] ata3.02: SATA link down (SStatus 0 SControl 320)
[  121.888866] ata3.03: hard resetting link
[  122.212222] ata3.03: SATA link down (SStatus 0 SControl 320)
[  122.216721] ata3.04: hard resetting link
[  122.540221] ata3.04: SATA link down (SStatus 0 SControl 320)
[  122.544633] ata3.05: hard resetting link
[  122.868232] ata3.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320)
[  122.873827] ata3.00: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[  122.878067] ata3.00: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[  122.883669] ata3.00: configured for UDMA/133
[  122.889185] ata3.01: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[  122.893487] ata3.01: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[  122.899114] ata3.01: configured for UDMA/133
[  122.903547] ata3.01: device reported invalid CHS sector 0
[  122.907930] ata3.01: device reported invalid CHS sector 0
[  122.912322] ata3.01: device reported invalid CHS sector 0
[  122.916715] sd 1:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[  122.921135] sd 1:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[  122.925558] Descriptor sense data with sense descriptors (in hex):
[  122.929959]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[  122.934528]         00 00 00 00
[  122.938953] sd 1:1:0:0: [sdc]  Add. Sense: No additional sense
information
[  122.943428] sd 1:1:0:0: [sdc] CDB: Read(10): 28 00 00 02 47 00 00 00
98 00
[  122.947984] end_request: I/O error, dev sdc, sector 149248
[  122.952425] Buffer I/O error on device sdc, logical block 18656
[  122.956888] Buffer I/O error on device sdc, logical block 18657
[  122.961268] Buffer I/O error on device sdc, logical block 18658
[  122.965594] Buffer I/O error on device sdc, logical block 18659
[  122.969830] Buffer I/O error on device sdc, logical block 18660
[  122.974033] Buffer I/O error on device sdc, logical block 18661
[  122.978172] Buffer I/O error on device sdc, logical block 18662
[  122.982256] Buffer I/O error on device sdc, logical block 18663
[  122.986239] Buffer I/O error on device sdc, logical block 18664
[  122.990165] Buffer I/O error on device sdc, logical block 18665
[  122.994116] sd 1:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[  122.998160] sd 1:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[  123.002283] Descriptor sense data with sense descriptors (in hex):
[  123.006370]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[  123.010586]         00 00 00 00
[  123.014657] sd 1:1:0:0: [sdc]  Add. Sense: No additional sense
information
[  123.018792] sd 1:1:0:0: [sdc] CDB: Read(10): 28 00 00 02 47 98 00 00
68 00
[  123.023005] end_request: I/O error, dev sdc, sector 149400
[  123.027149] sd 1:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[  123.031332] sd 1:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[  123.035531] Descriptor sense data with sense descriptors (in hex):
[  123.039728]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[  123.044071]         00 00 00 00
[  123.048263] sd 1:1:0:0: [sdc]  Add. Sense: No additional sense
information
[  123.052512] sd 1:1:0:0: [sdc] CDB: Read(10): 28 00 00 02 46 48 00 00
b8 00
[  123.056830] end_request: I/O error, dev sdc, sector 149064
[  123.061084] ata3: EH complete
[  123.065640] ata3.00: detaching (SCSI 1:0:0:0)
[  123.068043] sd 1:1:0:0: rejecting I/O to offline device
[  123.075042] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
[  123.077512] sd 1:0:0:0: [sdb] Stopping disk
[  123.082745] sd 1:1:0:0: rejecting I/O to offline device
[  123.084984] end_request: I/O error, dev sdc, sector 0
[  123.087925] sd 1:1:0:0: rejecting I/O to offline device
[  123.090124] end_request: I/O error, dev sdc, sector 0
[  123.694656] ata3.01: detaching (SCSI 1:1:0:0)
[  123.703452] sd 1:1:0:0: [sdc] Synchronizing SCSI cache
[  123.707890] sd 1:1:0:0: [sdc] Stopping disk


After reset - set NCQ depth to 1:


root@netboot:~# find /sys  -name queue_depth -print0 | xargs -0 -i sh -c
"echo -n {}: ; echo 1 > {} ; cat {}"
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:0:0/1:0:0:0/queue_depth:1
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:1:0/1:1:0:0/queue_depth:1
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads: 380 MB in  3.01 seconds = 126.06 MB/sec
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads: 384 MB in  3.01 seconds = 127.47 MB/sec
root@netboot:~# while true ; do hdparm -t /dev/sdb ; done

/dev/sdb:
 Timing buffered disk reads: 388 MB in  3.01 seconds = 129.03 MB/sec

/dev/sdb:
 Timing buffered disk reads: 394 MB in  3.01 seconds = 130.80 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.57 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.40 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.46 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.39 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.43 MB/sec

/dev/sdb:
 Timing buffered disk reads: 394 MB in  3.01 seconds = 130.80 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.60 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.42 MB/sec

/dev/sdb:
^C

[set NCQ back to 31:]
root@netboot:~# find /sys  -name queue_depth -print0 | xargs -0 -i sh -c
"echo -n {}: ; echo 31 > {} ; cat {}"
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:0:0/1:0:0:0/queue_depth:31
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:1:0/1:1:0:0/queue_depth:31

root@netboot:~# while true ; do hdparm -t /dev/sdb ; done

/dev/sdb:
 Timing buffered disk reads: 328 MB in  3.55 seconds =  92.29 MB/sec

/dev/sdb:
 Timing buffered disk reads: 204 MB in  5.30 seconds =  38.48 MB/sec

/dev/sdb:
 Timing buffered disk reads: 376 MB in  3.01 seconds = 124.78 MB/sec

/dev/sdb:
 Timing buffered disk reads: 200 MB in  3.01 seconds =  66.53 MB/sec

/dev/sdb:
 Timing buffered disk reads: 276 MB in  3.01 seconds =  91.68 MB/sec

/dev/sdb:
 Timing buffered disk reads: 154 MB in  3.36 seconds =  45.81 MB/sec

/dev/sdb:
 Timing buffered disk reads: 384 MB in  3.01 seconds = 127.45 MB/sec

/dev/sdb:
 Timing buffered disk reads: 358 MB in  3.01 seconds = 119.03 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.65 MB/sec

/dev/sdb:
 Timing buffered disk reads: 364 MB in  4.33 seconds =  84.11 MB/sec

/dev/sdb:
 Timing buffered disk reads: 188 MB in  3.01 seconds =  62.44 MB/sec

/dev/sdb:
 Timing buffered disk reads: 342 MB in  3.01 seconds = 113.47 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.39 MB/sec

/dev/sdb:
 Timing buffered disk reads: 394 MB in  3.01 seconds = 130.76 MB/sec

/dev/sdb:
 Timing buffered disk reads: 274 MB in  3.91 seconds =  70.16 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.50 MB/sec


Now it seems to work (no more resets), but performance does wander down
to 45MB/sec

For simultaneous reads for two drives behind an 3726 pmp on the 88SE9125
and NCQ=1 using 2.6.38:

root@netboot:~# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t
/dev/sdc) 2>&1 | grep MB" ; done
 Timing buffered disk reads: 280 MB in  3.01 seconds =  93.05 MB/sec
280 MB in  3.01 seconds =  93.12 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.45 MB/sec
284 MB in  3.02 seconds =  94.11 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.39 MB/sec
284 MB in  3.02 seconds =  94.12 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.28 MB/sec
284 MB in  3.02 seconds =  94.07 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.19 MB/sec
284 MB in  3.02 seconds =  94.06 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.32 MB/sec
284 MB in  3.02 seconds =  94.18 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.24 MB/sec
284 MB in  3.01 seconds =  94.24 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.17 MB/sec
284 MB in  3.01 seconds =  94.28 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.10 MB/sec
284 MB in  3.02 seconds =  94.08 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.31 MB/sec
284 MB in  3.01 seconds =  94.21 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.05 MB/sec
284 MB in  3.02 seconds =  94.12 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.23 MB/sec
284 MB in  3.01 seconds =  94.24 MB/sec


... so faster than 2.6.32, and consistent.  For NCQ=31:



root@netboot:~# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t
/dev/sdc) 2>&1 | grep MB" ; done
 Timing buffered disk reads: 276 MB in  3.02 seconds =  91.37 MB/sec
276 MB in  3.02 seconds =  91.52 MB/sec
 Timing buffered disk reads: 278 MB in  3.01 seconds =  92.31 MB/sec
278 MB in  3.01 seconds =  92.46 MB/sec
 Timing buffered disk reads: 268 MB in  3.00 seconds =  89.31 MB/sec
268 MB in  3.00 seconds =  89.32 MB/sec
 Timing buffered disk reads: 278 MB in  3.00 seconds =  92.61 MB/sec
278 MB in  3.01 seconds =  92.31 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.27 MB/sec
194 MB in  3.02 seconds =  64.24 MB/sec
 Timing buffered disk reads: 260 MB in  3.00 seconds =  86.55 MB/sec
260 MB in  3.00 seconds =  86.61 MB/sec
 Timing buffered disk reads: 278 MB in  3.01 seconds =  92.36 MB/sec
278 MB in  3.02 seconds =  92.20 MB/sec
 Timing buffered disk reads: 248 MB in  3.02 seconds =  82.23 MB/sec
248 MB in  3.01 seconds =  82.39 MB/sec
 Timing buffered disk reads: 268 MB in  3.00 seconds =  89.21 MB/sec
268 MB in  3.01 seconds =  89.09 MB/sec
 Timing buffered disk reads: 278 MB in  3.01 seconds =  92.44 MB/sec
278 MB in  3.01 seconds =  92.45 MB/sec
 Timing buffered disk reads: 280 MB in  3.02 seconds =  92.83 MB/sec
280 MB in  3.02 seconds =  92.61 MB/sec
 Timing buffered disk reads: 274 MB in  3.02 seconds =  90.77 MB/sec
274 MB in  3.02 seconds =  90.81 MB/sec



... a little slower, and with some strange performance dips (e.g. the
65M figure). 


After all this, I tried a "smartctl -x /dev/sd[bc]" and got this for sdb:

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2           26  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2           14  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS

and this for sdc:

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2            3  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2            2  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS



Tim.
--
To unsubscribe from this list: send the line "unsubscribe linux-ide" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Tim Small - July 7, 2011, 6:38 p.m.
In the same machine as the previous test set, but with 2.6.38 (debian
squeeze backports kernel):

NCQ 1, two drives both connected to 3726 behind the **88SE9123**
(previous mail was for the 88SE9125):

# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t /dev/sdc) 2>&1
| grep MB" ; done
 Timing buffered disk reads: 190 MB in  3.02 seconds =  62.97 MB/sec
190 MB in  3.02 seconds =  62.99 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.27 MB/sec
194 MB in  3.02 seconds =  64.24 MB/sec
 Timing buffered disk reads: 192 MB in  3.01 seconds =  63.87 MB/sec
194 MB in  3.01 seconds =  64.44 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.26 MB/sec
194 MB in  3.02 seconds =  64.23 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.14 MB/sec
194 MB in  3.03 seconds =  64.13 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.31 MB/sec
194 MB in  3.02 seconds =  64.18 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.31 MB/sec
194 MB in  3.02 seconds =  64.15 MB/sec
 Timing buffered disk reads: 192 MB in  3.01 seconds =  63.73 MB/sec
196 MB in  3.02 seconds =  64.87 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.16 MB/sec
194 MB in  3.02 seconds =  64.27 MB/sec
 Timing buffered disk reads: 192 MB in  3.01 seconds =  63.72 MB/sec
196 MB in  3.02 seconds =  64.83 MB/sec
 Timing buffered disk reads: 194 MB in  3.01 seconds =  64.47 MB/sec
192 MB in  3.01 seconds =  63.79 MB/sec


... so it works, but is about 50% slower than the 88SE9125...

change NCQ depth to 31:

# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t /dev/sdc) 2>&1
| grep MB" ; done
[after a considerable pause:]
 Timing buffered disk reads: 382 MB in  3.01 seconds = 127.10 MB/sec


... i.e. one drive results only, the other read failed, with this in dmesg:

[ 2930.016043] ata7.00: failed to read SCR 1 (Emask=0x40)
[ 2930.020801] ata7.01: failed to read SCR 1 (Emask=0x40)
[ 2930.025429] ata7.02: failed to read SCR 1 (Emask=0x40)
[ 2930.029970] ata7.03: failed to read SCR 1 (Emask=0x40)
[ 2930.034447] ata7.04: failed to read SCR 1 (Emask=0x40)
[ 2930.038859] ata7.05: failed to read SCR 1 (Emask=0x40)
[ 2930.043218] ata7.15: exception Emask 0x4 SAct 0x0 SErr 0x0 action 0x6
frozen
[ 2930.047661] ata7.00: exception Emask 0x100 SAct 0xc SErr 0x0 action
0x6 frozen
[ 2930.052077] ata7.00: failed command: READ FPDMA QUEUED
[ 2930.056439] ata7.00: cmd 60/00:10:00:06:00/01:00:00:00:00/40 tag 2
ncq 131072 in
[ 2930.056443]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.065295] ata7.00: status: { DRDY }
[ 2930.069753] ata7.00: failed command: READ FPDMA QUEUED
[ 2930.074243] ata7.00: cmd 60/00:18:00:07:00/01:00:00:00:00/40 tag 3
ncq 131072 in
[ 2930.074247]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.083380] ata7.00: status: { DRDY }
[ 2930.087981] ata7.01: exception Emask 0x100 SAct 0x3 SErr 0x0 action
0x6 frozen
[ 2930.092672] ata7.01: failed command: READ FPDMA QUEUED
[ 2930.097279] ata7.01: cmd 60/00:00:00:06:00/01:00:00:00:00/40 tag 0
ncq 131072 in
[ 2930.097283]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.106463] ata7.01: status: { DRDY }
[ 2930.111040] ata7.01: failed command: READ FPDMA QUEUED
[ 2930.115630] ata7.01: cmd 60/00:08:00:07:00/01:00:00:00:00/40 tag 1
ncq 131072 in
[ 2930.115634]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.124786] ata7.01: status: { DRDY }
[ 2930.129349] ata7.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.133977] ata7.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.138537] ata7.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.143074] ata7.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.147538] ata7.15: hard resetting link
[ 2930.864034] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
[ 2930.868757] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2930.873236] ata7.15: PMP revalidation failed (errno=-19)
[ 2935.868025] ata7.15: hard resetting link
[ 2936.588038] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
[ 2936.592742] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2936.597296] ata7.15: PMP revalidation failed (errno=-19)
[ 2936.601803] ata7.15: limiting SATA link speed to 1.5 Gbps
[ 2941.592044] ata7.15: hard resetting link
[ 2942.312039] ata7.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 2942.316762] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2942.321236] ata7.15: PMP revalidation failed (errno=-19)
[ 2942.325672] ata7.15: failed to recover PMP after 5 tries, giving up
[ 2942.330101] ata7.15: Port Multiplier detaching
[ 2942.334489] ata7.00: disabled
[ 2942.338863] ata7.01: disabled
[ 2942.343145] ata7.00: disabled
[ 2947.316024] ata7: hard resetting link
[ 2948.036036] ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
[ 2948.040497] ata7.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x1/0x9
[ 2948.044701] ahci 0000:02:00.0: FBS is enabled.
[ 2948.049005] ata7.00: hard resetting link
[ 2948.368250] ata7.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[ 2948.372472] ata7.01: hard resetting link
[ 2948.696248] ata7.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 2948.700471] ata7.02: hard resetting link
[ 2949.024255] ata7.02: SATA link down (SStatus 0 SControl 320)
[ 2949.028581] ata7.03: hard resetting link
[ 2949.352249] ata7.03: SATA link down (SStatus 0 SControl 320)
[ 2949.356582] ata7.04: hard resetting link
[ 2949.680248] ata7.04: SATA link down (SStatus 0 SControl 320)
[ 2949.684638] ata7.05: hard resetting link
[ 2950.008192] ata7.05: failed to write SCR 1 (Emask=0x1)
[ 2950.012618] ata7.05: SATA link down (SStatus 0 SControl 0)
[ 2950.018426] ata7.00: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 2950.022698] ata7.00: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[ 2950.028551] ata7.00: configured for UDMA/133
[ 2950.034073] ata7.01: native sectors (2) is smaller than sectors
(3907029168)
[ 2950.038668] ata7.01: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 2950.043219] ata7.01: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[ 2950.049087] ata7.01: configured for UDMA/133
[ 2950.053758] ata7.01: device reported invalid CHS sector 0
[ 2950.058290] ata7.01: device reported invalid CHS sector 0
[ 2950.062735] ata7.00: device reported invalid CHS sector 0
[ 2950.067131] ata7.00: device reported invalid CHS sector 0
[ 2950.071451] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 2950.075844] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[ 2950.080228] Descriptor sense data with sense descriptors (in hex):
[ 2950.084616]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.089114]         00 00 00 00
[ 2950.093453] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense
information
[ 2950.097839] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 06 00 00 01
00 00
[ 2950.102283] end_request: I/O error, dev sdc, sector 1536
[ 2950.106652] quiet_error: 45 callbacks suppressed
[ 2950.110957] Buffer I/O error on device sdc, logical block 192
[ 2950.115306] Buffer I/O error on device sdc, logical block 193
[ 2950.119578] Buffer I/O error on device sdc, logical block 194
[ 2950.123816] Buffer I/O error on device sdc, logical block 195
[ 2950.127958] Buffer I/O error on device sdc, logical block 196
[ 2950.132036] Buffer I/O error on device sdc, logical block 197
[ 2950.136119] Buffer I/O error on device sdc, logical block 198
[ 2950.140190] Buffer I/O error on device sdc, logical block 199
[ 2950.144269] Buffer I/O error on device sdc, logical block 200
[ 2950.148281] Buffer I/O error on device sdc, logical block 201
[ 2950.152265] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 2950.156275] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[ 2950.160289] Descriptor sense data with sense descriptors (in hex):
[ 2950.164318]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.168471]         00 00 00 00
[ 2950.172471] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense
information
[ 2950.176525] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 07 00 00 01
00 00
[ 2950.180659] end_request: I/O error, dev sdc, sector 1792
[ 2950.184743] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 2950.188856] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current]
[descriptor]
[ 2950.192976] Descriptor sense data with sense descriptors (in hex):
[ 2950.197094]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.201337]         00 00 00 00
[ 2950.205439] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense
information
[ 2950.209626] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 06 00 00 01
00 00
[ 2950.213939] end_request: I/O error, dev sdb, sector 1536
[ 2950.218252] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 2950.222627] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current]
[descriptor]
[ 2950.227010] Descriptor sense data with sense descriptors (in hex):
[ 2950.231370]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.235813]         00 00 00 00
[ 2950.240143] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense
information
[ 2950.244528] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 07 00 00 01
00 00
[ 2950.248975] end_request: I/O error, dev sdb, sector 1792
[ 2950.253351] ata7: EH complete
[ 2950.257986] ata7.00: detaching (SCSI 6:0:0:0)
[ 2950.260412] sd 6:1:0:0: rejecting I/O to offline device
[ 2950.262676] sd 6:0:0:0: rejecting I/O to offline device
[ 2950.272236] sd 6:0:0:0: [sdb] Synchronizing SCSI cache
[ 2950.274778] sd 6:0:0:0: [sdb] Stopping disk
[ 2950.284568] end_request: I/O error, dev sdb, sector 0
[ 2950.287099] sd 6:1:0:0: rejecting I/O to offline device
[ 2950.288321] end_request: I/O error, dev sdc, sector 0
[ 2950.291531] end_request: I/O error, dev sdb, sector 0
[ 2950.293912] sd 6:1:0:0: rejecting I/O to offline device
[ 2950.296077] end_request: I/O error, dev sdc, sector 0
[ 2950.868137] ata7.01: detaching (SCSI 6:1:0:0)
[ 2950.879987] sd 6:1:0:0: [sdc] Synchronizing SCSI cache
[ 2950.884351] sd 6:1:0:0: [sdc] Stopping disk
[ 2951.490748] scsi 6:0:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 2951.497341] sd 6:0:0:0: [sdb] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 2951.501834] sd 6:0:0:0: [sdb] Write Protect is off
[ 2951.506067] sd 6:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 2951.506855] scsi 6:1:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 2951.518252] sd 6:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 2951.523911] sd 6:1:0:0: [sdc] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 2951.530008] sd 6:1:0:0: [sdc] Write Protect is off
[ 2951.532522] sd 6:1:0:0: [sdc] Mode Sense: 00 3a 00 00
[ 2951.533349] sd 6:1:0:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 2953.444386]  sdc: sdc1
[ 2953.450667] sd 6:1:0:0: [sdc] Attached SCSI disk
[ 2954.301886]  sdb: sdb1
[ 2954.311753] sd 6:0:0:0: [sdb] Attached SCSI disk
[ 2994.016046] ata7.00: failed to read SCR 1 (Emask=0x40)
[ 2994.020684] ata7.01: failed to read SCR 1 (Emask=0x40)
[ 2994.025282] ata7.02: failed to read SCR 1 (Emask=0x40)
[ 2994.029859] ata7.03: failed to read SCR 1 (Emask=0x40)
[ 2994.034443] ata7.04: failed to read SCR 1 (Emask=0x40)
[ 2994.039024] ata7.05: failed to read SCR 1 (Emask=0x40)
[ 2994.043613] ata7.15: exception Emask 0x4 SAct 0x0 SErr 0x400000
action 0x6 frozen
[ 2994.048221] ata7.15: SError: { Handshk }
[ 2994.052790] ata7.00: exception Emask 0x100 SAct 0xa SErr 0x0 action
0x6 frozen
[ 2994.057393] ata7.00: failed command: READ FPDMA QUEUED
[ 2994.061957] ata7.00: cmd 60/00:08:00:18:00/01:00:00:00:00/40 tag 1
ncq 131072 in
[ 2994.061961]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.071179] ata7.00: status: { DRDY }
[ 2994.075747] ata7.00: failed command: READ FPDMA QUEUED
[ 2994.080311] ata7.00: cmd 60/00:18:00:19:00/01:00:00:00:00/40 tag 3
ncq 131072 in
[ 2994.080314]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.089460] ata7.00: status: { DRDY }
[ 2994.093974] ata7.01: exception Emask 0x100 SAct 0x5 SErr 0x0 action
0x6 frozen
[ 2994.098544] ata7.01: failed command: READ FPDMA QUEUED
[ 2994.103096] ata7.01: cmd 60/00:00:00:04:00/01:00:00:00:00/40 tag 0
ncq 131072 in
[ 2994.103099]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.112254] ata7.01: status: { DRDY }
[ 2994.116770] ata7.01: failed command: READ FPDMA QUEUED
[ 2994.121280] ata7.01: cmd 60/00:10:00:05:00/01:00:00:00:00/40 tag 2
ncq 131072 in
[ 2994.121283]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.130329] ata7.01: status: { DRDY }
[ 2994.134794] ata7.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.139343] ata7.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.143815] ata7.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.148233] ata7.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.152588] ata7.15: hard resetting link
[ 2994.872040] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
[ 2994.876666] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2994.881056] ata7.15: PMP revalidation failed (errno=-19)
[ 2999.876031] ata7.15: hard resetting link
[ 3000.596037] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
[ 3000.600759] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 3000.605307] ata7.15: PMP revalidation failed (errno=-19)
[ 3000.609803] ata7.15: limiting SATA link speed to 1.5 Gbps
[ 3005.600038] ata7.15: hard resetting link
[ 3006.320038] ata7.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[ 3006.324835] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 3006.329398] ata7.15: PMP revalidation failed (errno=-19)
[ 3006.333932] ata7.15: failed to recover PMP after 5 tries, giving up
[ 3006.338486] ata7.15: Port Multiplier detaching
[ 3006.343045] ata7.00: disabled
[ 3006.347531] ata7.01: disabled
[ 3006.351918] ata7.00: disabled
[ 3011.324021] ata7: hard resetting link
[ 3012.044038] ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
[ 3012.048607] ata7.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x1/0x9
[ 3012.052909] ahci 0000:02:00.0: FBS is enabled.
[ 3012.057467] ata7.00: hard resetting link
[ 3012.376255] ata7.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[ 3012.380560] ata7.01: hard resetting link
[ 3012.704248] ata7.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 3012.708580] ata7.02: hard resetting link
[ 3013.032247] ata7.02: SATA link down (SStatus 0 SControl 320)
[ 3013.036615] ata7.03: hard resetting link
[ 3013.360248] ata7.03: SATA link down (SStatus 0 SControl 320)
[ 3013.364635] ata7.04: hard resetting link
[ 3013.688246] ata7.04: SATA link down (SStatus 0 SControl 320)
[ 3013.692689] ata7.05: hard resetting link
[ 3014.016194] ata7.05: failed to write SCR 1 (Emask=0x1)
[ 3014.020635] ata7.05: SATA link down (SStatus 0 SControl 0)
[ 3014.026285] ata7.00: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 3014.030646] ata7.00: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[ 3014.036430] ata7.00: configured for UDMA/133
[ 3014.042023] ata7.01: native sectors (2) is smaller than sectors
(3907029168)
[ 3014.046718] ata7.01: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 3014.051279] ata7.01: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[ 3014.057159] ata7.01: configured for UDMA/133
[ 3014.059537] ata7.01: device reported invalid CHS sector 0
[ 3014.061890] ata7.00: device reported invalid CHS sector 0
[ 3014.064203] ata7.01: device reported invalid CHS sector 0
[ 3014.066474] ata7.00: device reported invalid CHS sector 0
[ 3014.068733] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 3014.071007] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[ 3014.073291] Descriptor sense data with sense descriptors (in hex):
[ 3014.075562]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.077904]         00 00 00 00
[ 3014.080183] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense
information
[ 3014.082476] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 04 00 00 01
00 00
[ 3014.084797] end_request: I/O error, dev sdc, sector 1024
[ 3014.087077] quiet_error: 118 callbacks suppressed
[ 3014.089320] Buffer I/O error on device sdc, logical block 128
[ 3014.091593] Buffer I/O error on device sdc, logical block 129
[ 3014.093817] Buffer I/O error on device sdc, logical block 130
[ 3014.096015] Buffer I/O error on device sdc, logical block 131
[ 3014.098167] Buffer I/O error on device sdc, logical block 132
[ 3014.100286] Buffer I/O error on device sdc, logical block 133
[ 3014.102402] Buffer I/O error on device sdc, logical block 134
[ 3014.104521] Buffer I/O error on device sdc, logical block 135
[ 3014.106638] Buffer I/O error on device sdc, logical block 136
[ 3014.108721] Buffer I/O error on device sdc, logical block 137
[ 3014.110792] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 3014.112877] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current]
[descriptor]
[ 3014.114966] Descriptor sense data with sense descriptors (in hex):
[ 3014.117053]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.119211]         00 00 00 00
[ 3014.121313] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense
information
[ 3014.123421] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 18 00 00 01
00 00
[ 3014.125605] end_request: I/O error, dev sdb, sector 6144
[ 3014.127754] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 3014.129913] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[ 3014.132067] Descriptor sense data with sense descriptors (in hex):
[ 3014.134199]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.136423]         00 00 00 00
[ 3014.138587] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense
information
[ 3014.140791] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 05 00 00 01
00 00
[ 3014.143051] end_request: I/O error, dev sdc, sector 1280
[ 3014.145323] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[ 3014.147615] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current]
[descriptor]
[ 3014.149897] Descriptor sense data with sense descriptors (in hex):
[ 3014.152156]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.154478]         00 00 00 00
[ 3014.156758] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense
information
[ 3014.159056] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 19 00 00 01
00 00
[ 3014.161406] end_request: I/O error, dev sdb, sector 6400
[ 3014.163703] ata7: EH complete
[ 3014.165979] ata7.00: detaching (SCSI 6:0:0:0)
[ 3014.168308] sd 6:0:0:0: rejecting I/O to offline device
[ 3014.177610] sd 6:0:0:0: [sdb] Synchronizing SCSI cache
[ 3014.179969] sd 6:0:0:0: [sdb] Stopping disk
[ 3014.791747] ata7.01: detaching (SCSI 6:1:0:0)
[ 3014.799621] sd 6:1:0:0: [sdc] Synchronizing SCSI cache
[ 3014.804160] sd 6:1:0:0: [sdc] Stopping disk
[ 3015.419701] scsi 6:0:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 3015.425355] sd 6:0:0:0: [sdb] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 3015.429980] sd 6:0:0:0: [sdb] Write Protect is off
[ 3015.434322] sd 6:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 3015.435019] scsi 6:1:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 3015.440304] sd 6:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 3015.445835] sd 6:1:0:0: [sdc] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 3015.450897] sd 6:1:0:0: [sdc] Write Protect is off
[ 3015.455341] sd 6:1:0:0: [sdc] Mode Sense: 00 3a 00 00
[ 3015.456615] sd 6:1:0:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 3017.371727]  sdc: sdc1
[ 3017.377835] sd 6:1:0:0: [sdc] Attached SCSI disk
[ 3018.219239]  sdb: sdb1
[ 3018.225421] sd 6:0:0:0: [sdb] Attached SCSI disk

... and the drives have this smartctl output:

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2           56  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2           35  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2            9  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2            5  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS
Tim Small - July 7, 2011, 6:43 p.m.
Sorry - I accidentally sent this from the wrong email address, which I
think kept it from reaching the list.

On 07/07/11 13:13, Tim Small wrote:
> 2x 2G Hitachi drives connected via a SiI 3726, and to the 88SE9125 card
> ( Debian 6.0  2.6.32 NCQ depth 31  - same with any value between 2 and
> 31 ) - works for simultaneous reads with hdparm - read speeds at 31M per
> second on both drives.  Reads from a single drive at between 19M per
> second and 130M per second with NCQ depth = 31 (most often 130M), but
> reads from a single drive with NCQ depth = 2 varied between 5M per
> second and 54M per second.  Reads from a single drive (direct to host,
> not via PMP) at 130M per second (127M per second with depth = 2).
>   

In the same machine, but with 2.6.38 (debian squeeze backports kernel):

NCQ 31, two drives connected to 3726 behind the **88SE9125** :

root@netboot:~# hdparm -t /dev/sdb

/dev/sdb:
 Timing buffered disk reads: 386 MB in  3.00 seconds = 128.59 MB/sec
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads:  38 MB in  7.01 seconds =   5.42 MB/sec
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads: read(2097152) returned 823296 bytes
BLKFLSBUF failed: No such device

This coincides with the following dmesg:

[  102.880043] ata3.00: failed to read SCR 1 (Emask=0x40)
[  102.884798] ata3.01: failed to read SCR 1 (Emask=0x40)
[  102.889604] ata3.02: failed to read SCR 1 (Emask=0x40)
[  102.894352] ata3.03: failed to read SCR 1 (Emask=0x40)
[  102.899057] ata3.04: failed to read SCR 1 (Emask=0x40)
[  102.903730] ata3.05: failed to read SCR 1 (Emask=0x40)
[  102.908365] ata3.15: exception Emask 0x4 SAct 0x0 SErr 0x400000
action 0x6 frozen
[  102.913067] ata3.15: SError: { Handshk }
[  102.917727] ata3.00: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.922460] ata3.01: exception Emask 0x100 SAct 0x7 SErr 0x0 action
0x6 frozen
[  102.927107] ata3.01: failed command: READ FPDMA QUEUED
[  102.931757] ata3.01: cmd 60/98:00:00:47:02/00:00:00:00:00/40 tag 0
ncq 77824 in
[  102.931761]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[  102.941055] ata3.01: status: { DRDY }
[  102.945643] ata3.01: failed command: READ FPDMA QUEUED
[  102.950234] ata3.01: cmd 60/68:08:98:47:02/00:00:00:00:00/40 tag 1
ncq 53248 in
[  102.950238]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[  102.959550] ata3.01: status: { DRDY }
[  102.964223] ata3.01: failed command: READ FPDMA QUEUED
[  102.968945] ata3.01: cmd 60/b8:10:48:46:02/00:00:00:00:00/40 tag 2
ncq 94208 in
[  102.968949]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[  102.978510] ata3.01: status: { DRDY }
[  102.983270] ata3.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.988128] ata3.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.992942] ata3.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  102.997719] ata3.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  103.002468] ata3.15: hard resetting link
[  103.720029] ata3.15: SATA link up 3.0 Gbps (SStatus 123 SControl 330)
[  103.725058] ata3.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[  103.729797] ata3.15: PMP revalidation failed (errno=-19)
[  108.724032] ata3.15: hard resetting link
[  109.444033] ata3.15: SATA link up 3.0 Gbps (SStatus 123 SControl 330)
[  109.448924] ata3.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[  109.453679] ata3.15: PMP revalidation failed (errno=-19)
[  109.458399] ata3.15: limiting SATA link speed to 1.5 Gbps
[  114.448029] ata3.15: hard resetting link
[  115.168034] ata3.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
[  115.173007] ata3.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[  115.177781] ata3.15: PMP revalidation failed (errno=-19)
[  115.182541] ata3.15: failed to recover PMP after 5 tries, giving up
[  115.187291] ata3.15: Port Multiplier detaching
[  115.191959] ata3.00: disabled
[  115.196572] ata3.01: disabled
[  115.201115] ata3.00: disabled
[  120.172024] ata3: hard resetting link
[  120.892037] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 330)
[  120.896695] ata3.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x1/0x9
[  120.901169] ahci 0000:01:00.0: FBS is enabled.
[  120.905800] ata3.00: hard resetting link
[  121.228222] ata3.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
[  121.232855] ata3.01: hard resetting link
[  121.556224] ata3.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[  121.560862] ata3.02: hard resetting link
[  121.884223] ata3.02: SATA link down (SStatus 0 SControl 320)
[  121.888866] ata3.03: hard resetting link
[  122.212222] ata3.03: SATA link down (SStatus 0 SControl 320)
[  122.216721] ata3.04: hard resetting link
[  122.540221] ata3.04: SATA link down (SStatus 0 SControl 320)
[  122.544633] ata3.05: hard resetting link
[  122.868232] ata3.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320)
[  122.873827] ata3.00: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[  122.878067] ata3.00: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[  122.883669] ata3.00: configured for UDMA/133
[  122.889185] ata3.01: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[  122.893487] ata3.01: 3907029168 sectors, multi 0: LBA48 NCQ (depth
31/32), AA
[  122.899114] ata3.01: configured for UDMA/133
[  122.903547] ata3.01: device reported invalid CHS sector 0
[  122.907930] ata3.01: device reported invalid CHS sector 0
[  122.912322] ata3.01: device reported invalid CHS sector 0
[  122.916715] sd 1:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[  122.921135] sd 1:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[  122.925558] Descriptor sense data with sense descriptors (in hex):
[  122.929959]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[  122.934528]         00 00 00 00
[  122.938953] sd 1:1:0:0: [sdc]  Add. Sense: No additional sense
information
[  122.943428] sd 1:1:0:0: [sdc] CDB: Read(10): 28 00 00 02 47 00 00 00
98 00
[  122.947984] end_request: I/O error, dev sdc, sector 149248
[  122.952425] Buffer I/O error on device sdc, logical block 18656
[  122.956888] Buffer I/O error on device sdc, logical block 18657
[  122.961268] Buffer I/O error on device sdc, logical block 18658
[  122.965594] Buffer I/O error on device sdc, logical block 18659
[  122.969830] Buffer I/O error on device sdc, logical block 18660
[  122.974033] Buffer I/O error on device sdc, logical block 18661
[  122.978172] Buffer I/O error on device sdc, logical block 18662
[  122.982256] Buffer I/O error on device sdc, logical block 18663
[  122.986239] Buffer I/O error on device sdc, logical block 18664
[  122.990165] Buffer I/O error on device sdc, logical block 18665
[  122.994116] sd 1:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[  122.998160] sd 1:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[  123.002283] Descriptor sense data with sense descriptors (in hex):
[  123.006370]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[  123.010586]         00 00 00 00
[  123.014657] sd 1:1:0:0: [sdc]  Add. Sense: No additional sense
information
[  123.018792] sd 1:1:0:0: [sdc] CDB: Read(10): 28 00 00 02 47 98 00 00
68 00
[  123.023005] end_request: I/O error, dev sdc, sector 149400
[  123.027149] sd 1:1:0:0: [sdc]  Result: hostbyte=DID_OK
driverbyte=DRIVER_SENSE
[  123.031332] sd 1:1:0:0: [sdc]  Sense Key : Aborted Command [current]
[descriptor]
[  123.035531] Descriptor sense data with sense descriptors (in hex):
[  123.039728]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[  123.044071]         00 00 00 00
[  123.048263] sd 1:1:0:0: [sdc]  Add. Sense: No additional sense
information
[  123.052512] sd 1:1:0:0: [sdc] CDB: Read(10): 28 00 00 02 46 48 00 00
b8 00
[  123.056830] end_request: I/O error, dev sdc, sector 149064
[  123.061084] ata3: EH complete
[  123.065640] ata3.00: detaching (SCSI 1:0:0:0)
[  123.068043] sd 1:1:0:0: rejecting I/O to offline device
[  123.075042] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
[  123.077512] sd 1:0:0:0: [sdb] Stopping disk
[  123.082745] sd 1:1:0:0: rejecting I/O to offline device
[  123.084984] end_request: I/O error, dev sdc, sector 0
[  123.087925] sd 1:1:0:0: rejecting I/O to offline device
[  123.090124] end_request: I/O error, dev sdc, sector 0
[  123.694656] ata3.01: detaching (SCSI 1:1:0:0)
[  123.703452] sd 1:1:0:0: [sdc] Synchronizing SCSI cache
[  123.707890] sd 1:1:0:0: [sdc] Stopping disk


After reset - set NCQ depth to 1:


root@netboot:~# find /sys  -name queue_depth -print0 | xargs -0 -i sh -c
"echo -n {}: ; echo 1 > {} ; cat {}"
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:0:0/1:0:0:0/queue_depth:1
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:1:0/1:1:0:0/queue_depth:1
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads: 380 MB in  3.01 seconds = 126.06 MB/sec
root@netboot:~# hdparm -t /dev/sdc

/dev/sdc:
 Timing buffered disk reads: 384 MB in  3.01 seconds = 127.47 MB/sec
root@netboot:~# while true ; do hdparm -t /dev/sdb ; done

/dev/sdb:
 Timing buffered disk reads: 388 MB in  3.01 seconds = 129.03 MB/sec

/dev/sdb:
 Timing buffered disk reads: 394 MB in  3.01 seconds = 130.80 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.57 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.40 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.46 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.39 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.43 MB/sec

/dev/sdb:
 Timing buffered disk reads: 394 MB in  3.01 seconds = 130.80 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.60 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.42 MB/sec

/dev/sdb:
^C

[set NCQ back to 31:]
root@netboot:~# find /sys  -name queue_depth -print0 | xargs -0 -i sh -c
"echo -n {}: ; echo 31 > {} ; cat {}"
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:0:0/1:0:0:0/queue_depth:31
/sys/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host1/target1:1:0/1:1:0:0/queue_depth:31

root@netboot:~# while true ; do hdparm -t /dev/sdb ; done

/dev/sdb:
 Timing buffered disk reads: 328 MB in  3.55 seconds =  92.29 MB/sec

/dev/sdb:
 Timing buffered disk reads: 204 MB in  5.30 seconds =  38.48 MB/sec

/dev/sdb:
 Timing buffered disk reads: 376 MB in  3.01 seconds = 124.78 MB/sec

/dev/sdb:
 Timing buffered disk reads: 200 MB in  3.01 seconds =  66.53 MB/sec

/dev/sdb:
 Timing buffered disk reads: 276 MB in  3.01 seconds =  91.68 MB/sec

/dev/sdb:
 Timing buffered disk reads: 154 MB in  3.36 seconds =  45.81 MB/sec

/dev/sdb:
 Timing buffered disk reads: 384 MB in  3.01 seconds = 127.45 MB/sec

/dev/sdb:
 Timing buffered disk reads: 358 MB in  3.01 seconds = 119.03 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.65 MB/sec

/dev/sdb:
 Timing buffered disk reads: 364 MB in  4.33 seconds =  84.11 MB/sec

/dev/sdb:
 Timing buffered disk reads: 188 MB in  3.01 seconds =  62.44 MB/sec

/dev/sdb:
 Timing buffered disk reads: 342 MB in  3.01 seconds = 113.47 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.39 MB/sec

/dev/sdb:
 Timing buffered disk reads: 394 MB in  3.01 seconds = 130.76 MB/sec

/dev/sdb:
 Timing buffered disk reads: 274 MB in  3.91 seconds =  70.16 MB/sec

/dev/sdb:
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.50 MB/sec


Now it seems to work (no more resets), but performance does wander down
to 45MB/sec

For simultaneous reads for two drives behind an 3726 pmp on the 88SE9125
and NCQ=1 using 2.6.38:

root@netboot:~# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t
/dev/sdc) 2>&1 | grep MB" ; done
 Timing buffered disk reads: 280 MB in  3.01 seconds =  93.05 MB/sec
280 MB in  3.01 seconds =  93.12 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.45 MB/sec
284 MB in  3.02 seconds =  94.11 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.39 MB/sec
284 MB in  3.02 seconds =  94.12 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.28 MB/sec
284 MB in  3.02 seconds =  94.07 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.19 MB/sec
284 MB in  3.02 seconds =  94.06 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.32 MB/sec
284 MB in  3.02 seconds =  94.18 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.24 MB/sec
284 MB in  3.01 seconds =  94.24 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.17 MB/sec
284 MB in  3.01 seconds =  94.28 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.10 MB/sec
284 MB in  3.02 seconds =  94.08 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.31 MB/sec
284 MB in  3.01 seconds =  94.21 MB/sec
 Timing buffered disk reads: 284 MB in  3.02 seconds =  94.05 MB/sec
284 MB in  3.02 seconds =  94.12 MB/sec
 Timing buffered disk reads: 284 MB in  3.01 seconds =  94.23 MB/sec
284 MB in  3.01 seconds =  94.24 MB/sec


... so faster than 2.6.32, and consistent.  For NCQ=31:



root@netboot:~# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t
/dev/sdc) 2>&1 | grep MB" ; done
 Timing buffered disk reads: 276 MB in  3.02 seconds =  91.37 MB/sec
276 MB in  3.02 seconds =  91.52 MB/sec
 Timing buffered disk reads: 278 MB in  3.01 seconds =  92.31 MB/sec
278 MB in  3.01 seconds =  92.46 MB/sec
 Timing buffered disk reads: 268 MB in  3.00 seconds =  89.31 MB/sec
268 MB in  3.00 seconds =  89.32 MB/sec
 Timing buffered disk reads: 278 MB in  3.00 seconds =  92.61 MB/sec
278 MB in  3.01 seconds =  92.31 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.27 MB/sec
194 MB in  3.02 seconds =  64.24 MB/sec
 Timing buffered disk reads: 260 MB in  3.00 seconds =  86.55 MB/sec
260 MB in  3.00 seconds =  86.61 MB/sec
 Timing buffered disk reads: 278 MB in  3.01 seconds =  92.36 MB/sec
278 MB in  3.02 seconds =  92.20 MB/sec
 Timing buffered disk reads: 248 MB in  3.02 seconds =  82.23 MB/sec
248 MB in  3.01 seconds =  82.39 MB/sec
 Timing buffered disk reads: 268 MB in  3.00 seconds =  89.21 MB/sec
268 MB in  3.01 seconds =  89.09 MB/sec
 Timing buffered disk reads: 278 MB in  3.01 seconds =  92.44 MB/sec
278 MB in  3.01 seconds =  92.45 MB/sec
 Timing buffered disk reads: 280 MB in  3.02 seconds =  92.83 MB/sec
280 MB in  3.02 seconds =  92.61 MB/sec
 Timing buffered disk reads: 274 MB in  3.02 seconds =  90.77 MB/sec
274 MB in  3.02 seconds =  90.81 MB/sec



... a little slower, and with some strange performance dips (e.g. the
65M figure).

After all this, I tried a "smartctl -x /dev/sd[bc]" and got this for sdb:

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2           26  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2           14  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS

and this for sdc:

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2            3  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2            2  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS



Tim.
--
To unsubscribe from this list: send the line "unsubscribe linux-ide" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Hubert Bailey - July 8, 2011, 4:42 a.m.
Tim,

The 9125 is a simple controller without a internal processor.  The 9123 contains an internal processor to enhance RAID 0/1 operations.  If you are testing in a JBOD configuration you will not take advantage of the 9123 internal processor.  The internal processor can result in lower performance than the 9125.  However if you configure the drives in a RAID configuration using the 9123 RAID  utility you should see better performance than with 9125.

-----Original Message-----
From: Tim Small [mailto:tim@seoss.co.uk]
Sent: Thursday, July 07, 2011 1:39 PM
To: Tejun Heo; Hubert Bailey; Larry Li; linux-ide@vger.kernel.org
Subject: Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller

In the same machine as the previous test set, but with 2.6.38 (debian squeeze backports kernel):

NCQ 1, two drives both connected to 3726 behind the **88SE9123** (previous mail was for the 88SE9125):

# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t /dev/sdc) 2>&1
| grep MB" ; done
 Timing buffered disk reads: 190 MB in  3.02 seconds =  62.97 MB/sec 190 MB in  3.02 seconds =  62.99 MB/sec  Timing buffered disk reads: 194 MB in  3.02 seconds =  64.27 MB/sec
194 MB in  3.02 seconds =  64.24 MB/sec
 Timing buffered disk reads: 192 MB in  3.01 seconds =  63.87 MB/sec
194 MB in  3.01 seconds =  64.44 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.26 MB/sec
194 MB in  3.02 seconds =  64.23 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.14 MB/sec
194 MB in  3.03 seconds =  64.13 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.31 MB/sec
194 MB in  3.02 seconds =  64.18 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.31 MB/sec
194 MB in  3.02 seconds =  64.15 MB/sec
 Timing buffered disk reads: 192 MB in  3.01 seconds =  63.73 MB/sec
196 MB in  3.02 seconds =  64.87 MB/sec
 Timing buffered disk reads: 194 MB in  3.02 seconds =  64.16 MB/sec
194 MB in  3.02 seconds =  64.27 MB/sec
 Timing buffered disk reads: 192 MB in  3.01 seconds =  63.72 MB/sec
196 MB in  3.02 seconds =  64.83 MB/sec
 Timing buffered disk reads: 194 MB in  3.01 seconds =  64.47 MB/sec
192 MB in  3.01 seconds =  63.79 MB/sec


... so it works, but is about 50% slower than the 88SE9125...

change NCQ depth to 31:

# while true ; do sh -c "(hdparm -t /dev/sdb & hdparm -t /dev/sdc) 2>&1
| grep MB" ; done
[after a considerable pause:]
 Timing buffered disk reads: 382 MB in  3.01 seconds = 127.10 MB/sec


... i.e. one drive results only, the other read failed, with this in dmesg:

[ 2930.016043] ata7.00: failed to read SCR 1 (Emask=0x40) [ 2930.020801] ata7.01: failed to read SCR 1 (Emask=0x40) [ 2930.025429] ata7.02: failed to read SCR 1 (Emask=0x40) [ 2930.029970] ata7.03: failed to read SCR 1 (Emask=0x40) [ 2930.034447] ata7.04: failed to read SCR 1 (Emask=0x40) [ 2930.038859] ata7.05: failed to read SCR 1 (Emask=0x40) [ 2930.043218] ata7.15: exception Emask 0x4 SAct 0x0 SErr 0x0 action 0x6 frozen [ 2930.047661] ata7.00: exception Emask 0x100 SAct 0xc SErr 0x0 action
0x6 frozen
[ 2930.052077] ata7.00: failed command: READ FPDMA QUEUED [ 2930.056439] ata7.00: cmd 60/00:10:00:06:00/01:00:00:00:00/40 tag 2 ncq 131072 in
[ 2930.056443]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.065295] ata7.00: status: { DRDY } [ 2930.069753] ata7.00: failed command: READ FPDMA QUEUED [ 2930.074243] ata7.00: cmd 60/00:18:00:07:00/01:00:00:00:00/40 tag 3 ncq 131072 in
[ 2930.074247]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.083380] ata7.00: status: { DRDY } [ 2930.087981] ata7.01: exception Emask 0x100 SAct 0x3 SErr 0x0 action
0x6 frozen
[ 2930.092672] ata7.01: failed command: READ FPDMA QUEUED [ 2930.097279] ata7.01: cmd 60/00:00:00:06:00/01:00:00:00:00/40 tag 0 ncq 131072 in
[ 2930.097283]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.106463] ata7.01: status: { DRDY } [ 2930.111040] ata7.01: failed command: READ FPDMA QUEUED [ 2930.115630] ata7.01: cmd 60/00:08:00:07:00/01:00:00:00:00/40 tag 1 ncq 131072 in
[ 2930.115634]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2930.124786] ata7.01: status: { DRDY } [ 2930.129349] ata7.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.133977] ata7.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.138537] ata7.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.143074] ata7.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2930.147538] ata7.15: hard resetting link [ 2930.864034] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370) [ 2930.868757] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2930.873236] ata7.15: PMP revalidation failed (errno=-19) [ 2935.868025] ata7.15: hard resetting link [ 2936.588038] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370) [ 2936.592742] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2936.597296] ata7.15: PMP revalidation failed (errno=-19) [ 2936.601803] ata7.15: limiting SATA link speed to 1.5 Gbps [ 2941.592044] ata7.15: hard resetting link [ 2942.312039] ata7.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 2942.316762] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2942.321236] ata7.15: PMP revalidation failed (errno=-19) [ 2942.325672] ata7.15: failed to recover PMP after 5 tries, giving up [ 2942.330101] ata7.15: Port Multiplier detaching [ 2942.334489] ata7.00: disabled [ 2942.338863] ata7.01: disabled [ 2942.343145] ata7.00: disabled [ 2947.316024] ata7: hard resetting link [ 2948.036036] ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 370) [ 2948.040497] ata7.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 [ 2948.044701] ahci 0000:02:00.0: FBS is enabled.
[ 2948.049005] ata7.00: hard resetting link [ 2948.368250] ata7.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 2948.372472] ata7.01: hard resetting link [ 2948.696248] ata7.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 2948.700471] ata7.02: hard resetting link [ 2949.024255] ata7.02: SATA link down (SStatus 0 SControl 320) [ 2949.028581] ata7.03: hard resetting link [ 2949.352249] ata7.03: SATA link down (SStatus 0 SControl 320) [ 2949.356582] ata7.04: hard resetting link [ 2949.680248] ata7.04: SATA link down (SStatus 0 SControl 320) [ 2949.684638] ata7.05: hard resetting link [ 2950.008192] ata7.05: failed to write SCR 1 (Emask=0x1) [ 2950.012618] ata7.05: SATA link down (SStatus 0 SControl 0) [ 2950.018426] ata7.00: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 2950.022698] ata7.00: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA [ 2950.028551] ata7.00: configured for UDMA/133 [ 2950.034073] ata7.01: native sectors (2) is smaller than sectors
(3907029168)
[ 2950.038668] ata7.01: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 2950.043219] ata7.01: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA [ 2950.049087] ata7.01: configured for UDMA/133 [ 2950.053758] ata7.01: device reported invalid CHS sector 0 [ 2950.058290] ata7.01: device reported invalid CHS sector 0 [ 2950.062735] ata7.00: device reported invalid CHS sector 0 [ 2950.067131] ata7.00: device reported invalid CHS sector 0 [ 2950.071451] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 2950.075844] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current] [descriptor] [ 2950.080228] Descriptor sense data with sense descriptors (in hex):
[ 2950.084616]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.089114]         00 00 00 00
[ 2950.093453] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense information [ 2950.097839] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 06 00 00 01 00 00 [ 2950.102283] end_request: I/O error, dev sdc, sector 1536 [ 2950.106652] quiet_error: 45 callbacks suppressed [ 2950.110957] Buffer I/O error on device sdc, logical block 192 [ 2950.115306] Buffer I/O error on device sdc, logical block 193 [ 2950.119578] Buffer I/O error on device sdc, logical block 194 [ 2950.123816] Buffer I/O error on device sdc, logical block 195 [ 2950.127958] Buffer I/O error on device sdc, logical block 196 [ 2950.132036] Buffer I/O error on device sdc, logical block 197 [ 2950.136119] Buffer I/O error on device sdc, logical block 198 [ 2950.140190] Buffer I/O error on device sdc, logical block 199 [ 2950.144269] Buffer I/O error on device sdc, logical block 200 [ 2950.148281] Buffer I/O error on device sdc, logical block 201 [ 2950.152265] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 2950.156275] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current] [descriptor] [ 2950.160289] Descriptor sense data with sense descriptors (in hex):
[ 2950.164318]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.168471]         00 00 00 00
[ 2950.172471] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense information [ 2950.176525] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 07 00 00 01 00 00 [ 2950.180659] end_request: I/O error, dev sdc, sector 1792 [ 2950.184743] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 2950.188856] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current] [descriptor] [ 2950.192976] Descriptor sense data with sense descriptors (in hex):
[ 2950.197094]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.201337]         00 00 00 00
[ 2950.205439] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense information [ 2950.209626] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 06 00 00 01 00 00 [ 2950.213939] end_request: I/O error, dev sdb, sector 1536 [ 2950.218252] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 2950.222627] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current] [descriptor] [ 2950.227010] Descriptor sense data with sense descriptors (in hex):
[ 2950.231370]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 2950.235813]         00 00 00 00
[ 2950.240143] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense information [ 2950.244528] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 07 00 00 01 00 00 [ 2950.248975] end_request: I/O error, dev sdb, sector 1792 [ 2950.253351] ata7: EH complete [ 2950.257986] ata7.00: detaching (SCSI 6:0:0:0) [ 2950.260412] sd 6:1:0:0: rejecting I/O to offline device [ 2950.262676] sd 6:0:0:0: rejecting I/O to offline device [ 2950.272236] sd 6:0:0:0: [sdb] Synchronizing SCSI cache [ 2950.274778] sd 6:0:0:0: [sdb] Stopping disk [ 2950.284568] end_request: I/O error, dev sdb, sector 0 [ 2950.287099] sd 6:1:0:0: rejecting I/O to offline device [ 2950.288321] end_request: I/O error, dev sdc, sector 0 [ 2950.291531] end_request: I/O error, dev sdb, sector 0 [ 2950.293912] sd 6:1:0:0: rejecting I/O to offline device [ 2950.296077] end_request: I/O error, dev sdc, sector 0 [ 2950.868137] ata7.01: detaching (SCSI 6:1:0:0) [ 2950.879987] sd 6:1:0:0: [sdc] Synchronizing SCSI cache [ 2950.884351] sd 6:1:0:0: [sdc] Stopping disk
[ 2951.490748] scsi 6:0:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 2951.497341] sd 6:0:0:0: [sdb] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 2951.501834] sd 6:0:0:0: [sdb] Write Protect is off [ 2951.506067] sd 6:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 2951.506855] scsi 6:1:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 2951.518252] sd 6:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 2951.523911] sd 6:1:0:0: [sdc] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 2951.530008] sd 6:1:0:0: [sdc] Write Protect is off [ 2951.532522] sd 6:1:0:0: [sdc] Mode Sense: 00 3a 00 00 [ 2951.533349] sd 6:1:0:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 2953.444386]  sdc: sdc1
[ 2953.450667] sd 6:1:0:0: [sdc] Attached SCSI disk [ 2954.301886]  sdb: sdb1 [ 2954.311753] sd 6:0:0:0: [sdb] Attached SCSI disk [ 2994.016046] ata7.00: failed to read SCR 1 (Emask=0x40) [ 2994.020684] ata7.01: failed to read SCR 1 (Emask=0x40) [ 2994.025282] ata7.02: failed to read SCR 1 (Emask=0x40) [ 2994.029859] ata7.03: failed to read SCR 1 (Emask=0x40) [ 2994.034443] ata7.04: failed to read SCR 1 (Emask=0x40) [ 2994.039024] ata7.05: failed to read SCR 1 (Emask=0x40) [ 2994.043613] ata7.15: exception Emask 0x4 SAct 0x0 SErr 0x400000 action 0x6 frozen [ 2994.048221] ata7.15: SError: { Handshk } [ 2994.052790] ata7.00: exception Emask 0x100 SAct 0xa SErr 0x0 action
0x6 frozen
[ 2994.057393] ata7.00: failed command: READ FPDMA QUEUED [ 2994.061957] ata7.00: cmd 60/00:08:00:18:00/01:00:00:00:00/40 tag 1 ncq 131072 in
[ 2994.061961]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.071179] ata7.00: status: { DRDY } [ 2994.075747] ata7.00: failed command: READ FPDMA QUEUED [ 2994.080311] ata7.00: cmd 60/00:18:00:19:00/01:00:00:00:00/40 tag 3 ncq 131072 in
[ 2994.080314]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.089460] ata7.00: status: { DRDY } [ 2994.093974] ata7.01: exception Emask 0x100 SAct 0x5 SErr 0x0 action
0x6 frozen
[ 2994.098544] ata7.01: failed command: READ FPDMA QUEUED [ 2994.103096] ata7.01: cmd 60/00:00:00:04:00/01:00:00:00:00/40 tag 0 ncq 131072 in
[ 2994.103099]          res 40/00:01:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.112254] ata7.01: status: { DRDY } [ 2994.116770] ata7.01: failed command: READ FPDMA QUEUED [ 2994.121280] ata7.01: cmd 60/00:10:00:05:00/01:00:00:00:00/40 tag 2 ncq 131072 in
[ 2994.121283]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask
0x4 (timeout)
[ 2994.130329] ata7.01: status: { DRDY } [ 2994.134794] ata7.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.139343] ata7.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.143815] ata7.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.148233] ata7.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[ 2994.152588] ata7.15: hard resetting link [ 2994.872040] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370) [ 2994.876666] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 2994.881056] ata7.15: PMP revalidation failed (errno=-19) [ 2999.876031] ata7.15: hard resetting link [ 3000.596037] ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370) [ 3000.600759] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 3000.605307] ata7.15: PMP revalidation failed (errno=-19) [ 3000.609803] ata7.15: limiting SATA link speed to 1.5 Gbps [ 3005.600038] ata7.15: hard resetting link [ 3006.320038] ata7.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 3006.324835] ata7.15: Port Multiplier vendor mismatch '0x1095' != '0x0'
[ 3006.329398] ata7.15: PMP revalidation failed (errno=-19) [ 3006.333932] ata7.15: failed to recover PMP after 5 tries, giving up [ 3006.338486] ata7.15: Port Multiplier detaching [ 3006.343045] ata7.00: disabled [ 3006.347531] ata7.01: disabled [ 3006.351918] ata7.00: disabled [ 3011.324021] ata7: hard resetting link [ 3012.044038] ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 370) [ 3012.048607] ata7.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 [ 3012.052909] ahci 0000:02:00.0: FBS is enabled.
[ 3012.057467] ata7.00: hard resetting link [ 3012.376255] ata7.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 3012.380560] ata7.01: hard resetting link [ 3012.704248] ata7.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 3012.708580] ata7.02: hard resetting link [ 3013.032247] ata7.02: SATA link down (SStatus 0 SControl 320) [ 3013.036615] ata7.03: hard resetting link [ 3013.360248] ata7.03: SATA link down (SStatus 0 SControl 320) [ 3013.364635] ata7.04: hard resetting link [ 3013.688246] ata7.04: SATA link down (SStatus 0 SControl 320) [ 3013.692689] ata7.05: hard resetting link [ 3014.016194] ata7.05: failed to write SCR 1 (Emask=0x1) [ 3014.020635] ata7.05: SATA link down (SStatus 0 SControl 0) [ 3014.026285] ata7.00: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 3014.030646] ata7.00: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA [ 3014.036430] ata7.00: configured for UDMA/133 [ 3014.042023] ata7.01: native sectors (2) is smaller than sectors
(3907029168)
[ 3014.046718] ata7.01: ATA-8: Hitachi HDS5C3020ALA632, ML6OA580, max
UDMA/133
[ 3014.051279] ata7.01: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA [ 3014.057159] ata7.01: configured for UDMA/133 [ 3014.059537] ata7.01: device reported invalid CHS sector 0 [ 3014.061890] ata7.00: device reported invalid CHS sector 0 [ 3014.064203] ata7.01: device reported invalid CHS sector 0 [ 3014.066474] ata7.00: device reported invalid CHS sector 0 [ 3014.068733] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 3014.071007] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current] [descriptor] [ 3014.073291] Descriptor sense data with sense descriptors (in hex):
[ 3014.075562]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.077904]         00 00 00 00
[ 3014.080183] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense information [ 3014.082476] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 04 00 00 01 00 00 [ 3014.084797] end_request: I/O error, dev sdc, sector 1024 [ 3014.087077] quiet_error: 118 callbacks suppressed [ 3014.089320] Buffer I/O error on device sdc, logical block 128 [ 3014.091593] Buffer I/O error on device sdc, logical block 129 [ 3014.093817] Buffer I/O error on device sdc, logical block 130 [ 3014.096015] Buffer I/O error on device sdc, logical block 131 [ 3014.098167] Buffer I/O error on device sdc, logical block 132 [ 3014.100286] Buffer I/O error on device sdc, logical block 133 [ 3014.102402] Buffer I/O error on device sdc, logical block 134 [ 3014.104521] Buffer I/O error on device sdc, logical block 135 [ 3014.106638] Buffer I/O error on device sdc, logical block 136 [ 3014.108721] Buffer I/O error on device sdc, logical block 137 [ 3014.110792] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 3014.112877] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current] [descriptor] [ 3014.114966] Descriptor sense data with sense descriptors (in hex):
[ 3014.117053]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.119211]         00 00 00 00
[ 3014.121313] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense information [ 3014.123421] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 18 00 00 01 00 00 [ 3014.125605] end_request: I/O error, dev sdb, sector 6144 [ 3014.127754] sd 6:1:0:0: [sdc]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 3014.129913] sd 6:1:0:0: [sdc]  Sense Key : Aborted Command [current] [descriptor] [ 3014.132067] Descriptor sense data with sense descriptors (in hex):
[ 3014.134199]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.136423]         00 00 00 00
[ 3014.138587] sd 6:1:0:0: [sdc]  Add. Sense: No additional sense information [ 3014.140791] sd 6:1:0:0: [sdc] CDB: Read(10): 28 00 00 00 05 00 00 01 00 00 [ 3014.143051] end_request: I/O error, dev sdc, sector 1280 [ 3014.145323] sd 6:0:0:0: [sdb]  Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE [ 3014.147615] sd 6:0:0:0: [sdb]  Sense Key : Aborted Command [current] [descriptor] [ 3014.149897] Descriptor sense data with sense descriptors (in hex):
[ 3014.152156]         72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
[ 3014.154478]         00 00 00 00
[ 3014.156758] sd 6:0:0:0: [sdb]  Add. Sense: No additional sense information [ 3014.159056] sd 6:0:0:0: [sdb] CDB: Read(10): 28 00 00 00 19 00 00 01 00 00 [ 3014.161406] end_request: I/O error, dev sdb, sector 6400 [ 3014.163703] ata7: EH complete [ 3014.165979] ata7.00: detaching (SCSI 6:0:0:0) [ 3014.168308] sd 6:0:0:0: rejecting I/O to offline device [ 3014.177610] sd 6:0:0:0: [sdb] Synchronizing SCSI cache [ 3014.179969] sd 6:0:0:0: [sdb] Stopping disk [ 3014.791747] ata7.01: detaching (SCSI 6:1:0:0) [ 3014.799621] sd 6:1:0:0: [sdc] Synchronizing SCSI cache [ 3014.804160] sd 6:1:0:0: [sdc] Stopping disk
[ 3015.419701] scsi 6:0:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 3015.425355] sd 6:0:0:0: [sdb] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 3015.429980] sd 6:0:0:0: [sdb] Write Protect is off [ 3015.434322] sd 6:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 3015.435019] scsi 6:1:0:0: Direct-Access     ATA      Hitachi HDS5C302
ML6O PQ: 0 ANSI: 5
[ 3015.440304] sd 6:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 3015.445835] sd 6:1:0:0: [sdc] 3907029168 512-byte logical blocks:
(2.00 TB/1.81 TiB)
[ 3015.450897] sd 6:1:0:0: [sdc] Write Protect is off [ 3015.455341] sd 6:1:0:0: [sdc] Mode Sense: 00 3a 00 00 [ 3015.456615] sd 6:1:0:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 3017.371727]  sdc: sdc1
[ 3017.377835] sd 6:1:0:0: [sdc] Attached SCSI disk [ 3018.219239]  sdb: sdb1 [ 3018.225421] sd 6:0:0:0: [sdb] Attached SCSI disk

... and the drives have this smartctl output:

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2           56  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2           35  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS

SATA Phy Event Counters (GP Log 0x11)
ID      Size     Value  Description
0x0001  2            0  Command failed due to ICRC error
0x0002  2            0  R_ERR response for data FIS
0x0003  2            0  R_ERR response for device-to-host data FIS
0x0004  2            0  R_ERR response for host-to-device data FIS
0x0005  2            0  R_ERR response for non-data FIS
0x0006  2            0  R_ERR response for device-to-host non-data FIS
0x0007  2            0  R_ERR response for host-to-device non-data FIS
0x0009  2            9  Transition from drive PhyRdy to drive PhyNRdy
0x000a  2            5  Device-to-host register FISes sent due to a COMRESET
0x000b  2            0  CRC errors within host-to-device FIS
0x000d  2            0  Non-CRC errors within host-to-device FIS



--
South East Open Source Solutions Limited Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ VAT number: 900 6633 53  http://seoss.co.uk/ +44-(0)1273-808309


-----
No virus found in this message.
Checked by AVG - www.avg.com
Version: 10.0.1388 / Virus Database: 1516/3750 - Release Date: 07/07/11
--
To unsubscribe from this list: send the line "unsubscribe linux-ide" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Tim Small - July 8, 2011, 9:53 a.m.
On 08/07/11 05:42, Hubert Bailey wrote:
> Tim,
>
> The 9125 is a simple controller without a internal processor.  The 9123 contains an internal processor to enhance RAID 0/1 operations.  If you are testing in a JBOD configuration you will not take advantage of the 9123 internal processor.

OK, that's fine.  I have a nice fast CPU in the system which runs the
Linux md code (which I can debug if necessary) with very high
throughput, and it even works across controller cards.  A JBOD is what I
want.

>   The internal processor can result in lower performance than the 9125.

It shouldn't result it complete read failures though, should it?  That's
what we are seeing on both the 9123, and the 9125 (although the 9123
seems to be worse).

Also 130M per second total throughput on a device which should have
around 500M per second throughput seems like very low performance to
me.  If the processor is capable of handling 350M/second+ throughput,
then that looks more like a performance bug with the PMP support to me?

>   However if you configure the drives in a RAID configuration using the 9123 RAID  utility you should see better performance than with 9125.
>   

The drives in the machine are using Linux's software RAID6 (26 drives in
the machine in total - multiple controllers).  The 9123-based cards were
selected because they were more readily available and cheaper.  Just
straight AHCI passthrough is all I want to work here, and the firmware
version installed on the 9123 cards I have doesn't support RAID AFAIK,
it just does plain AHCI.

And going back to the 9125 - the performance with that is unreliable
unless you turn off NCQ, and more seriously, sometimes reads are failed
entirely.  These are the 88SE9125 results again with 2.6.38 and the
default Linux NCQ depth of 31, whilst reading a single drive at a time
from behind a 3726 PMP:

 Timing buffered disk reads: 386 MB in  3.00 seconds = 128.59 MB/sec
 Timing buffered disk reads:  38 MB in  7.01 seconds =   5.42 MB/sec
 Timing buffered disk reads: read(2097152) returned 823296 bytes
BLKFLSBUF failed: No such device

^^ i.e. a read failure, see the previous emails for the associated
kernel error messages

 Timing buffered disk reads: 328 MB in  3.55 seconds =  92.29 MB/sec
 Timing buffered disk reads: 204 MB in  5.30 seconds =  38.48 MB/sec
 Timing buffered disk reads: 376 MB in  3.01 seconds = 124.78 MB/sec
 Timing buffered disk reads: 200 MB in  3.01 seconds =  66.53 MB/sec
 Timing buffered disk reads: 276 MB in  3.01 seconds =  91.68 MB/sec
 Timing buffered disk reads: 154 MB in  3.36 seconds =  45.81 MB/sec
 Timing buffered disk reads: 384 MB in  3.01 seconds = 127.45 MB/sec
 Timing buffered disk reads: 358 MB in  3.01 seconds = 119.03 MB/sec
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.65 MB/sec
 Timing buffered disk reads: 364 MB in  4.33 seconds =  84.11 MB/sec
 Timing buffered disk reads: 188 MB in  3.01 seconds =  62.44 MB/sec
 Timing buffered disk reads: 342 MB in  3.01 seconds = 113.47 MB/sec
 Timing buffered disk reads: 392 MB in  3.01 seconds = 130.39 MB/sec
 Timing buffered disk reads: 394 MB in  3.01 seconds = 130.76 MB/sec
 Timing buffered disk reads: 274 MB in  3.91 seconds =  70.16 MB/sec
 Timing buffered disk reads: 392 MB in  3.00 seconds = 130.50 MB/sec


Please could you acknowledge that there is actually a problem here?  I
don't know whether it's with the 88SE91xx controllers, or with the Linux
AHCI driver (or Linux PMP support), but this is clearly not correct
behaviour.  This fault doesn't appear when using a SiI3132, or an
88SX7042.  I don't currently have a different AHCI+FBS capable
controller to double-check against, but may be able to check against an
Intel one in a couple of weeks time.

Thanks,

Tim.
--
To unsubscribe from this list: send the line "unsubscribe linux-ide" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Tejun Heo - July 13, 2011, 7:34 a.m.
Hello,

On Fri, Jul 08, 2011 at 10:53:01AM +0100, Tim Small wrote:
> On 08/07/11 05:42, Hubert Bailey wrote:
>> The 9125 is a simple controller without a internal processor.  The
>> 9123 contains an internal processor to enhance RAID 0/1 operations.
>> If you are testing in a JBOD configuration you will not take
>> advantage of the 9123 internal proces sor.
> 
> OK, that's fine.  I have a nice fast CPU in the system which runs the
> Linux md code (which I can debug if necessary) with very high
> throughput, and it even works across controller cards.  A JBOD is what I
> want.

Yeah, especially for RAID 0/1, there isn't much 'acceleration' to do
and with the abundant extra cores and vast amount of main memory these
days hardware support for even R5/6 doesn't seem too useful.

> Please could you acknowledge that there is actually a problem here?  I
> don't know whether it's with the 88SE91xx controllers, or with the Linux
> AHCI driver (or Linux PMP support), but this is clearly not correct
> behaviour.  This fault doesn't appear when using a SiI3132, or an
> 88SX7042.  I don't currently have a different AHCI+FBS capable
> controller to double-check against, but may be able to check against an
> Intel one in a couple of weeks time.

Oh sure, it's not working properly.  Looking at the performance
numbers you posted for Windows, it seems the Windows driver isn't
using FBS either.  Larry, Hubert, can you guys please confirm this?
Should we blacklist FBS support for some of marvell ahci's?

Thanks.

Patch

diff --git a/drivers/ata/libahci.c b/drivers/ata/libahci.c
index d38c40f..a2f4b68 100644
--- a/drivers/ata/libahci.c
+++ b/drivers/ata/libahci.c
@@ -444,6 +444,7 @@  void ahci_save_initial_config(struct device *dev,
 			   "controller can do FBS, turning on CAP_FBS\n");
 		cap |= HOST_CAP_FBS;
 	}
+	cap &= ~HOST_CAP_FBS;
 
 	if (force_port_map && port_map != force_port_map) {
 		dev_printk(KERN_INFO, dev, "forcing port_map 0x%x -> 0x%x\n",