State of Port Multiplier Support in libata?

State of Port Multiplier Support in libata?

[Stefan Skotte]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi,

I was wondering what the odds are that my setup could be supported:

* Stardom/Raidon SOHOTANK ST-6600 (5 disk SATA array)
(http://www.stardom.com.tw/sohotank%20st6600.htm)
* STLab Silicon Image 3531 NCQ/FIS PMP PCIe adapter with one eSATA port
(uses sata_sil24).
(http://www.st-lab.com/assign.asp?keyid=bf9)

The classical example of it not working properly is that only one disk
in bay 2 is recognized; all other does not respond at all:

(the following denotes a few retries of getting the enclosure to work)

========
[ 2853.136680] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x2
frozen
[ 2853.136689] ata1: (irq_stat 0x00b00090, PHY RDY changed)
[ 2853.849146] ata1: soft resetting port
[ 2854.575897] ata1: softreset failed (SRST command error)
[ 2854.575904] ata1: reset failed (errno=-5), retrying in 10 secs
[ 2863.832012] ata1: hard resetting port
[ 2866.116128] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 2866.131290] ata1.00: ata_hpa_resize 1: sectors = 976773168,
hpa_sectors = 976773168
[ 2866.131300] ata1.00: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[ 2866.131305] ata1.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[ 2866.132337] ata1.00: ata_hpa_resize 1: sectors = 976773168,
hpa_sectors = 976773168
[ 2866.132349] ata1.00: configured for UDMA/100
[ 2866.132357] ata1: EH complete
[ 2866.132979] scsi 0:0:0:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[ 2866.133196] sd 0:0:0:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[ 2866.133349] sd 0:0:0:0: [sdb] Write Protect is off
[ 2866.133352] sd 0:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 2866.133596] sd 0:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 2866.133802] sd 0:0:0:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[ 2866.133951] sd 0:0:0:0: [sdb] Write Protect is off
[ 2866.133954] sd 0:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 2866.134190] sd 0:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[ 2866.134194]  sdb: sdb1
[ 2866.137954] sd 0:0:0:0: [sdb] Attached SCSI disk
[ 2866.138016] sd 0:0:0:0: Attached scsi generic sg2 type 0
[ 2888.640954] ata1: exception Emask 0x10 SAct 0x0 SErr 0x80000 action
0x2 frozen
[ 2888.640962] ata1: (irq_stat 0x01100010, PHY RDY changed)
[ 2889.352204] ata1: soft resetting port
[ 2889.352215] ata1: SATA link down (SStatus 0 SControl 300)
[ 2889.352224] ata1: failed to recover some devices, retrying in 5 secs
[ 2894.347612] ata1: hard resetting port
[ 2896.631711] ata1: softreset failed (SRST command error)
[ 2896.631718] ata1: reset failed (errno=-5), retrying in 8 secs
[ 2904.330473] ata1: hard resetting port
[ 2906.614575] ata1: softreset failed (SRST command error)
[ 2906.614582] ata1: reset failed (errno=-5), retrying in 8 secs
[ 2914.313359] ata1: hard resetting port
[ 2916.597439] ata1: softreset failed (SRST command error)
[ 2916.597446] ata1: reset failed (errno=-5), retrying in 33 secs
[ 2949.253385] ata1: hard resetting port
[ 2951.537463] ata1: softreset failed (SRST command error)
[ 2951.537471] ata1: reset failed, giving up
[ 2951.537475] ata1.00: disabled
[ 2951.537481] ata1: EH pending after completion, repeating EH (cnt=4)
[ 2951.537492] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x2
frozen
[ 2951.537496] ata1: (irq_stat 0x00a00080, device exchanged)
[ 2952.252216] ata1: soft resetting port
[ 2952.356056] ata1: softreset failed (SRST command error)
[ 2952.356063] ata1: reset failed (errno=-5), retrying in 10 secs
[ 2962.235101] ata1: hard resetting port
[ 2964.519180] ata1: softreset failed (SRST command error)
[ 2964.519187] ata1: reset failed (errno=-5), retrying in 8 secs
[ 2972.217964] ata1: hard resetting port
[ 2974.502045] ata1: softreset failed (SRST command error)
[ 2974.502051] ata1: reset failed (errno=-5), retrying in 33 secs
[ 3007.158016] ata1: hard resetting port
[ 3009.442069] ata1: softreset failed (SRST command error)
[ 3009.442076] ata1: reset failed, giving up
[ 3009.442084] ata1: EH complete
[ 3009.442958] sd 0:0:0:0: [sdb] Synchronizing SCSI cache
[ 3009.444698] sd 0:0:0:0: [sdb] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[ 3009.444705] sd 0:0:0:0: [sdb] Stopping disk
[ 3009.444722] sd 0:0:0:0: [sdb] START_STOP FAILED
[ 3009.444724] sd 0:0:0:0: [sdb] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[ 3009.445350] ACPI: PCI interrupt for device 0000:01:00.0 disabled
[ 3014.640966] sata_sil24 0000:01:00.0: version 0.9
[ 3014.640991] ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level,
low) -> IRQ 16
[ 3014.641022] PCI: Setting latency timer of device 0000:01:00.0 to 64
[ 3014.641300] scsi3 : sata_sil24
[ 3014.641373] ata4: SATA max UDMA/100 cmd 0xf8b9c000 ctl 0x00000000
bmdma 0x00000000 irq 0
[ 3015.056432] ata4: softreset failed (SRST command error)
[ 3015.056440] ata4: reset failed (errno=-5), retrying in 10 secs
[ 3027.219595] ata4: softreset failed (SRST command error)
[ 3027.219604] ata4: reset failed (errno=-5), retrying in 8 secs
[ 3037.202438] ata4: softreset failed (SRST command error)
[ 3037.202448] ata4: reset failed (errno=-5), retrying in 33 secs
[ 3072.142463] ata4: softreset failed (SRST command error)
[ 3072.142471] ata4: reset failed, giving up
========

As you can see the first try went quite okay since the disk was present
in bay 2, but then I moved it to bay 3-4 in the consecutive attempts;
which let to some timeouts.

Hardware/Configuration information:

Ubuntu Gutsy, stock kernel 2.6.22 (sata_sil24 v0.9). I have previously
tried with Feisty 2.6.20 (sata_sil24 v0.8), but that didn't work either.

Commell LV-677, Intel 945GM Chipset, Core 2 Duo mobile CPU, 3 GB Ram

I have verified the scsi_luns are set to 512, which should be more than
enough (as I found a reference to this in a rPath support issue somewhere).

lspci output:

==============
00:00.0 Host bridge: Intel Corporation Mobile 945GM/PM/GMS/940GML and
945GT Express Memory Controller Hub (rev 03)
00:01.0 PCI bridge: Intel Corporation Mobile 945GM/PM/GMS/940GML and
945GT Express PCI Express Root Port (rev 03)
00:02.0 VGA compatible controller: Intel Corporation Mobile
945GM/GMS/940GML Express Integrated Graphics Controller (rev 03)
00:02.1 Display controller: Intel Corporation Mobile 945GM/GMS/940GML
Express Integrated Graphics Controller (rev 03)
00:1b.0 Audio device: Intel Corporation 82801G (ICH7 Family) High
Definition Audio Controller (rev 02)
00:1c.0 PCI bridge: Intel Corporation 82801G (ICH7 Family) PCI Express
Port 1 (rev 02)
00:1d.0 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
#1 (rev 02)
00:1d.1 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
#2 (rev 02)
00:1d.2 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
#3 (rev 02)
00:1d.3 USB Controller: Intel Corporation 82801G (ICH7 Family) USB UHCI
#4 (rev 02)
00:1d.7 USB Controller: Intel Corporation 82801G (ICH7 Family) USB2 EHCI
Controller (rev 02)
00:1e.0 PCI bridge: Intel Corporation 82801 Mobile PCI Bridge (rev e2)
00:1f.0 ISA bridge: Intel Corporation 82801GBM (ICH7-M) LPC Interface
Bridge (rev 02)
00:1f.2 IDE interface: Intel Corporation 82801GBM/GHM (ICH7 Family)
Serial ATA Storage Controller IDE (rev 02)
00:1f.3 SMBus: Intel Corporation 82801G (ICH7 Family) SMBus Controller
(rev 02)
01:00.0 Mass storage controller: Silicon Image, Inc. Unknown device 3531
(rev 01)
02:00.0 Ethernet controller: Intel Corporation 82573L Gigabit Ethernet
Controller
03:0c.0 FireWire (IEEE 1394): Agere Systems FW323 (rev 61)
==============

Do I need a specific patch to enable my adapter, or is the support not
even there yet for my configuration ? (sure hope so :-/ )

Any help will be appreciated !


Kind Regards,
Stefan Skotte

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGhNVK+vG8YFo3LPMRAn9bAJ4/3+oxbbO9S5jEW5lBZWzpmZlVmQCfa65Z
7Z5I8VnK+JyA7XrSjIeVuJ8=
=mrwG
-----END PGP SIGNATURE-----

Re: State of Port Multiplier Support in libata?

[Tejun Heo]

