* SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller
@ 2011-06-07 18:04 Tim Small
2011-06-09 14:37 ` Tejun Heo
0 siblings, 1 reply; 14+ messages in thread
From: Tim Small @ 2011-06-07 18:04 UTC (permalink / raw)
To: linux-ide@vger.kernel.org
Hi,
I'm putting together a storage box to be used as a backup server with a
few disks (probably 26 hard disks - 3.5" 2TB 5900rpm), and have been
trying out a Silicon Image 3726 port multiplier.
The box I'm building currently has SATA ports provided by four different
types of controllers:
SATA 3 and 4x SATA 2 (Intel H67 chipset ports in ahci mode).
SATA 2 (Silicon Image 3132 - a single PCIe 1.0 x1 add-in card - ideally
only for temporary debugging reasons).
SATA 3 (Marvell 88SE9123 - several PCI express 2.0 x1 AHCI controller
cards).
SATA 2 (Silicon Image 3124 - PCI card).
The H67 seems to support the port multiplier but only in CBS mode (I can
read from an Intel 80G SSD at 260M per second when connected directly to
the motherboard, 170M per second from the motherboard AHCI via the PMP,
but that speed drops to 20M per second when I concurrently read from a
hard drive attached to the same port multiplier).
The Silicon Image 3132 works with the port multiplier, but I can only
get about 130M per second out of the 3132 (PCIe 1.0 1x with MaxPayload
128 bytes is all I get on this Gigabyte GA-PH67A-UD3-B3 motherboard), it
seems to be using FIS mode (the 130M per second is shared between drives
during concurrent reads).
The Silicon Image 3124 also works, but is not much use because the
ITE8892 PCI bridge chip only supports ye olde 33MHz PCI (so ~80M per
second max throughput for the whole card).
If I connect the 3726 port multiplier to the Marvell 88SE9123, it gets
recognised, and various ports get reset, but a "Port Multiplier vendor
mismatch" error message gets printed out, and no actual drives get detected.
77.203802] ata14: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xe frozen
77.204043] ata14: irq_stat 0x80400040, connection status changed
77.204201] ata14: SError: { PHYRdyChg CommWake DevExch }
77.204360] ata14: hard resetting link
78.098504] ata14: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
78.098905] ata14.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9
78.100545] ahci 0000:01:00.0: FBS is enabled.
78.100792] ata14.00: hard resetting link
78.418603] ata14.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320)
78.418795] ata14.01: hard resetting link
78.738493] ata14.01: SATA link down (SStatus 0 SControl 320)
78.738695] ata14.02: hard resetting link
79.058397] ata14.02: SATA link down (SStatus 0 SControl 320)
79.058595] ata14.03: hard resetting link
79.378274] ata14.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
79.378454] ata14.04: hard resetting link
79.698187] ata14.04: SATA link down (SStatus 0 SControl 320)
79.698382] ata14.05: hard resetting link
83.016906] ata14.15: qc timeout (cmd 0xe4)
83.017069] ata14.05: failed to read SCR 0 (Emask=0x4)
83.017226] ata14.05: failed to read SCR 0 (Emask=0x40)
83.017385] ata14.05: failed to read SCR 0 (Emask=0x40)
83.017540] ata14.00: failed to IDENTIFY (I/O error, err_mask=0x40)
83.017706] ata14.15: hard resetting link
83.788616] ata14.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
83.788966] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x113'
83.789149] ata14.15: PMP revalidation failed (errno=-19)
88.786995] ata14.15: hard resetting link
89.558702] ata14.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370)
89.559059] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x113'
89.559225] ata14.15: PMP revalidation failed (errno=-19)
89.559383] ata14.15: limiting SATA link speed to 1.5 Gbps
94.557103] ata14.15: hard resetting link
95.328790] ata14.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310)
95.329185] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x113'
95.329357] ata14.15: PMP revalidation failed (errno=-19)
95.329517] ata14.15: failed to recover PMP after 5 tries, giving up
95.329682] ata14.15: Port Multiplier detaching
95.329838] ata14.00: disabled
95.329981] ata14: EH complete
I found this:
https://gist.github.com/709632
"Using Marvell 88SE9123 Chip with Sil3726 PMP Chip Workaround patch for gentoo-sources-2.6.36-r1"
--- libata-pmp.c.orig 2010-11-22 04:34:38.000000000 +0900
+++ libata-pmp.c 2010-11-22 04:42:59.000000000 +0900
@@ -286,6 +286,8 @@
reason = "failed to write Sil3726 Private Register";
goto fail;
}
+ /* nr_ports decrement */
+ nr_ports--;
}
if (print_info) {
... and was going to give it a go, but it's not really obvious to me
what it does (aside from the err great comment of course), and I
couldn't find any other references to this patch on the web, and thought
someone here might be able to shed some light on it...
Cheers,
Tim.
^ permalink raw reply [flat|nested] 14+ messages in thread* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-06-07 18:04 SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller Tim Small @ 2011-06-09 14:37 ` Tejun Heo 2011-06-09 21:11 ` Tim Small 0 siblings, 1 reply; 14+ messages in thread From: Tejun Heo @ 2011-06-09 14:37 UTC (permalink / raw) To: Tim Small; +Cc: linux-ide@vger.kernel.org Hello, On Tue, Jun 07, 2011 at 07:04:33PM +0100, Tim Small wrote: > --- libata-pmp.c.orig 2010-11-22 04:34:38.000000000 +0900 > +++ libata-pmp.c 2010-11-22 04:42:59.000000000 +0900 > @@ -286,6 +286,8 @@ > reason = "failed to write Sil3726 Private Register"; > goto fail; > } > + /* nr_ports decrement */ > + nr_ports--; > } > > if (print_info) { > > > > ... and was going to give it a go, but it's not really obvious to me > what it does (aside from the err great comment of course), and I > couldn't find any other references to this patch on the web, and thought > someone here might be able to shed some light on it... 3726 has an extra port for SEMB device (ie. it's not connected to actual downstream port) and the above will make the kernel ignore that port completely. Maybe we shouldn't issue hardreset either. Can you please try the following patch (without the nr_ports-- hack)? diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c index f06b7ea..3ab4784 100644 --- a/drivers/ata/libata-pmp.c +++ b/drivers/ata/libata-pmp.c @@ -398,7 +398,8 @@ static void sata_pmp_quirks(struct ata_port *ap) /* port 5 is for SEMB device and it doesn't like SRST */ if (link->pmp == 5) - link->flags |= ATA_LFLAG_NO_SRST | + link->flags |= ATA_LFLAG_NO_HRST | + ATA_LFLAG_NO_SRST | ATA_LFLAG_ASSUME_SEMB; } } else if (vendor == 0x1095 && devid == 0x4723) { -- tejun ^ permalink raw reply related [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-06-09 14:37 ` Tejun Heo @ 2011-06-09 21:11 ` Tim Small 2011-06-10 10:24 ` Tejun Heo 0 siblings, 1 reply; 14+ messages in thread From: Tim Small @ 2011-06-09 21:11 UTC (permalink / raw) To: Tejun Heo; +Cc: linux-ide@vger.kernel.org Hi Tejun, 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... This is what happens when I hot-plugging the 3726 (with two drives attached to it) into a SiI3132... 399.038172] ata2: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xe frozen 399.038296] ata2: irq_stat 0x00b40090, PHY RDY changed 399.038402] ata2: hard resetting link 401.235936] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 0) 401.236557] ata2.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 401.236904] ata2.00: hard resetting link 401.556327] ata2.00: SATA link up 1.5 Gbps (SStatus 113 SControl 320) 401.556471] ata2.01: hard resetting link 401.876223] ata2.01: SATA link down (SStatus 0 SControl 320) 401.876440] ata2.02: hard resetting link 402.196093] ata2.02: SATA link down (SStatus 0 SControl 320) 402.196304] ata2.03: hard resetting link 402.516010] ata2.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) 402.516204] ata2.04: hard resetting link 402.835901] ata2.04: SATA link down (SStatus 0 SControl 320) 403.147472] ata2.05: no reset method available, skipping reset 403.147925] ata2.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300) 403.148773] ata2.00: ATA-7: Maxtor 6Y120M0, YAR51BW0, max UDMA/133 403.148945] ata2.00: 240121728 sectors, multi 0: LBA 403.150032] ata2.00: configured for UDMA/100 403.151113] ata2.03: ATA-7: Hitachi HUA721010KLA330, GKAOAB0A, max UDMA/133 403.151302] ata2.03: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32) 403.152568] ata2.03: configured for UDMA/100 403.152721] ata2: EH complete 403.152867] scsi 1:0:0:0: Direct-Access ATA Maxtor 6Y120M0 YAR5 PQ: 0 ANSI: 5 403.153349] sd 1:0:0:0: [sdb] 240121728 512-byte logical blocks: (122 GB/114 GiB) 403.153439] sd 1:0:0:0: [sdb] Write Protect is off 403.153459] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00 403.153505] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 403.154034] scsi 1:3:0:0: Direct-Access ATA Hitachi HUA72101 GKAO PQ: 0 ANSI: 5 403.154481] sd 1:3:0:0: [sdc] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB) 403.154546] sd 1:3:0:0: [sdc] Write Protect is off 403.154548] sd 1:3:0:0: [sdc] Mode Sense: 00 3a 00 00 403.154572] sd 1:3:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 403.162661] sdb: sdb1 403.163293] sd 1:0:0:0: [sdb] Attached SCSI disk 403.168597] sdc: sdc1 sdc2 < sdc5 > 403.169009] sd 1:3:0:0: [sdc] Attached SCSI disk ... reads from those drives then seem to work fine. 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... 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 736.101732] ata14.03: disabled 736.101874] ata14.00: disabled 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 746.629880] ahci 0000:01:00.0: FBS is enabled. 746.630139] ata14.00: hard resetting link 746.949339] ata14.00: SATA link down (SStatus 0 SControl 310) 746.949534] ata14.01: hard resetting link 747.269258] ata14.01: SATA link down (SStatus 0 SControl 320) 747.269448] ata14.02: hard resetting link 747.589167] ata14.02: SATA link down (SStatus 0 SControl 320) 747.589359] ata14.03: hard resetting link 747.909043] ata14.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) 747.909230] ata14.04: hard resetting link 748.228933] ata14.04: SATA link down (SStatus 0 SControl 320) 748.540699] ata14.05: no reset method available, skipping reset 748.541014] ata14.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300) 748.542361] ata14.03: ATA-7: Hitachi HUA721010KLA330, GKAOAB0A, max UDMA/133 748.542549] ata14.03: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA 748.544247] ata14.03: configured for UDMA/133 748.544445] ata14: EH complete 748.544610] ata14.03: detaching (SCSI 13:3:0:0) 748.556691] sd 13:3:0:0: [sdb] Synchronizing SCSI cache 748.556960] sd 13:3:0:0: [sdb] Stopping disk 749.009984] scsi 13:3:0:0: Direct-Access ATA Hitachi HUA72101 GKAO PQ: 0 ANSI: 5 749.010373] sd 13:3:0:0: [sdb] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB) 749.025616] sd 13:3:0:0: [sdb] Write Protect is off 749.025619] sd 13:3:0:0: [sdb] Mode Sense: 00 3a 00 00 749.025641] sd 13:3:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 751.208927] sdb: sdb1 sdb2 < sdb5 > 751.209352] sd 13:3:0:0: [sdb] Attached SCSI disk 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) 814.767241] ata14.15: limiting SATA link speed to 1.5 Gbps 819.764939] ata14.15: hard resetting link 821.488377] ata14.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310) 821.488766] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0' 821.488932] ata14.15: PMP revalidation failed (errno=-19) 826.486679] ata14.15: hard resetting link 828.210145] ata14.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310) 828.210520] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0' 828.210681] ata14.15: PMP revalidation failed (errno=-19) 828.210832] ata14.15: failed to recover PMP after 5 tries, giving up 828.210990] ata14.15: Port Multiplier detaching 828.211136] ata14.03: disabled 828.211274] ata14.00: disabled 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 834.932550] ahci 0000:01:00.0: FBS is enabled. 834.932810] ata14.00: hard resetting link 835.252010] ata14.00: SATA link up 1.5 Gbps (SStatus 113 SControl 310) 835.252200] ata14.01: hard resetting link 835.571932] ata14.01: SATA link down (SStatus 0 SControl 320) 835.572139] ata14.02: hard resetting link 835.891849] ata14.02: SATA link down (SStatus 0 SControl 320) 835.892045] ata14.03: hard resetting link 836.211721] ata14.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) 836.211903] ata14.04: hard resetting link 836.531597] ata14.04: SATA link down (SStatus 0 SControl 320) 836.843382] ata14.05: no reset method available, skipping reset 836.843720] ata14.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300) 836.844502] ata14.00: ATA-7: Maxtor 6Y120M0, YAR51BW0, max UDMA/133 836.844674] ata14.00: 240121728 sectors, multi 0: LBA 836.845674] ata14.00: configured for UDMA/133 836.847053] ata14.03: ATA-7: Hitachi HUA721010KLA330, GKAOAB0A, max UDMA/133 836.847228] ata14.03: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA 836.848736] ata14.03: configured for UDMA/133 836.848913] ata14: EH complete 836.848922] ata14.03: detaching (SCSI 13:3:0:0) 836.871374] sd 13:3:0:0: [sdb] Synchronizing SCSI cache 836.871703] sd 13:3:0:0: [sdb] Stopping disk 837.322901] scsi 13:0:0:0: Direct-Access ATA Maxtor 6Y120M0 YAR5 PQ: 0 ANSI: 5 837.323334] sd 13:0:0:0: [sdb] 240121728 512-byte logical blocks: (122 GB/114 GiB) 837.323392] sd 13:0:0:0: [sdb] Write Protect is off 837.323395] sd 13:0:0:0: [sdb] Mode Sense: 00 3a 00 00 837.323421] sd 13:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 837.323670] scsi 13:3:0:0: Direct-Access ATA Hitachi HUA72101 GKAO PQ: 0 ANSI: 5 837.324358] sd 13:3:0:0: [sdc] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB) 837.324628] sd 13:3:0:0: [sdc] Write Protect is off 837.324787] sd 13:3:0:0: [sdc] Mode Sense: 00 3a 00 00 837.324815] sd 13:3:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 837.327022] sdb: sdb1 837.327376] sd 13:0:0:0: [sdb] Attached SCSI disk 839.487216] sdc: sdc1 sdc2 < sdc5 > 839.487664] sd 13:3:0:0: [sdc] Attached SCSI disk .... 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). 839.487664] sd 13:3:0:0: [sdc] Attached SCSI disk 928.712783] ata14.00: failed to read SCR 1 (Emask=0x40) 928.713010] ata14.01: failed to read SCR 1 (Emask=0x40) 928.713167] ata14.02: failed to read SCR 1 (Emask=0x40) 928.713320] ata14.03: failed to read SCR 1 (Emask=0x40) 928.713474] ata14.04: failed to read SCR 1 (Emask=0x40) 928.713630] ata14.05: failed to read SCR 1 (Emask=0x40) 928.713787] ata14.15: exception Emask 0x4 SAct 0x0 SErr 0x0 action 0x6 frozen 928.713957] ata14.00: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen 928.714178] ata14.01: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen 928.714399] ata14.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen 928.714620] ata14.03: exception Emask 0x100 SAct 0x3 SErr 0x0 action 0x6 frozen 928.714841] ata14.03: failed command: READ FPDMA QUEUED 928.714999] ata14.03: cmd 60/00:00:00:02:00/01:00:00:00:00/40 tag 0 ncq 131072 in 928.715000] res 40/00:01:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout) 928.715440] ata14.03: status: { DRDY } 928.715583] ata14.03: failed command: READ FPDMA QUEUED 928.715738] ata14.03: cmd 60/00:08:00:03:00/01:00:00:00:00/40 tag 1 ncq 131072 in 928.715739] res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout) 928.716179] ata14.03: status: { DRDY } 928.716329] ata14.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen 928.716552] ata14.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen 928.716785] ata14.15: hard resetting link 930.440201] ata14.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370) 930.440531] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0' 930.440702] ata14.15: PMP revalidation failed (errno=-19) 935.438490] ata14.15: hard resetting link 937.161975] ata14.15: SATA link up 3.0 Gbps (SStatus 123 SControl 370) 937.162311] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0' 937.162474] ata14.15: PMP revalidation failed (errno=-19) 937.162629] ata14.15: limiting SATA link speed to 1.5 Gbps 942.160272] ata14.15: hard resetting link 943.883736] ata14.15: SATA link up 1.5 Gbps (SStatus 113 SControl 310) 943.884114] ata14.15: Port Multiplier vendor mismatch '0x1095' != '0x0' 943.884297] ata14.15: PMP revalidation failed (errno=-19) 943.884457] ata14.15: failed to recover PMP after 5 tries, giving up 943.884623] ata14.15: Port Multiplier detaching 943.884778] ata14.00: disabled 943.884920] ata14.03: disabled 943.885063] ata14.00: disabled 948.882087] ata14: hard resetting link 950.605510] ata14: SATA link up 3.0 Gbps (SStatus 123 SControl 370) 950.605902] ata14.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 950.606143] ahci 0000:01:00.0: FBS is enabled. 950.606387] ata14.00: hard resetting link 950.925629] ata14.00: SATA link up 1.5 Gbps (SStatus 113 SControl 310) 950.925807] ata14.01: hard resetting link 951.245532] ata14.01: SATA link down (SStatus 0 SControl 320) 951.245728] ata14.02: hard resetting link 951.565428] ata14.02: SATA link down (SStatus 0 SControl 320) 951.565625] ata14.03: hard resetting link 951.885272] ata14.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) 951.885449] ata14.04: hard resetting link 952.205216] ata14.04: SATA link down (SStatus 0 SControl 320) 952.516939] ata14.05: no reset method available, skipping reset 952.517234] ata14.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300) 952.517977] ata14.00: ATA-7: Maxtor 6Y120M0, YAR51BW0, max UDMA/133 952.518145] ata14.00: 240121728 sectors, multi 0: LBA 952.518955] ata14.00: configured for UDMA/133 952.519905] ata14.03: ATA-7: Hitachi HUA721010KLA330, GKAOAB0A, max UDMA/133 952.520082] ata14.03: 1953525168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA 952.521264] ata14.03: configured for UDMA/133 952.521443] ata14.03: device reported invalid CHS sector 0 952.521605] ata14.03: device reported invalid CHS sector 0 952.521761] sd 13:3:0:0: [sdc] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE 952.522053] sd 13:3:0:0: [sdc] Sense Key : Aborted Command [current] [descriptor] 952.522548] Descriptor sense data with sense descriptors (in hex): 952.522788] 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00 952.524111] 00 00 00 00 952.524591] sd 13:3:0:0: [sdc] Add. Sense: No additional sense information 952.524903] sd 13:3:0:0: [sdc] CDB: Read(10): 28 00 00 00 02 00 00 01 00 00 952.525980] end_request: I/O error, dev sdc, sector 512 952.526140] Buffer I/O error on device sdc, logical block 64 952.526306] Buffer I/O error on device sdc, logical block 65 952.526323] sd 13:3:0:0: rejecting I/O to offline device 952.526628] Buffer I/O error on device sdc, logical block 66 952.526630] Buffer I/O error on device sdc, logical block 67 952.526633] Buffer I/O error on device sdc, logical block 68 952.526635] Buffer I/O error on device sdc, logical block 69 952.526638] Buffer I/O error on device sdc, logical block 70 952.526640] Buffer I/O error on device sdc, logical block 71 952.526642] Buffer I/O error on device sdc, logical block 72 952.526644] Buffer I/O error on device sdc, logical block 73 952.526663] sd 13:3:0:0: [sdc] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE 952.526665] sd 13:3:0:0: [sdc] Sense Key : Aborted Command [current] [descriptor] 952.526668] Descriptor sense data with sense descriptors (in hex): 952.526686] 72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00 952.526692] 00 00 00 00 952.526696] sd 13:3:0:0: [sdc] Add. Sense: No additional sense information 952.526716] sd 13:3:0:0: [sdc] CDB: Read(10): 28 00 00 00 03 00 00 01 00 00 952.526741] end_request: I/O error, dev sdc, sector 768 952.526811] ata14: EH complete 952.526848] ata14.00: detaching (SCSI 13:0:0:0) 952.531753] sd 13:3:0:0: rejecting I/O to offline device 952.531916] end_request: I/O error, dev sdc, sector 0 952.532078] sd 13:3:0:0: rejecting I/O to offline device 952.532239] end_request: I/O error, dev sdc, sector 0 952.544961] sd 13:0:0:0: [sdb] Synchronizing SCSI cache 952.545209] sd 13:0:0:0: [sdb] Stopping disk 952.653571] ata14.03: detaching (SCSI 13:3:0:0) 952.672917] sd 13:3:0:0: [sdc] Synchronizing SCSI cache 952.673212] sd 13:3:0:0: [sdc] Stopping disk 953.145975] scsi 13:0:0:0: Direct-Access ATA Maxtor 6Y120M0 YAR5 PQ: 0 ANSI: 5 953.146403] sd 13:0:0:0: [sdb] 240121728 512-byte logical blocks: (122 GB/114 GiB) 953.146428] scsi 13:3:0:0: Direct-Access ATA Hitachi HUA72101 GKAO PQ: 0 ANSI: 5 953.146614] sd 13:3:0:0: [sdc] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB) 953.146666] sd 13:3:0:0: [sdc] Write Protect is off 953.146669] sd 13:3:0:0: [sdc] Mode Sense: 00 3a 00 00 953.146692] sd 13:3:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 953.147550] sd 13:0:0:0: [sdb] Write Protect is off 953.147710] sd 13:0:0:0: [sdb] Mode Sense: 00 3a 00 00 953.147739] sd 13:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 955.301412] sdc: sdc1 sdc2 < sdc5 > 955.301853] sd 13:3:0:0: [sdc] Attached SCSI disk 956.199755] sdb: sdb1 956.200134] sd 13:0:0:0: [sdb] Attached SCSI disk I hope this is of some help - if you can give any hints, I'm happy to try and dig a bit further (and/or if you'd like me to sent you any of the hardware involved, please let me know). Cheers! Tim. -- 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-06-09 21:11 ` Tim Small @ 2011-06-10 10:24 ` Tejun Heo 2011-06-10 10:31 ` Hubert Bailey 2011-06-10 16:43 ` Tim Small 0 siblings, 2 replies; 14+ messages in thread From: Tejun Heo @ 2011-06-10 10:24 UTC (permalink / raw) To: Tim Small; +Cc: linux-ide@vger.kernel.org, Saeed Bishara, Hubert Bailey 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? 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", Thanks. -- tejun ^ permalink raw reply related [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-06-10 10:24 ` Tejun Heo @ 2011-06-10 10:31 ` Hubert Bailey 2011-06-10 16:43 ` Tim Small 1 sibling, 0 replies; 14+ messages in thread From: Hubert Bailey @ 2011-06-10 10:31 UTC (permalink / raw) To: 'tj@kernel.org', 'tim@seoss.co.uk' Cc: 'linux-ide@vger.kernel.org', Saeed Bishara I have forwards this to the SW team. They should contact you shortly. ----- Original Message ----- From: Tejun Heo [mailto:tj@kernel.org] Sent: Friday, June 10, 2011 03:24 AM To: Tim Small <tim@seoss.co.uk> Cc: linux-ide@vger.kernel.org <linux-ide@vger.kernel.org>; Saeed Bishara; Hubert Bailey Subject: Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 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? 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", Thanks. -- tejun ^ permalink raw reply related [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-06-10 10:24 ` Tejun Heo 2011-06-10 10:31 ` Hubert Bailey @ 2011-06-10 16:43 ` Tim Small 2011-07-06 20:34 ` Tim Small 1 sibling, 1 reply; 14+ messages in thread From: Tim Small @ 2011-06-10 16:43 UTC (permalink / raw) To: Tejun Heo; +Cc: linux-ide@vger.kernel.org, Saeed Bishara, Hubert Bailey 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-06-10 16:43 ` Tim Small @ 2011-07-06 20:34 ` Tim Small 2011-07-07 12:13 ` Tim Small 0 siblings, 1 reply; 14+ messages in thread From: Tim Small @ 2011-07-06 20:34 UTC (permalink / raw) To: Tejun Heo, Hubert Bailey, lil; +Cc: linux-ide@vger.kernel.org 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-07-06 20:34 ` Tim Small @ 2011-07-07 12:13 ` Tim Small 2011-07-07 18:30 ` Tim Small 2011-07-07 18:43 ` Tim Small 0 siblings, 2 replies; 14+ messages in thread From: Tim Small @ 2011-07-07 12:13 UTC (permalink / raw) To: Tejun Heo, Hubert Bailey, lil; +Cc: linux-ide@vger.kernel.org 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. -- 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-07-07 12:13 ` Tim Small @ 2011-07-07 18:30 ` Tim Small 2011-07-07 18:38 ` Tim Small 2011-07-07 18:43 ` Tim Small 1 sibling, 1 reply; 14+ messages in thread From: Tim Small @ 2011-07-07 18:30 UTC (permalink / raw) To: Tejun Heo, Hubert Bailey, lil; +Cc: linux-ide@vger.kernel.org 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-07-07 18:30 ` Tim Small @ 2011-07-07 18:38 ` Tim Small 2011-07-08 4:42 ` Hubert Bailey 0 siblings, 1 reply; 14+ messages in thread From: Tim Small @ 2011-07-07 18:38 UTC (permalink / raw) To: Tejun Heo, Hubert Bailey, lil, linux-ide@vger.kernel.org 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* RE: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-07-07 18:38 ` Tim Small @ 2011-07-08 4:42 ` Hubert Bailey 2011-07-08 9:53 ` Tim Small 0 siblings, 1 reply; 14+ messages in thread From: Hubert Bailey @ 2011-07-08 4:42 UTC (permalink / raw) To: 'Tim Small', Tejun Heo, Larry Li, linux-ide@vger.kernel.org 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.14426 9] 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 offli ne 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.1066 38] 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 ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-07-08 4:42 ` Hubert Bailey @ 2011-07-08 9:53 ` Tim Small 2011-07-13 7:34 ` Tejun Heo 0 siblings, 1 reply; 14+ messages in thread From: Tim Small @ 2011-07-08 9:53 UTC (permalink / raw) To: Hubert Bailey, linux-ide@vger.kernel.org; +Cc: Tejun Heo, Larry Li 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-07-08 9:53 ` Tim Small @ 2011-07-13 7:34 ` Tejun Heo 0 siblings, 0 replies; 14+ messages in thread From: Tejun Heo @ 2011-07-13 7:34 UTC (permalink / raw) To: Tim Small; +Cc: Hubert Bailey, linux-ide@vger.kernel.org, Larry Li 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. -- tejun ^ permalink raw reply [flat|nested] 14+ messages in thread
* Re: SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller 2011-07-07 12:13 ` Tim Small 2011-07-07 18:30 ` Tim Small @ 2011-07-07 18:43 ` Tim Small 1 sibling, 0 replies; 14+ messages in thread From: Tim Small @ 2011-07-07 18:43 UTC (permalink / raw) To: linux-ide@vger.kernel.org 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. ^ permalink raw reply [flat|nested] 14+ messages in thread
end of thread, other threads:[~2011-07-13 7:34 UTC | newest] Thread overview: 14+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2011-06-07 18:04 SiI 3726 pmp doesn't work with 2.6.38 and Marvell 88SE9123 AHCI controller Tim Small 2011-06-09 14:37 ` Tejun Heo 2011-06-09 21:11 ` Tim Small 2011-06-10 10:24 ` Tejun Heo 2011-06-10 10:31 ` Hubert Bailey 2011-06-10 16:43 ` Tim Small 2011-07-06 20:34 ` Tim Small 2011-07-07 12:13 ` Tim Small 2011-07-07 18:30 ` Tim Small 2011-07-07 18:38 ` Tim Small 2011-07-08 4:42 ` Hubert Bailey 2011-07-08 9:53 ` Tim Small 2011-07-13 7:34 ` Tejun Heo 2011-07-07 18:43 ` Tim Small
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).