Stefan Skotte wrote:
> Hi,
> 
> I was wondering what the odds are that my setup could be supported:
> 
> * Stardom/Raidon SOHOTANK ST-6600 (5 disk SATA array)
> (http://www.stardom.com.tw/sohotank%20st6600.htm)
> * STLab Silicon Image 3531 NCQ/FIS PMP PCIe adapter with one eSATA port
> (uses sata_sil24).
> (http://www.st-lab.com/assign.asp?keyid=bf9)
> 
> The classical example of it not working properly is that only one disk
> in bay 2 is recognized; all other does not respond at all:

Get 2.6.22-rc6 and apply patches from the following page.

  http://home-tj.org/wiki/index.php/Libata-tj-stable

It should work.

-- 
tejun

Re: State of Port Multiplier Support in libata?

[Stefan Skotte]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Tejun Heo wrote:
> Stefan Skotte wrote:
>> Hi,
>>
>> I was wondering what the odds are that my setup could be supported:
>>
>> * Stardom/Raidon SOHOTANK ST-6600 (5 disk SATA array)
>> (http://www.stardom.com.tw/sohotank%20st6600.htm)
>> * STLab Silicon Image 3531 NCQ/FIS PMP PCIe adapter with one eSATA port
>> (uses sata_sil24).
>> (http://www.st-lab.com/assign.asp?keyid=bf9)
>>
>> The classical example of it not working properly is that only one disk
>> in bay 2 is recognized; all other does not respond at all:
> 
> Get 2.6.22-rc6 and apply patches from the following page.
> 
>   http://home-tj.org/wiki/index.php/Libata-tj-stable
> 
> It should work.
> 

Thanks alot :) - I'm actually building it now on 2.6.22-rc6.

However there seems to be something within ipr.c that doesn't compile right:

==========================================================
Error Msg:
==========================================================
drivers/scsi/ipr.c: In function ‘__ipr_eh_dev_reset’:
drivers/scsi/ipr.c:3955: warning: passing argument 4 of ‘ata_do_eh’ from
incompatible pointer type
drivers/scsi/ipr.c: In function ‘ipr_ata_phy_reset’:
drivers/scsi/ipr.c:5049: error: ‘struct ata_port’ has no member named
‘device’
drivers/scsi/ipr.c:5053: error: ‘struct ata_port’ has no member named
‘device’
drivers/scsi/ipr.c:5056: error: ‘struct ata_port’ has no member named
‘device’
make[3]: *** [drivers/scsi/ipr.o] Error 1
make[2]: *** [drivers/scsi] Error 2
make[1]: *** [drivers] Error 2
make[1]: Leaving directory `/usr/src/linux-2.6.22-rc6'
make: *** [debian/stamp-build-kernel] Error 2
==========================================================

I just removed the ipr module since I'm not going to use it, but maybe
I'm doing something wrong since I'm usng the debian build process (?),
anyways I downloaded 2.6.22-rc6 from testing on kernel.org, so that
should atleast be right.

Thanks for getting back to me, I will report back how well my 3531-based
controller fares...

Kind regards,
Stefan


-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGiKs/+vG8YFo3LPMRAjVVAJ9Zg1mKZh5UKuRzcm/8pB1Oh4tAfQCdGV5R
Ejekf0OS2bfmf0UqGnp7jAY=
=Zg0T
-----END PGP SIGNATURE-----

Re: State of Port Multiplier Support in libata?

[Tejun Heo]

Stefan Skotte wrote:
> drivers/scsi/ipr.c: In function \x18__ipr_eh_dev_reset\x19:
> drivers/scsi/ipr.c:3955: warning: passing argument 4 of \x18ata_do_eh\x19 from
> incompatible pointer type
> drivers/scsi/ipr.c: In function \x18ipr_ata_phy_reset\x19:
> drivers/scsi/ipr.c:5049: error: \x18struct ata_port\x19 has no member named
> \x18device\x19
> drivers/scsi/ipr.c:5053: error: \x18struct ata_port\x19 has no member named
> \x18device\x19
> drivers/scsi/ipr.c:5056: error: \x18struct ata_port\x19 has no member named
> \x18device\x19
> make[3]: *** [drivers/scsi/ipr.o] Error 1
> make[2]: *** [drivers/scsi] Error 2
> make[1]: *** [drivers] Error 2
> make[1]: Leaving directory `/usr/src/linux-2.6.22-rc6'
> make: *** [debian/stamp-build-kernel] Error 2

Aiee, that's my bad.  I forgot to convert ipr.

> I just removed the ipr module since I'm not going to use it, but maybe
> I'm doing something wrong since I'm usng the debian build process (?),
> anyways I downloaded 2.6.22-rc6 from testing on kernel.org, so that
> should atleast be right.
> 
> Thanks for getting back to me, I will report back how well my 3531-based
> controller fares...

Thanks.

-- 
tejun

Re: State of Port Multiplier Support in libata?

[Stefan Skotte]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Tejun,

I've just compiled, and I'm now running the kernel with the patches applied.

It seems to work, however I'm not sure why the SATA Link is 1.5gb/s ?
Both my disks are SATA-II 300.

Here's some system information related to the patch(es):

========== hdparm -Tt /dev/sd[bc]1 ===========
/dev/sdb1:
 Timing cached reads:   2786 MB in  2.00 seconds = 1393.25 MB/sec
 Timing buffered disk reads:  232 MB in  3.01 seconds =  77.17 MB/sec

/dev/sdc1:
 Timing cached reads:   2742 MB in  2.00 seconds = 1370.87 MB/sec
 Timing buffered disk reads:  208 MB in  3.02 seconds =  68.88 MB/sec

========== dmesg ==========
[   90.256606] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
frozen
[   90.256615] ata1: irq_stat 0x00b40090 <PHY RDY changed>
[   90.256625] ata1: hard resetting link
[   92.449372] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[   92.593106] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x9/0x9
[   92.720891] ata1.00: hard resetting link
[   93.204061] ata1.00: softreset failed (SRST command error)
[   93.204068] ata1.00: reset failed (errno=-5), retrying in 10 secs
[  102.703482] ata1.00: hard resetting link
[  103.314425] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  103.330386] ata1.01: hard resetting link
[  103.893414] ata1.01: SATA link down (SStatus 0 SControl 300)
[  103.909388] ata1.02: hard resetting link
[  104.472403] ata1.02: SATA link down (SStatus 0 SControl 300)
[  104.488388] ata1.03: hard resetting link
[  105.051395] ata1.03: SATA link down (SStatus 0 SControl 300)
[  105.067367] ata1.04: hard resetting link
[  105.662330] ata1.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  105.662336] ata1.05: hard resetting link
[  106.225347] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  106.260017] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[  106.260023] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[  106.318220] ata1.00: configured for UDMA/100
[  106.333611] ata1.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[  106.333617] ata1.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[  106.334621] ata1.04: configured for UDMA/100
[  106.349138] ata1: EH complete
[  106.349170] PM: Adding info for No Bus:target0:0:0
[  106.349323] scsi 0:0:0:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[  106.349336] PM: Adding info for scsi:0:0:0:0
[  106.350572] sd 0:0:0:0: [sdb] 1465149168 512-byte hardware sectors
(750156 MB)
[  106.350589] sd 0:0:0:0: [sdb] Write Protect is off
[  106.350591] sd 0:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[  106.350615] sd 0:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  106.350666] sd 0:0:0:0: [sdb] 1465149168 512-byte hardware sectors
(750156 MB)
[  106.350678] sd 0:0:0:0: [sdb] Write Protect is off
[  106.350680] sd 0:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[  106.350702] sd 0:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  106.350705]  sdb: sdb1
[  106.366234] sd 0:0:0:0: [sdb] Attached SCSI disk
[  106.366296] sd 0:0:0:0: Attached scsi generic sg2 type 0
[  106.366329] PM: Adding info for No Bus:target0:0:4
[  106.366807] scsi 0:0:4:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[  106.366814] PM: Adding info for scsi:0:0:4:0
[  106.367883] sd 0:0:4:0: [sdc] 976773168 512-byte hardware sectors
(500108 MB)
[  106.367896] sd 0:0:4:0: [sdc] Write Protect is off
[  106.367899] sd 0:0:4:0: [sdc] Mode Sense: 00 3a 00 00
[  106.367922] sd 0:0:4:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  106.367963] sd 0:0:4:0: [sdc] 976773168 512-byte hardware sectors
(500108 MB)
[  106.367976] sd 0:0:4:0: [sdc] Write Protect is off
[  106.367978] sd 0:0:4:0: [sdc] Mode Sense: 00 3a 00 00
[  106.368000] sd 0:0:4:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  106.368003]  sdc: sdc1
[  106.373944] sd 0:0:4:0: [sdc] Attached SCSI disk
[  106.373977] sd 0:0:4:0: Attached scsi generic sg3 type 0
[  154.013280] kjournald starting.  Commit interval 5 seconds
[  154.018158] EXT3 FS on sdb1, internal journal
[  154.018168] EXT3-fs: mounted filesystem with ordered data mode.
[  156.854093] kjournald starting.  Commit interval 5 seconds
[  156.861351] EXT3 FS on sdc1, internal journal
[  156.861361] EXT3-fs: mounted filesystem with ordered data mode.
============================

Still my controller is not identified (PCI id?); dont know if thats
something you want to change for the final patch:

01:00.0 Mass storage controller: Silicon Image, Inc. Unknown device 3531
(rev 01)



- -Stefan

Tejun Heo wrote:
> Stefan Skotte wrote:
>> drivers/scsi/ipr.c: In function \x18__ipr_eh_dev_reset\x19:
>> drivers/scsi/ipr.c:3955: warning: passing argument 4 of \x18ata_do_eh\x19 from
>> incompatible pointer type
>> drivers/scsi/ipr.c: In function \x18ipr_ata_phy_reset\x19:
>> drivers/scsi/ipr.c:5049: error: \x18struct ata_port\x19 has no member named
>> \x18device\x19
>> drivers/scsi/ipr.c:5053: error: \x18struct ata_port\x19 has no member named
>> \x18device\x19
>> drivers/scsi/ipr.c:5056: error: \x18struct ata_port\x19 has no member named
>> \x18device\x19
>> make[3]: *** [drivers/scsi/ipr.o] Error 1
>> make[2]: *** [drivers/scsi] Error 2
>> make[1]: *** [drivers] Error 2
>> make[1]: Leaving directory `/usr/src/linux-2.6.22-rc6'
>> make: *** [debian/stamp-build-kernel] Error 2
> 
> Aiee, that's my bad.  I forgot to convert ipr.
> 
>> I just removed the ipr module since I'm not going to use it, but maybe
>> I'm doing something wrong since I'm usng the debian build process (?),
>> anyways I downloaded 2.6.22-rc6 from testing on kernel.org, so that
>> should atleast be right.
>>
>> Thanks for getting back to me, I will report back how well my 3531-based
>> controller fares...
> 
> Thanks.
> 

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGiMOv+vG8YFo3LPMRAkpOAKCjNCxGz4f+S20SOM8azZGnnMgufwCcCZXI
py27dunJY0xf+Q8EU8hM7bc=
=8cHz
-----END PGP SIGNATURE-----

Re: State of Port Multiplier Support in libata?

[Tejun Heo]

Stefan Skotte wrote:
> I've just compiled, and I'm now running the kernel with the patches applied.
> 
> It seems to work, however I'm not sure why the SATA Link is 1.5gb/s ?
> Both my disks are SATA-II 300.

I dunno either.  Does it come up as 3Gbps if you connect it directly to
the controller?

> ========== dmesg ==========
> [   90.256606] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
> frozen
> [   90.256615] ata1: irq_stat 0x00b40090 <PHY RDY changed>
> [   90.256625] ata1: hard resetting link
> [   92.449372] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
> [   92.593106] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
> feat 0x9/0x9
> [   92.720891] ata1.00: hard resetting link
> [   93.204061] ata1.00: softreset failed (SRST command error)
> [   93.204068] ata1.00: reset failed (errno=-5), retrying in 10 secs

I suppose you powered up the array @90sec, right?

> [  102.703482] ata1.00: hard resetting link
> [  103.314425] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [  103.330386] ata1.01: hard resetting link
> [  103.893414] ata1.01: SATA link down (SStatus 0 SControl 300)
> [  103.909388] ata1.02: hard resetting link
> [  104.472403] ata1.02: SATA link down (SStatus 0 SControl 300)
> [  104.488388] ata1.03: hard resetting link
> [  105.051395] ata1.03: SATA link down (SStatus 0 SControl 300)
> [  105.067367] ata1.04: hard resetting link
> [  105.662330] ata1.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [  105.662336] ata1.05: hard resetting link
> [  106.225347] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [  106.260017] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
> [  106.260023] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
> [  106.318220] ata1.00: configured for UDMA/100
> [  106.333611] ata1.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
> [  106.333617] ata1.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
> [  106.334621] ata1.04: configured for UDMA/100
> [  106.349138] ata1: EH complete

Everything looks pretty good.  Care to try some hotplug / power on, off
testings?

> Still my controller is not identified (PCI id?); dont know if thats
> something you want to change for the final patch:
> 
> 01:00.0 Mass storage controller: Silicon Image, Inc. Unknown device 3531
> (rev 01)

Oh well, this has nothing to do with the kernel or the driver.  You
should ask the pciutils maintainer.

-- 
tejun

Re: State of Port Multiplier Support in libata?

[Stefan Skotte]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hey Tejun,

Here's a few tries at testing the power on/off, unplugging disks:

============================
Here's the full log after a reboot, and me powering up the array
manually afterwards:
============================
[ 9995.743400] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
frozen
[ 9995.743409] ata1: irq_stat 0x00b40090 <PHY RDY changed>
[ 9995.743419] ata1: hard resetting link
[ 9997.936879] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[ 9998.080620] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x9/0x9
[ 9998.208414] ata1.00: hard resetting link
[ 9998.691615] ata1.00: softreset failed (SRST command error)
[ 9998.691623] ata1.00: reset failed (errno=-5), retrying in 10 secs
[10008.191634] ata1.00: hard resetting link
[10008.802619] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[10008.818589] ata1.01: hard resetting link
[10009.381644] ata1.01: SATA link down (SStatus 0 SControl 300)
[10009.397617] ata1.02: hard resetting link
[10009.960672] ata1.02: SATA link down (SStatus 0 SControl 300)
[10009.976646] ata1.03: hard resetting link
[10010.539699] ata1.03: SATA link down (SStatus 0 SControl 300)
[10010.555671] ata1.04: hard resetting link
[10011.150673] ata1.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[10011.150682] ata1.05: hard resetting link
[10011.713728] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[10011.759634] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[10011.759641] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[10011.817827] ata1.00: configured for UDMA/100
[10011.830608] ata1.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[10011.830615] ata1.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[10011.831615] ata1.04: configured for UDMA/100
[10011.845509] ata1: EH complete
[10011.845542] PM: Adding info for No Bus:target0:0:0
[10011.845990] scsi 0:0:0:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[10011.845998] PM: Adding info for scsi:0:0:0:0
[10011.846305] sd 0:0:0:0: [sdb] 1465149168 512-byte hardware sectors
(750156 MB)
[10011.846457] sd 0:0:0:0: [sdb] Write Protect is off
[10011.846460] sd 0:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[10011.846691] sd 0:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[10011.846895] sd 0:0:0:0: [sdb] 1465149168 512-byte hardware sectors
(750156 MB)
[10011.847041] sd 0:0:0:0: [sdb] Write Protect is off
[10011.847043] sd 0:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[10011.847273] sd 0:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[10011.847277]  sdb: sdb1
[10011.865846] sd 0:0:0:0: [sdb] Attached SCSI disk
[10011.865877] sd 0:0:0:0: Attached scsi generic sg2 type 0
[10011.865896] PM: Adding info for No Bus:target0:0:4
[10011.866259] scsi 0:0:4:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[10011.866266] PM: Adding info for scsi:0:0:4:0
[10011.867096] sd 0:0:4:0: [sdc] 976773168 512-byte hardware sectors
(500108 MB)
[10011.867112] sd 0:0:4:0: [sdc] Write Protect is off
[10011.867115] sd 0:0:4:0: [sdc] Mode Sense: 00 3a 00 00
[10011.867128] sd 0:0:4:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[10011.867166] sd 0:0:4:0: [sdc] 976773168 512-byte hardware sectors
(500108 MB)
[10011.867174] sd 0:0:4:0: [sdc] Write Protect is off
[10011.867176] sd 0:0:4:0: [sdc] Mode Sense: 00 3a 00 00
[10011.867188] sd 0:0:4:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[10011.867192]  sdc: sdc1
[10011.870897] sd 0:0:4:0: [sdc] Attached SCSI disk
[10011.870931] sd 0:0:4:0: Attached scsi generic sg3 type 0
============================
Here's when I rmmod sata_sil24:
=============================
[10142.204662] ata1.00: disabled
[10142.204667] ata1.04: disabled
[10142.205101] sd 0:0:0:0: [sdb] Synchronizing SCSI cache
[10142.206502] sd 0:0:0:0: [sdb] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[10142.206509] sd 0:0:0:0: [sdb] Stopping disk
[10142.207051] sd 0:0:0:0: [sdb] START_STOP FAILED
[10142.207054] sd 0:0:0:0: [sdb] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[10142.207223] PM: Removing info for scsi:0:0:0:0
[10142.207276] PM: Removing info for No Bus:target0:0:0
[10142.207421] sd 0:0:4:0: [sdc] Synchronizing SCSI cache
[10142.211458] sd 0:0:4:0: [sdc] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[10142.211465] sd 0:0:4:0: [sdc] Stopping disk
[10142.211777] sd 0:0:4:0: [sdc] START_STOP FAILED
[10142.211779] sd 0:0:4:0: [sdc] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[10142.211948] PM: Removing info for scsi:0:0:4:0
[10142.212008] PM: Removing info for No Bus:target0:0:4
[10142.212043] PM: Removing info for No Bus:host0
[10142.212103] ACPI: PCI interrupt for device 0000:01:00.0 disabled
=============================
Booting with array turned on:
(disks are spun up one at a time)
This also includes my slim dvdrw + seagate 500gb drive.
=============================
[   43.125831] scsi0 : sata_sil24
[   43.125837] PM: Adding info for No Bus:host0
[   43.125860] ata1: SATA max UDMA/100 cmd 0xf8878000 ctl 0x00000000
bmdma 0x00000000 irq 0
[   44.200476] PM: Adding info for ieee1394:00031d000000b79d
[   44.200536] ieee1394: Host added: ID:BUS[0-00:1023]
GUID[00031d000000b79d]
[   45.318554] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[   45.462294] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x9/0x9
[   45.590089] ata1.00: hard resetting link
[   46.201068] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[   46.217041] ata1.01: hard resetting link
[   46.780101] ata1.01: SATA link down (SStatus 0 SControl 300)
[   46.796074] ata1.02: hard resetting link
[   47.359134] ata1.02: SATA link down (SStatus 0 SControl 300)
[   47.375106] ata1.03: hard resetting link
[   47.938168] ata1.03: SATA link down (SStatus 0 SControl 300)
[   47.954139] ata1.04: hard resetting link
[   48.549147] ata1.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[   48.549153] ata1.05: hard resetting link
[   49.112205] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[   56.404253] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[   56.404259] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[   56.462446] ata1.00: configured for UDMA/100
[   62.687472] ata1.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[   62.687479] ata1.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[   62.688546] ata1.04: configured for UDMA/100
[   62.701504] ata1: EH complete
[   62.701528] PM: Adding info for No Bus:target0:0:0
[   62.701659] scsi 0:0:0:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[   62.701672] PM: Adding info for scsi:0:0:0:0
[   62.701999] PM: Adding info for No Bus:target0:0:4
[   62.702047] scsi 0:0:4:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[   62.702053] PM: Adding info for scsi:0:0:4:0
[   62.704419] ata_piix 0000:00:1f.2: version 2.11
[   62.704426] ata_piix 0000:00:1f.2: MAP [ P0 P2 IDE IDE ]
[   62.704446] ACPI: PCI Interrupt 0000:00:1f.2[B] -> GSI 19 (level,
low) -> IRQ 18
[   62.704474] PCI: Setting latency timer of device 0000:00:1f.2 to 64
[   62.704515] scsi1 : ata_piix
[   62.704522] PM: Adding info for No Bus:host1
[   62.704549] scsi2 : ata_piix
[   62.704554] PM: Adding info for No Bus:host2
[   62.704569] ata2: SATA max UDMA/133 cmd 0x000101f0 ctl 0x000103f6
bmdma 0x0001fa00 irq 14
[   62.704572] ata3: PATA max UDMA/100 cmd 0x00010170 ctl 0x00010376
bmdma 0x0001fa08 irq 15
[   62.709627] sd 0:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[   62.709637] sd 0:0:0:0: [sda] Write Protect is off
[   62.709640] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[   62.709651] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   62.709695] sd 0:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[   62.709702] sd 0:0:0:0: [sda] Write Protect is off
[   62.709704] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[   62.709716] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   62.709720]  sda: sda1
[   62.755054] sd 0:0:0:0: [sda] Attached SCSI disk
[   62.755485] sd 0:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[   62.755494] sd 0:0:4:0: [sdb] Write Protect is off
[   62.755496] sd 0:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[   62.755508] sd 0:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   62.755540] sd 0:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[   62.755548] sd 0:0:4:0: [sdb] Write Protect is off
[   62.755550] sd 0:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[   62.755561] sd 0:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   62.755564]  sdb: sdb1
[   62.761248] sd 0:0:4:0: [sdb] Attached SCSI disk
[   62.764902] sd 0:0:0:0: Attached scsi generic sg0 type 0
[   62.764918] sd 0:0:4:0: Attached scsi generic sg1 type 0
[   62.903813] ata2.00: ATA-7: ST3500630A, 3.AAE, max UDMA/100
[   62.903820] ata2.00: 976773168 sectors, multi 16: LBA48
[   62.903825] ata2.00: applying bridge limits
[   62.970241] ata2.00: configured for UDMA/100
[   63.288941] ata3.00: ATAPI: MATSHITADVD-RAM UJ-846S, F100, max UDMA/66
[   63.288945] ata3.00: limited to UDMA/33 due to 40-wire cable
[   63.460653] ata3.00: configured for UDMA/33
[   63.460672] PM: Adding info for No Bus:target1:0:0
[   63.460738] scsi 1:0:0:0: Direct-Access     ATA      ST3500630A
 3.AA PQ: 0 ANSI: 5
[   63.460746] PM: Adding info for scsi:1:0:0:0
[   63.460978] sd 1:0:0:0: [sdc] 976773168 512-byte hardware sectors
(500108 MB)
[   63.460988] sd 1:0:0:0: [sdc] Write Protect is off
[   63.460991] sd 1:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[   63.461003] sd 1:0:0:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   63.461039] sd 1:0:0:0: [sdc] 976773168 512-byte hardware sectors
(500108 MB)
[   63.461046] sd 1:0:0:0: [sdc] Write Protect is off
[   63.461048] sd 1:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[   63.461060] sd 1:0:0:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   63.461062]  sdc: sdc1 sdc2 < sdc5 >
[   63.507333] sd 1:0:0:0: [sdc] Attached SCSI disk
[   63.507523] sd 1:0:0:0: Attached scsi generic sg2 type 0
[   63.507540] PM: Adding info for No Bus:target2:0:0
[   63.509120] scsi 2:0:0:0: CD-ROM            MATSHITA DVD-RAM UJ-846S
 F100 PQ: 0 ANSI: 5
[   63.509131] PM: Adding info for scsi:2:0:0:0
[   63.509595] scsi 2:0:0:0: Attached scsi generic sg3 type 5
[   63.524513] sr0: scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw
xa/form2 cdda caddy
[   63.524517] Uniform CD-ROM driver Revision: 3.20
[   63.524661] sr 2:0:0:0: Attached scsi CD-ROM sr0
=============================
Array turned of without rmmod'ing sata_sil24:
=============================
[  351.223540] ata1.00: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  351.223550] ata1.01: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  351.223556] ata1.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  351.223562] ata1.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  351.223568] ata1.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  351.223573] ata1.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[  351.479090] ata1.15: failed to read PMP product ID
[  351.479096] ata1.15: retrying hardreset
[  351.479106] ata1.15: hard resetting link
[  356.566580] ata1.15: SATA link down (SStatus 1 SControl 0)
[  356.822165] ata1.15: failed to read PMP GSCR[0] (errno=-5)
[  356.822172] ata1.15: PMP revalidation failed (errno=-5)
[  356.822179] ata1.15: limiting SATA link speed to 1.5 Gbps
[  356.822184] ata1.15: retrying hardreset in 5 secs
[  361.817800] ata1.15: hard resetting link
[  366.905308] ata1.15: SATA link down (SStatus 1 SControl 10)
[  367.160893] ata1.15: failed to read PMP GSCR[0] (errno=-5)
[  367.160900] ata1.15: PMP revalidation failed (errno=-5)
[  367.160906] ata1.15: retrying hardreset in 5 secs
.. and continues to retry
=============================
Array turned on again:
=============================
(continued from above)
[  372.156532] ata1.15: hard resetting link
[  377.244059] ata1.15: SATA link down (SStatus 1 SControl 10)
[  377.499621] ata1.15: failed to read PMP GSCR[0] (errno=-5)
[  377.499628] ata1.15: PMP revalidation failed (errno=-5)
[  377.499635] ata1.15: retrying hardreset in 5 secs
[  382.495257] ata1.15: hard resetting link
[  387.582767] ata1.15: SATA link down (SStatus 1 SControl 10)
[  387.838349] ata1.15: failed to read PMP GSCR[0] (errno=-5)
[  387.838356] ata1.15: PMP revalidation failed (errno=-5)
[  387.838360] ata1.15: failed to recover PMP after 3 tries, giving up
[  387.838365] ata1.15: Port Multiplier detaching
[  387.838391] ata1.00: disabled
[  387.838398] ata1.04: disabled
[  387.838403] ata1.00: disabled
[  387.838411] ata1: EH pending after completion, repeating EH (cnt=4)
[  387.838423] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9
[  387.838428] ata1: irq_stat 0x01940090 <PHY RDY changed>
[  387.838437] ata1: hard resetting link
[  392.111206] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[  392.254950] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x9/0x9
[  392.382744] ata1.00: hard resetting link
[  392.865950] ata1.00: softreset failed (SRST command error)
[  392.865958] ata1.00: reset failed (errno=-5), retrying in 10 secs
[  402.366056] ata1.00: hard resetting link
[  402.977046] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  402.993018] ata1.01: hard resetting link
[  403.556078] ata1.01: SATA link down (SStatus 0 SControl 300)
[  403.572050] ata1.02: hard resetting link
[  404.135131] ata1.02: SATA link down (SStatus 0 SControl 300)
[  404.151086] ata1.03: hard resetting link
[  404.714143] ata1.03: SATA link down (SStatus 0 SControl 300)
[  404.730118] ata1.04: hard resetting link
[  405.325123] ata1.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  405.325130] ata1.05: hard resetting link
[  405.888183] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  405.933855] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[  405.933862] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[  405.992055] ata1.00: configured for UDMA/100
[  406.006812] ata1.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[  406.006820] ata1.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[  406.007809] ata1.04: configured for UDMA/100
[  406.019974] ata1: EH complete
[  406.019987] ata1.00: detaching (SCSI 0:0:0:0)
[  406.020286] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  406.020392] sd 0:0:0:0: [sda] Stopping disk
[  406.020502] PM: Removing info for scsi:0:0:0:0
[  406.020536] PM: Removing info for No Bus:target0:0:0
[  406.020546] ata1.04: detaching (SCSI 0:0:4:0)
[  406.020674] sd 0:0:4:0: [sdb] Synchronizing SCSI cache
[  406.020843] sd 0:0:4:0: [sdb] Stopping disk
[  406.464589] PM: Removing info for scsi:0:0:4:0
[  406.464678] PM: Removing info for No Bus:target0:0:4
[  406.464714] PM: Adding info for No Bus:target0:0:0
[  406.466047] scsi 0:0:0:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[  406.466063] PM: Adding info for scsi:0:0:0:0
[  406.467227] sd 0:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[  406.467240] sd 0:0:0:0: [sda] Write Protect is off
[  406.467244] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  406.467257] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  406.467300] sd 0:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[  406.467308] sd 0:0:0:0: [sda] Write Protect is off
[  406.467311] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  406.467323] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  406.467326]  sda: sda1
[  408.040630] sd 0:0:0:0: [sda] Attached SCSI disk
[  408.040695] sd 0:0:0:0: Attached scsi generic sg0 type 0
[  408.040734] PM: Adding info for No Bus:target0:0:4
[  408.041214] scsi 0:0:4:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[  408.041221] PM: Adding info for scsi:0:0:4:0
[  408.041667] sd 0:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[  408.041677] sd 0:0:4:0: [sdb] Write Protect is off
[  408.041680] sd 0:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[  408.041692] sd 0:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  408.041727] sd 0:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[  408.041735] sd 0:0:4:0: [sdb] Write Protect is off
[  408.041737] sd 0:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[  408.041751] sd 0:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  408.041754]  sdb: sdb1
[  410.941492] sd 0:0:4:0: [sdb] Attached SCSI disk
[  410.941561] sd 0:0:4:0: Attached scsi generic sg1 type 0
=============================
Disk in bay 2 pulled out:
=============================
[  560.721523] ata1.00: exception Emask 0x10 SAct 0x0 SErr 0x4010000
action 0xb
[  560.753469] ata1.00: hard resetting link
[  561.731833] ata1.00: SATA link down (SStatus 0 SControl 300)
[  561.747809] ata1: failed to recover some devices, retrying in 5 secs
[  566.759437] ata1.00: hard resetting link
[  567.322494] ata1.00: SATA link down (SStatus 0 SControl 300)
[  567.354441] ata1.00: limiting SATA link speed to 1.5 Gbps
[  567.354449] ata1.00: limiting speed to UDMA/100:PIO3
[  567.354454] ata1: failed to recover some devices, retrying in 5 secs
[  572.366093] ata1.00: hard resetting link
[  572.993021] ata1.00: SATA link down (SStatus 0 SControl 310)
[  573.008995] ata1.00: disabled
[  573.544093] ata1.00: hard resetting link
[  574.171053] ata1.00: SATA link down (SStatus 0 SControl 300)
[  574.187034] ata1: EH complete
[  574.187052] ata1.00: detaching (SCSI 0:0:0:0)
[  574.187323] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  574.187372] sd 0:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[  574.187380] sd 0:0:0:0: [sda] Stopping disk
[  574.187399] sd 0:0:0:0: [sda] START_STOP FAILED
[  574.187401] sd 0:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[  574.187407] PM: Removing info for scsi:0:0:0:0
[  574.187439] PM: Removing info for No Bus:target0:0:0
==============================
Disk in bay 2 reinserted:
==============================
[  600.263465] ata1.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000
action 0xb
[  600.295411] ata1.00: hard resetting link
[  601.193925] ata1.00: softreset failed (SRST command error)
[  601.193933] ata1.00: reset failed (errno=-5), retrying in 10 secs
[  610.278721] ata1.00: hard resetting link
[  611.305018] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  611.350966] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[  611.350974] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[  611.409167] ata1.00: configured for UDMA/100
[  611.424823] ata1: EH complete
[  611.424857] PM: Adding info for No Bus:target0:0:0
[  611.424971] scsi 0:0:0:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[  611.424985] PM: Adding info for scsi:0:0:0:0
[  611.425082] sd 0:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[  611.425102] sd 0:0:0:0: [sda] Write Protect is off
[  611.425107] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  611.425134] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  611.425198] sd 0:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[  611.425206] sd 0:0:0:0: [sda] Write Protect is off
[  611.425209] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[  611.425221] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[  611.425225]  sda: sda1
[  611.448869] sd 0:0:0:0: [sda] Attached SCSI disk
[  611.448931] sd 0:0:0:0: Attached scsi generic sg0 type 0
===========================

I will try to connect a harddrive directly to my controller, but that
will take some further testing (I'll get back on that subject).

The pci id doesn't concern me much, as long as the array works :D

Let me know if you need more tests...

- -stefan

Tejun Heo wrote:
> Stefan Skotte wrote:
>> I've just compiled, and I'm now running the kernel with the patches applied.
>>
>> It seems to work, however I'm not sure why the SATA Link is 1.5gb/s ?
>> Both my disks are SATA-II 300.
> 
> I dunno either.  Does it come up as 3Gbps if you connect it directly to
> the controller?
> 
>> ========== dmesg ==========
>> [   90.256606] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
>> frozen
>> [   90.256615] ata1: irq_stat 0x00b40090 <PHY RDY changed>
>> [   90.256625] ata1: hard resetting link
>> [   92.449372] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
>> [   92.593106] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
>> feat 0x9/0x9
>> [   92.720891] ata1.00: hard resetting link
>> [   93.204061] ata1.00: softreset failed (SRST command error)
>> [   93.204068] ata1.00: reset failed (errno=-5), retrying in 10 secs
> 
> I suppose you powered up the array @90sec, right?
> 
>> [  102.703482] ata1.00: hard resetting link
>> [  103.314425] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> [  103.330386] ata1.01: hard resetting link
>> [  103.893414] ata1.01: SATA link down (SStatus 0 SControl 300)
>> [  103.909388] ata1.02: hard resetting link
>> [  104.472403] ata1.02: SATA link down (SStatus 0 SControl 300)
>> [  104.488388] ata1.03: hard resetting link
>> [  105.051395] ata1.03: SATA link down (SStatus 0 SControl 300)
>> [  105.067367] ata1.04: hard resetting link
>> [  105.662330] ata1.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> [  105.662336] ata1.05: hard resetting link
>> [  106.225347] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> [  106.260017] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
>> [  106.260023] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
>> [  106.318220] ata1.00: configured for UDMA/100
>> [  106.333611] ata1.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
>> [  106.333617] ata1.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
>> [  106.334621] ata1.04: configured for UDMA/100
>> [  106.349138] ata1: EH complete
> 
> Everything looks pretty good.  Care to try some hotplug / power on, off
> testings?
> 
>> Still my controller is not identified (PCI id?); dont know if thats
>> something you want to change for the final patch:
>>
>> 01:00.0 Mass storage controller: Silicon Image, Inc. Unknown device 3531
>> (rev 01)
> 
> Oh well, this has nothing to do with the kernel or the driver.  You
> should ask the pciutils maintainer.
> 


-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGiPyW+vG8YFo3LPMRAqbzAJ9ZadqzwV1Ny7dglHRiy94pIAaiXQCdFf73
hQnrX3u9Ypf/CvbIPgqP1E0=
=sDoi
-----END PGP SIGNATURE-----

Re: State of Port Multiplier Support in libata?

[Tejun Heo]

Hello,

Stefan Skotte wrote:
> ============================
> Here's the full log after a reboot, and me powering up the array
> manually afterwards:
> ============================
> [ 9995.743400] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
> frozen
> [ 9995.743409] ata1: irq_stat 0x00b40090 <PHY RDY changed>
> [ 9995.743419] ata1: hard resetting link
> [ 9997.936879] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
> [ 9998.080620] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
> feat 0x9/0x9
> [ 9998.208414] ata1.00: hard resetting link
> [ 9998.691615] ata1.00: softreset failed (SRST command error)
> [ 9998.691623] ata1.00: reset failed (errno=-5), retrying in 10 secs

Hmmm... it seems we can do a bit better here with shorter retry
interval.  The driver probably spins up in 5~7 secs.  The rest is wasted
here.  10secs isn't too bad tho.

> =============================
> Booting with array turned on:
> (disks are spun up one at a time)
> This also includes my slim dvdrw + seagate 500gb drive.
> =============================

Everything looks good.

> =============================
> Array turned of without rmmod'ing sata_sil24:
> =============================
[--snip--]
> [  351.479090] ata1.15: failed to read PMP product ID
> [  351.479096] ata1.15: retrying hardreset
> [  351.479106] ata1.15: hard resetting link
> [  356.566580] ata1.15: SATA link down (SStatus 1 SControl 0)
> [  356.822165] ata1.15: failed to read PMP GSCR[0] (errno=-5)
> [  356.822172] ata1.15: PMP revalidation failed (errno=-5)
> [  356.822179] ata1.15: limiting SATA link speed to 1.5 Gbps
> [  356.822184] ata1.15: retrying hardreset in 5 secs
> [  361.817800] ata1.15: hard resetting link
> [  366.905308] ata1.15: SATA link down (SStatus 1 SControl 10)
> [  367.160893] ata1.15: failed to read PMP GSCR[0] (errno=-5)
> [  367.160900] ata1.15: PMP revalidation failed (errno=-5)
> [  367.160906] ata1.15: retrying hardreset in 5 secs
> .. and continues to retry

The retry limit is 5 times.  Because losing PMP makes all downstream
devices detached, I thought it's worth to try hard.  If you put another
device including another PMP there, libata will give up the current one
quickly (after only two tries).

> =============================
> Array turned on again:
> =============================
> (continued from above)
> [  372.156532] ata1.15: hard resetting link
> [  377.244059] ata1.15: SATA link down (SStatus 1 SControl 10)
> [  377.499621] ata1.15: failed to read PMP GSCR[0] (errno=-5)
> [  377.499628] ata1.15: PMP revalidation failed (errno=-5)
> [  377.499635] ata1.15: retrying hardreset in 5 secs
> [  382.495257] ata1.15: hard resetting link
> [  387.582767] ata1.15: SATA link down (SStatus 1 SControl 10)
> [  387.838349] ata1.15: failed to read PMP GSCR[0] (errno=-5)
> [  387.838356] ata1.15: PMP revalidation failed (errno=-5)

Ah... This is unfortunate.  Even though the array was turned back on, it
failed to respond to the last two tries resulting in detachment.  I
wonder why it failed to respond to two tries.  Is this behavior
reproducible?  If so, does updating firmware of PMP help?

> [  387.838360] ata1.15: failed to recover PMP after 3 tries, giving up

Ummm.... This should have been five.

> [  387.838365] ata1.15: Port Multiplier detaching
> [  387.838391] ata1.00: disabled
> [  387.838398] ata1.04: disabled
> [  387.838403] ata1.00: disabled

The rest looks fine.

> ==============================
> Disk in bay 2 reinserted:
> ==============================
> [  600.263465] ata1.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000
> action 0xb
> [  600.295411] ata1.00: hard resetting link
> [  601.193925] ata1.00: softreset failed (SRST command error)
> [  601.193933] ata1.00: reset failed (errno=-5), retrying in 10 secs
> [  610.278721] ata1.00: hard resetting link
> [  611.305018] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [  611.350966] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
> [  611.350974] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
> [  611.409167] ata1.00: configured for UDMA/100
> [  611.424823] ata1: EH complete

Pretty, isn't it?  :-)

Thanks.

-- 
tejun

Re: State of Port Multiplier Support in libata?

[Stefan Skotte]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Here's the full log from trying to reproduce error in powering array on/off:

=====================
******** modprobe sata_sil24 (array is already on)...
[27635.288848] sata_sil24 0000:01:00.0: version 1.0
[27635.288873] ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level,
low) -> IRQ 16
[27635.288904] PCI: Setting latency timer of device 0000:01:00.0 to 64
[27635.290003] scsi3 : sata_sil24
[27635.290018] PM: Adding info for No Bus:host3
[27635.290050] ata4: SATA max UDMA/100 cmd 0xf8e8c000 ctl 0x00000000
bmdma 0x00000000 irq 0
[27637.483686] ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[27637.627430] ata4.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x9/0x9
[27637.755223] ata4.00: hard resetting link
[27638.366203] ata4.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[27638.382178] ata4.01: hard resetting link
[27638.945235] ata4.01: SATA link down (SStatus 0 SControl 300)
[27638.961210] ata4.02: hard resetting link
[27639.524273] ata4.02: SATA link down (SStatus 0 SControl 300)
[27639.540487] ata4.03: hard resetting link
[27640.103302] ata4.03: SATA link down (SStatus 0 SControl 300)
[27640.119275] ata4.04: hard resetting link
[27640.714280] ata4.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[27640.714287] ata4.05: hard resetting link
[27641.277339] ata4.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[27641.323510] ata4.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[27641.323516] ata4.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[27641.381708] ata4.00: configured for UDMA/100
[27641.392371] ata4.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[27641.392377] ata4.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[27641.393434] ata4.04: configured for UDMA/100
[27641.409113] ata4: EH complete
[27641.409224] PM: Adding info for No Bus:target3:0:0
[27641.409593] scsi 3:0:0:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[27641.409696] PM: Adding info for scsi:3:0:0:0
[27641.409920] sd 3:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[27641.410095] sd 3:0:0:0: [sda] Write Protect is off
[27641.410097] sd 3:0:0:0: [sda] Mode Sense: 00 3a 00 00
[27641.410338] sd 3:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27641.410543] sd 3:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[27641.410691] sd 3:0:0:0: [sda] Write Protect is off
[27641.410694] sd 3:0:0:0: [sda] Mode Sense: 00 3a 00 00
[27641.410931] sd 3:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27641.410934]  sda: sda1
[27641.429747] sd 3:0:0:0: [sda] Attached SCSI disk
[27641.429932] sd 3:0:0:0: Attached scsi generic sg0 type 0
[27641.430054] PM: Adding info for No Bus:target3:0:4
[27641.430376] scsi 3:0:4:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[27641.430481] PM: Adding info for scsi:3:0:4:0
[27641.430699] sd 3:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[27641.430849] sd 3:0:4:0: [sdb] Write Protect is off
[27641.430852] sd 3:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[27641.431097] sd 3:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27641.431303] sd 3:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[27641.431453] sd 3:0:4:0: [sdb] Write Protect is off
[27641.431456] sd 3:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[27641.431719] sd 3:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27641.431722]  sdb: sdb1
[27641.440613] sd 3:0:4:0: [sdb] Attached SCSI disk
[27641.440707] sd 3:0:4:0: Attached scsi generic sg1 type 0
********* power off array......
[27684.956387] ata4.00: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[27684.956396] ata4.01: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[27684.956402] ata4.02: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[27684.956408] ata4.03: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[27684.956413] ata4.04: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[27684.956419] ata4.05: exception Emask 0x100 SAct 0x0 SErr 0x0 action
0x6 frozen
[27685.211956] ata4.15: failed to read PMP product ID
[27685.211962] ata4.15: retrying hardreset
[27685.211969] ata4.15: hard resetting link
[27690.299444] ata4.15: SATA link down (SStatus 1 SControl 0)
[27690.555072] ata4.15: failed to read PMP GSCR[0] (errno=-5)
[27690.555077] ata4.15: PMP revalidation failed (errno=-5)
[27690.555084] ata4.15: limiting SATA link speed to 1.5 Gbps
[27690.555089] ata4.15: retrying hardreset in 5 secs
[27695.550667] ata4.15: hard resetting link
[27700.638173] ata4.15: SATA link down (SStatus 1 SControl 10)
[27700.893759] ata4.15: failed to read PMP GSCR[0] (errno=-5)
[27700.893765] ata4.15: PMP revalidation failed (errno=-5)
[27700.893771] ata4.15: retrying hardreset in 5 secs
[27705.889391] ata4.15: hard resetting link
[27710.976901] ata4.15: SATA link down (SStatus 1 SControl 10)
[27711.232487] ata4.15: failed to read PMP GSCR[0] (errno=-5)
[27711.232493] ata4.15: PMP revalidation failed (errno=-5)
[27711.232499] ata4.15: retrying hardreset in 5 secs
[27716.228121] ata4.15: hard resetting link
[27721.315629] ata4.15: SATA link down (SStatus 1 SControl 10)
[27721.571215] ata4.15: failed to read PMP GSCR[0] (errno=-5)
[27721.571221] ata4.15: PMP revalidation failed (errno=-5)
[27721.571226] ata4.15: failed to recover PMP after 3 tries, giving up
[27721.571230] ata4.15: Port Multiplier detaching
[27721.571257] ata4.00: disabled
[27721.571264] ata4.04: disabled
[27721.571268] ata4.00: disabled
[27721.571275] ata4: EH pending after completion, repeating EH (cnt=4)
[27721.571286] ata4: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x9
[27721.571291] ata4: irq_stat 0x01940090 <PHY RDY changed>
[27721.571298] ata4: hard resetting link
[27726.658706] ata4: SATA link down (SStatus 1 SControl 0)
[27726.658723] ata4: EH complete
[27726.658736] ata4.00: detaching (SCSI 3:0:0:0)
[27726.659003] sd 3:0:0:0: [sda] Synchronizing SCSI cache
[27726.661348] sd 3:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[27726.661354] sd 3:0:0:0: [sda] Stopping disk
[27726.661555] sd 3:0:0:0: [sda] START_STOP FAILED
[27726.661557] sd 3:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[27726.661565] PM: Removing info for scsi:3:0:0:0
[27726.661612] PM: Removing info for No Bus:target3:0:0
[27726.661621] ata4.04: detaching (SCSI 3:0:4:0)
[27726.661756] sd 3:0:4:0: [sdb] Synchronizing SCSI cache
[27726.663246] sd 3:0:4:0: [sdb] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[27726.663250] sd 3:0:4:0: [sdb] Stopping disk
[27726.663513] sd 3:0:4:0: [sdb] START_STOP FAILED
[27726.663515] sd 3:0:4:0: [sdb] Result: hostbyte=DID_BAD_TARGET
driverbyte=DRIVER_OK,SUGGEST_OK
[27726.663520] PM: Removing info for scsi:3:0:4:0
[27726.663550] PM: Removing info for No Bus:target3:0:4
******' power on array....
[27778.077300] ata4: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
frozen
[27778.077308] ata4: irq_stat 0x00b40090 <PHY RDY changed>
[27778.077318] ata4: hard resetting link
[27780.273144] ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[27780.416888] ata4.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x9/0x9
[27780.544683] ata4.00: hard resetting link
[27781.027888] ata4.00: softreset failed (SRST command error)
[27781.027895] ata4.00: reset failed (errno=-5), retrying in 10 secs
[27790.527995] ata4.00: hard resetting link
[27791.138984] ata4.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[27791.154959] ata4.01: hard resetting link
[27791.718016] ata4.01: SATA link down (SStatus 0 SControl 300)
[27791.733992] ata4.02: hard resetting link
[27792.297049] ata4.02: SATA link down (SStatus 0 SControl 300)
[27792.313025] ata4.03: hard resetting link
[27792.876081] ata4.03: SATA link down (SStatus 0 SControl 300)
[27792.892056] ata4.04: hard resetting link
[27793.487061] ata4.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[27793.487068] ata4.05: hard resetting link
[27794.050120] ata4.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[27794.090537] ata4.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[27794.090543] ata4.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[27794.148733] ata4.00: configured for UDMA/100
[27794.160917] ata4.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[27794.160923] ata4.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[27794.161914] ata4.04: configured for UDMA/100
[27794.177913] ata4: EH complete
[27794.177944] PM: Adding info for No Bus:target3:0:0
[27794.178386] scsi 3:0:0:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[27794.178394] PM: Adding info for scsi:3:0:0:0
[27794.178703] sd 3:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[27794.178856] sd 3:0:0:0: [sda] Write Protect is off
[27794.178859] sd 3:0:0:0: [sda] Mode Sense: 00 3a 00 00
[27794.179113] sd 3:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27794.179314] sd 3:0:0:0: [sda] 1465149168 512-byte hardware sectors
(750156 MB)
[27794.179461] sd 3:0:0:0: [sda] Write Protect is off
[27794.179464] sd 3:0:0:0: [sda] Mode Sense: 00 3a 00 00
[27794.179697] sd 3:0:0:0: [sda] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27794.179700]  sda: sda1
[27794.196746] sd 3:0:0:0: [sda] Attached SCSI disk
[27794.196806] sd 3:0:0:0: Attached scsi generic sg0 type 0
[27794.196841] PM: Adding info for No Bus:target3:0:4
[27794.197370] scsi 3:0:4:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[27794.197378] PM: Adding info for scsi:3:0:4:0
[27794.197669] sd 3:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[27794.197816] sd 3:0:4:0: [sdb] Write Protect is off
[27794.197819] sd 3:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[27794.198072] sd 3:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27794.198271] sd 3:0:4:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[27794.198417] sd 3:0:4:0: [sdb] Write Protect is off
[27794.198420] sd 3:0:4:0: [sdb] Mode Sense: 00 3a 00 00
[27794.198651] sd 3:0:4:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[27794.198654]  sdb: sdb1
[27794.201222] sd 3:0:4:0: [sdb] Attached SCSI disk
[27794.201259] sd 3:0:4:0: Attached scsi generic sg1 type 0
=======================

Unfortunately there isn't any firmware available for the PMP on my PCIe
board, if thats what you mean (?), it doesn't even have RAID capability.



Tejun Heo wrote:
> Hello,
> 
> Stefan Skotte wrote:
>> ============================
>> Here's the full log after a reboot, and me powering up the array
>> manually afterwards:
>> ============================
>> [ 9995.743400] ata1: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
>> frozen
>> [ 9995.743409] ata1: irq_stat 0x00b40090 <PHY RDY changed>
>> [ 9995.743419] ata1: hard resetting link
>> [ 9997.936879] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
>> [ 9998.080620] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
>> feat 0x9/0x9
>> [ 9998.208414] ata1.00: hard resetting link
>> [ 9998.691615] ata1.00: softreset failed (SRST command error)
>> [ 9998.691623] ata1.00: reset failed (errno=-5), retrying in 10 secs
> 
> Hmmm... it seems we can do a bit better here with shorter retry
> interval.  The driver probably spins up in 5~7 secs.  The rest is wasted
> here.  10secs isn't too bad tho.
> 
>> =============================
>> Booting with array turned on:
>> (disks are spun up one at a time)
>> This also includes my slim dvdrw + seagate 500gb drive.
>> =============================
> 
> Everything looks good.
> 
>> =============================
>> Array turned of without rmmod'ing sata_sil24:
>> =============================
> [--snip--]
>> [  351.479090] ata1.15: failed to read PMP product ID
>> [  351.479096] ata1.15: retrying hardreset
>> [  351.479106] ata1.15: hard resetting link
>> [  356.566580] ata1.15: SATA link down (SStatus 1 SControl 0)
>> [  356.822165] ata1.15: failed to read PMP GSCR[0] (errno=-5)
>> [  356.822172] ata1.15: PMP revalidation failed (errno=-5)
>> [  356.822179] ata1.15: limiting SATA link speed to 1.5 Gbps
>> [  356.822184] ata1.15: retrying hardreset in 5 secs
>> [  361.817800] ata1.15: hard resetting link
>> [  366.905308] ata1.15: SATA link down (SStatus 1 SControl 10)
>> [  367.160893] ata1.15: failed to read PMP GSCR[0] (errno=-5)
>> [  367.160900] ata1.15: PMP revalidation failed (errno=-5)
>> [  367.160906] ata1.15: retrying hardreset in 5 secs
>> .. and continues to retry
> 
> The retry limit is 5 times.  Because losing PMP makes all downstream
> devices detached, I thought it's worth to try hard.  If you put another
> device including another PMP there, libata will give up the current one
> quickly (after only two tries).
> 
>> =============================
>> Array turned on again:
>> =============================
>> (continued from above)
>> [  372.156532] ata1.15: hard resetting link
>> [  377.244059] ata1.15: SATA link down (SStatus 1 SControl 10)
>> [  377.499621] ata1.15: failed to read PMP GSCR[0] (errno=-5)
>> [  377.499628] ata1.15: PMP revalidation failed (errno=-5)
>> [  377.499635] ata1.15: retrying hardreset in 5 secs
>> [  382.495257] ata1.15: hard resetting link
>> [  387.582767] ata1.15: SATA link down (SStatus 1 SControl 10)
>> [  387.838349] ata1.15: failed to read PMP GSCR[0] (errno=-5)
>> [  387.838356] ata1.15: PMP revalidation failed (errno=-5)
> 
> Ah... This is unfortunate.  Even though the array was turned back on, it
> failed to respond to the last two tries resulting in detachment.  I
> wonder why it failed to respond to two tries.  Is this behavior
> reproducible?  If so, does updating firmware of PMP help?
> 
>> [  387.838360] ata1.15: failed to recover PMP after 3 tries, giving up
> 
> Ummm.... This should have been five.
> 
>> [  387.838365] ata1.15: Port Multiplier detaching
>> [  387.838391] ata1.00: disabled
>> [  387.838398] ata1.04: disabled
>> [  387.838403] ata1.00: disabled
> 
> The rest looks fine.
> 
>> ==============================
>> Disk in bay 2 reinserted:
>> ==============================
>> [  600.263465] ata1.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000
>> action 0xb
>> [  600.295411] ata1.00: hard resetting link
>> [  601.193925] ata1.00: softreset failed (SRST command error)
>> [  601.193933] ata1.00: reset failed (errno=-5), retrying in 10 secs
>> [  610.278721] ata1.00: hard resetting link
>> [  611.305018] ata1.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> [  611.350966] ata1.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
>> [  611.350974] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
>> [  611.409167] ata1.00: configured for UDMA/100
>> [  611.424823] ata1: EH complete
> 
> Pretty, isn't it?  :-)
> 
> Thanks.
> 

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGiWgk+vG8YFo3LPMRAoL1AJ4m56jlJhCg8vHkc3IfPawjQKDpaQCZAUvn
fqLn3FmJtLC0tk47ncuFVa0=
=ssXd
-----END PGP SIGNATURE-----

Re: State of Port Multiplier Support in libata?

[Tejun Heo]

Stefan Skotte wrote:
> Here's the full log from trying to reproduce error in powering array on/off:
> 
> =====================
> ********* power off array......
> [27685.211956] ata4.15: failed to read PMP product ID
> [27685.211962] ata4.15: retrying hardreset
> [27685.211969] ata4.15: hard resetting link
> [27690.299444] ata4.15: SATA link down (SStatus 1 SControl 0)
> [27690.555072] ata4.15: failed to read PMP GSCR[0] (errno=-5)
> [27690.555077] ata4.15: PMP revalidation failed (errno=-5)
> [27690.555084] ata4.15: limiting SATA link speed to 1.5 Gbps
> [27690.555089] ata4.15: retrying hardreset in 5 secs
> [27695.550667] ata4.15: hard resetting link
> [27700.638173] ata4.15: SATA link down (SStatus 1 SControl 10)
> [27700.893759] ata4.15: failed to read PMP GSCR[0] (errno=-5)
> [27700.893765] ata4.15: PMP revalidation failed (errno=-5)
> [27700.893771] ata4.15: retrying hardreset in 5 secs
> [27705.889391] ata4.15: hard resetting link
> [27710.976901] ata4.15: SATA link down (SStatus 1 SControl 10)
> [27711.232487] ata4.15: failed to read PMP GSCR[0] (errno=-5)
> [27711.232493] ata4.15: PMP revalidation failed (errno=-5)
> [27711.232499] ata4.15: retrying hardreset in 5 secs
> [27716.228121] ata4.15: hard resetting link
> [27721.315629] ata4.15: SATA link down (SStatus 1 SControl 10)
> [27721.571215] ata4.15: failed to read PMP GSCR[0] (errno=-5)
> [27721.571221] ata4.15: PMP revalidation failed (errno=-5)
> [27721.571226] ata4.15: failed to recover PMP after 3 tries, giving up
> [27721.571230] ata4.15: Port Multiplier detaching
> [27721.571257] ata4.00: disabled
> [27721.571264] ata4.04: disabled
> [27721.571268] ata4.00: disabled

This is okay.  PMP is detached after five tries.

> ******' power on array....
> [27778.077300] ata4: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
> frozen
> [27778.077308] ata4: irq_stat 0x00b40090 <PHY RDY changed>
> [27778.077318] ata4: hard resetting link
> [27780.273144] ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
> [27780.416888] ata4.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
> feat 0x9/0x9
> [27780.544683] ata4.00: hard resetting link
> [27781.027888] ata4.00: softreset failed (SRST command error)
> [27781.027895] ata4.00: reset failed (errno=-5), retrying in 10 secs
> [27790.527995] ata4.00: hard resetting link
> [27791.138984] ata4.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [27791.154959] ata4.01: hard resetting link
> [27791.718016] ata4.01: SATA link down (SStatus 0 SControl 300)
> [27791.733992] ata4.02: hard resetting link
> [27792.297049] ata4.02: SATA link down (SStatus 0 SControl 300)
> [27792.313025] ata4.03: hard resetting link
> [27792.876081] ata4.03: SATA link down (SStatus 0 SControl 300)
> [27792.892056] ata4.04: hard resetting link
> [27793.487061] ata4.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [27793.487068] ata4.05: hard resetting link
> [27794.050120] ata4.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [27794.090537] ata4.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
> [27794.090543] ata4.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
> [27794.148733] ata4.00: configured for UDMA/100
> [27794.160917] ata4.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
> [27794.160923] ata4.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
> [27794.161914] ata4.04: configured for UDMA/100

And probed correctly when powered back on.  What I was worried about was
when you power it off briefly and back on (or disconnect the cable
briefly) while EH is still retrying.  libata is supposed to recover
without detaching devices.

> =======================
> 
> Unfortunately there isn't any firmware available for the PMP on my PCIe
> board, if thats what you mean (?), it doesn't even have RAID capability.

http://www.siliconimage.com/support/supportsearchresults.aspx?pid=26&cid=23&ctid=2&osid=0&

This is what I meant but the latest one is dated 3/30/2006, so yours
might as well have the latest one already.

-- 
tejun

Re: State of Port Multiplier Support in libata?

[Stefan Skotte]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi Tejun,

On the 1.5Gbps vs. 3.0Gbps issue I had, the problem was just that I
hadn't paid attention to the factory default jumpers... They were set to
1.5Gbps ( I guess they do that for legacy purposes) :)

Do you want me to perform any other tests?

PS: Are you going to convert the patches for ipr.c & ipr.h so you can
apply the libata-tj patches without removing them ?

======================================================
dmesg output for reference (boot with array turned on:
======================================================
..
..
[   45.139206] sata_sil24 0000:01:00.0: version 1.0
[   45.139232] ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level,
low) -> IRQ 16
[   45.139276] PCI: Setting latency timer of device 0000:01:00.0 to 64
[   45.139334] scsi2 : sata_sil24
[   45.139340] PM: Adding info for No Bus:host2
[   45.139365] ata3: SATA max UDMA/100 cmd 0xf88bc000 ctl 0x00000000
bmdma 0x00000000 irq 0
[   45.885764] PM: Adding info for ieee1394:00031d000000b79d
[   45.885822] ieee1394: Host added: ID:BUS[0-00:1023]
GUID[00031d000000b79d]
[   47.335279] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
[   47.479001] ata3.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
feat 0x9/0x9
[   47.606797] ata3.00: hard resetting link
[   48.201813] ata3.00: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[   48.217787] ata3.01: hard resetting link
[   48.828779] ata3.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[   48.844751] ata3.02: hard resetting link
[   49.407820] ata3.02: SATA link down (SStatus 0 SControl 300)
[   49.423794] ata3.03: hard resetting link
[   49.986845] ata3.03: SATA link down (SStatus 0 SControl 300)
[   50.002837] ata3.04: hard resetting link
[   50.565906] ata3.04: SATA link down (SStatus 0 SControl 300)
[   50.565912] ata3.05: hard resetting link
[   51.128975] ata3.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[   51.150824] ata3.00: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
[   51.150829] ata3.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[   51.151812] ata3.00: configured for UDMA/100
[   51.197390] ata3.01: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
[   51.197395] ata3.01: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[   51.255592] ata3.01: configured for UDMA/100
[   51.268746] ata3: EH complete
[   51.268783] PM: Adding info for No Bus:target2:0:0
[   51.268902] scsi 2:0:0:0: Direct-Access     ATA      WDC WD5000YS-01M
09.0 PQ: 0 ANSI: 5
[   51.268915] PM: Adding info for scsi:2:0:0:0
[   51.269009] sd 2:0:0:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[   51.269028] sd 2:0:0:0: [sdb] Write Protect is off
[   51.269033] sd 2:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[   51.269059] sd 2:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   51.269137] sd 2:0:0:0: [sdb] 976773168 512-byte hardware sectors
(500108 MB)
[   51.269145] sd 2:0:0:0: [sdb] Write Protect is off
[   51.269147] sd 2:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[   51.269158] sd 2:0:0:0: [sdb] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   51.269162]  sdb: sdb1
[   51.274296] sd 2:0:0:0: [sdb] Attached SCSI disk
[   51.274358] sd 2:0:0:0: Attached scsi generic sg2 type 0
[   51.274389] PM: Adding info for No Bus:target2:0:1
[   51.274487] scsi 2:0:1:0: Direct-Access     ATA      ST3750640AS
 3.AA PQ: 0 ANSI: 5
[   51.274498] PM: Adding info for scsi:2:0:1:0
[   51.274571] sd 2:0:1:0: [sdc] 1465149168 512-byte hardware sectors
(750156 MB)
[   51.274578] sd 2:0:1:0: [sdc] Write Protect is off
[   51.274580] sd 2:0:1:0: [sdc] Mode Sense: 00 3a 00 00
[   51.274592] sd 2:0:1:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   51.274621] sd 2:0:1:0: [sdc] 1465149168 512-byte hardware sectors
(750156 MB)
[   51.274629] sd 2:0:1:0: [sdc] Write Protect is off
[   51.274630] sd 2:0:1:0: [sdc] Mode Sense: 00 3a 00 00
[   51.274642] sd 2:0:1:0: [sdc] Write cache: enabled, read cache:
enabled, doesn't support DPO or FUA
[   51.274647]  sdc: sdc1
[   51.295282] sd 2:0:1:0: [sdc] Attached SCSI disk
[   51.295332] sd 2:0:1:0: Attached scsi generic sg3 type 0
..
..
======================================================================

Kind regards,
Stefan Skotte

Tejun Heo wrote:
> Stefan Skotte wrote:
>> Here's the full log from trying to reproduce error in powering array on/off:
>>
>> =====================
>> ********* power off array......
>> [27685.211956] ata4.15: failed to read PMP product ID
>> [27685.211962] ata4.15: retrying hardreset
>> [27685.211969] ata4.15: hard resetting link
>> [27690.299444] ata4.15: SATA link down (SStatus 1 SControl 0)
>> [27690.555072] ata4.15: failed to read PMP GSCR[0] (errno=-5)
>> [27690.555077] ata4.15: PMP revalidation failed (errno=-5)
>> [27690.555084] ata4.15: limiting SATA link speed to 1.5 Gbps
>> [27690.555089] ata4.15: retrying hardreset in 5 secs
>> [27695.550667] ata4.15: hard resetting link
>> [27700.638173] ata4.15: SATA link down (SStatus 1 SControl 10)
>> [27700.893759] ata4.15: failed to read PMP GSCR[0] (errno=-5)
>> [27700.893765] ata4.15: PMP revalidation failed (errno=-5)
>> [27700.893771] ata4.15: retrying hardreset in 5 secs
>> [27705.889391] ata4.15: hard resetting link
>> [27710.976901] ata4.15: SATA link down (SStatus 1 SControl 10)
>> [27711.232487] ata4.15: failed to read PMP GSCR[0] (errno=-5)
>> [27711.232493] ata4.15: PMP revalidation failed (errno=-5)
>> [27711.232499] ata4.15: retrying hardreset in 5 secs
>> [27716.228121] ata4.15: hard resetting link
>> [27721.315629] ata4.15: SATA link down (SStatus 1 SControl 10)
>> [27721.571215] ata4.15: failed to read PMP GSCR[0] (errno=-5)
>> [27721.571221] ata4.15: PMP revalidation failed (errno=-5)
>> [27721.571226] ata4.15: failed to recover PMP after 3 tries, giving up
>> [27721.571230] ata4.15: Port Multiplier detaching
>> [27721.571257] ata4.00: disabled
>> [27721.571264] ata4.04: disabled
>> [27721.571268] ata4.00: disabled
> 
> This is okay.  PMP is detached after five tries.
> 
>> ******' power on array....
>> [27778.077300] ata4: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xa
>> frozen
>> [27778.077308] ata4: irq_stat 0x00b40090 <PHY RDY changed>
>> [27778.077318] ata4: hard resetting link
>> [27780.273144] ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
>> [27780.416888] ata4.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports,
>> feat 0x9/0x9
>> [27780.544683] ata4.00: hard resetting link
>> [27781.027888] ata4.00: softreset failed (SRST command error)
>> [27781.027895] ata4.00: reset failed (errno=-5), retrying in 10 secs
>> [27790.527995] ata4.00: hard resetting link
>> [27791.138984] ata4.00: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> [27791.154959] ata4.01: hard resetting link
>> [27791.718016] ata4.01: SATA link down (SStatus 0 SControl 300)
>> [27791.733992] ata4.02: hard resetting link
>> [27792.297049] ata4.02: SATA link down (SStatus 0 SControl 300)
>> [27792.313025] ata4.03: hard resetting link
>> [27792.876081] ata4.03: SATA link down (SStatus 0 SControl 300)
>> [27792.892056] ata4.04: hard resetting link
>> [27793.487061] ata4.04: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> [27793.487068] ata4.05: hard resetting link
>> [27794.050120] ata4.05: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
>> [27794.090537] ata4.00: ATA-7: ST3750640AS, 3.AAE, max UDMA/133
>> [27794.090543] ata4.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
>> [27794.148733] ata4.00: configured for UDMA/100
>> [27794.160917] ata4.04: ATA-7: WDC WD5000YS-01MPB1, 09.02E09, max UDMA/133
>> [27794.160923] ata4.04: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32)
>> [27794.161914] ata4.04: configured for UDMA/100
> 
> And probed correctly when powered back on.  What I was worried about was
> when you power it off briefly and back on (or disconnect the cable
> briefly) while EH is still retrying.  libata is supposed to recover
> without detaching devices.
> 
>> =======================
>>
>> Unfortunately there isn't any firmware available for the PMP on my PCIe
>> board, if thats what you mean (?), it doesn't even have RAID capability.
> 
> http://www.siliconimage.com/support/supportsearchresults.aspx?pid=26&cid=23&ctid=2&osid=0&
> 
> This is what I meant but the latest one is dated 3/30/2006, so yours
> might as well have the latest one already.
> 

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFGkTOi+vG8YFo3LPMRAr4yAJ4483plhoGWGD4oQl96RsZg1qTekgCfS2me
N0PQN0qfifqZqBwlefyA1HU=
=pF1z
-----END PGP SIGNATURE-----

Re: State of Port Multiplier Support in libata?

[Tejun Heo]

Hello,

Stefan Skotte wrote:
> On the 1.5Gbps vs. 3.0Gbps issue I had, the problem was just that I
> hadn't paid attention to the factory default jumpers... They were set to
> 1.5Gbps ( I guess they do that for legacy purposes) :)

Okay.

> Do you want me to perform any other tests?

Not at the moment.

> PS: Are you going to convert the patches for ipr.c & ipr.h so you can
> apply the libata-tj patches without removing them ?

Yeah, now that 2.6.23-rc1 is open.  I'll update those and resubmit the
patch.

Thanks.

-- 
tejun