43358 – Silicon Image sil5744 over eSATA support regression

Bug 43358 - Silicon Image sil5744 over eSATA support regression

Summary: Silicon Image sil5744 over eSATA support regression

Status:	NEW

Alias:	None

Product:	IO/Storage
Classification:	Unclassified
Component:	Serial ATA (show other bugs)
Hardware:	All Linux

Importance:	P1 normal
Assignee:	Jeff Garzik

URL:
Keywords:

Depends on:
Blocks:

Reported:	2012-06-09 01:00 UTC by Richard
Modified:	2014-05-30 07:12 UTC (History)
CC List:	3 users (show)

See Also:
Kernel Version:	3.4
Subsystem:
Regression:	Yes
Bisected commit-id:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Description Richard 2012-06-09 01:00:38 UTC

Overview:
I have an external eSATA/USB2.0 hard drive enclosure (Startech S252U2ERR) which uses the Silicon Image sil5744 RAID SATA controller.
I am using this on the following:
ATI Technologies Inc SB7x0/SB8x0/SB9x0 SATA Controller [AHCI mode] (rev 40) (prog-if 01 [AHCI 1.0])
There are 4 modes: JBOD, BIG, RAID0 and RAID1

Only the JBOD mode works okay on later kernel versions and both installed disks are detected using eSATA Port Multipler.
In any of the other modes, specifically RAID1, the device never initialises properly and the kernel retries eventually time out. Lots of lines are logged in dmesg.

All 2.6 kernel versions up to and including 2.6.36.4 work properly in all modes.
All kernel versions after this (2.6.37 onwards, including 3.x versions; 3.4.0 tested) do not work.


Steps to Reproduce:
1) Plug device into eSATA port in RAID1 mode and power on
2) Power on PC and boot into Linux kernel after 2.6.37
3) Load Partition Editor application
4) Monitor dmesg output to see lots or errors and failures. LEDs on device flash every 1 second trying to initialise. lsmod output shows high "Use count" against 'ahci'
5) Kernel attempts eventually stop after several minutes and application launches but does not show the SATA device

Expected Results:
Partition Editor launches immediately and shows the SATA device present

Build Date & Platform:
2.6.37 kernel
Ubuntu 10.10, 11.04, 11.10 and 12.04

Additional Builds and Platforms:
Also Gentoo Linux

Additional Information:
lsmod shows high (5 or 6) "Use count" against the ahci kernel module on a failing system

See also:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/910999?comments=all

kernel log excerpt:
...
09/06/2012 01:53:36	ata5	exception Emask 0x10 SAct 0x0 SErr 0x40d0002 action 0xe frozen
09/06/2012 01:53:36	ata5	irq_stat 0x00400040, connection status changed
09/06/2012 01:53:36	ata5	SError: { RecovComm PHYRdyChg CommWake 10B8B DevExch }
09/06/2012 01:53:36	ata5	hard resetting link
09/06/2012 01:53:37	ata5	SATA link up 3.0 Gbps (SStatus 123 SControl 300)
09/06/2012 01:53:37	ata5.15	Port Multiplier 1.1, 0x1095:0x5744 r33, 2 ports, feat 0x1/0x9
09/06/2012 01:53:37	ata5.00	hard resetting link
09/06/2012 01:53:38	ata5.00	SATA link up 3.0 Gbps (SStatus 123 SControl 320)
09/06/2012 01:53:38	ata5.01	hard resetting link
09/06/2012 01:53:38	ata5.01	SATA link down (SStatus 0 SControl 320)
09/06/2012 01:53:38	ata5.00	ATA-7: External Disk 0, 1.1597, max UDMA/133
09/06/2012 01:53:38	ata5.00	156301488 sectors, multi 1: LBA48 NCQ (depth 31/32)
09/06/2012 01:53:38	ata5.00	configured for UDMA/133
09/06/2012 01:53:38	ata5	EH complete
09/06/2012 01:53:38	scsi 4	:0:0: Direct-Access ATA External Disk 0 1.15 PQ: 0 ANSI: 5
09/06/2012 01:53:38	sd 4	:0:0: Attached scsi generic sg1 type 0
09/06/2012 01:53:38	sd 4	:0:0: [sdb] 156301488 512-byte logical blocks: (80.0 GB/74.5 GiB)
09/06/2012 01:53:38	sd 4	:0:0: [sdb] Write Protect is off
09/06/2012 01:53:38	sd 4	:0:0: [sdb] Mode Sense: 00 3a 00 00
09/06/2012 01:53:38	sd 4	:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
09/06/2012 01:53:38	ata5.00	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:38	ata5.01	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:38	ata5.15	exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:38	ata5.15	irq_stat 0x08000000, interface fatal error
09/06/2012 01:53:38	ata5.00	exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:38	ata5.00	failed command: READ FPDMA QUEUED
09/06/2012 01:53:38	ata5.00	cmd 60/08:00:00:00:00/00:00:00:00:00/40 tag 0 ncq 4096 in
09/06/2012 01:53:38	         res 50/00	0:00:00:00/00:00:00:00:00/00 Emask 0x100 (unknown error)
09/06/2012 01:53:38	ata5.00	status: { DRDY }
09/06/2012 01:53:38	ata5.01	exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:38	ata5.15	hard resetting link
09/06/2012 01:53:39	ata5.15	SATA link up 3.0 Gbps (SStatus 123 SControl 300)
09/06/2012 01:53:39	ata5.00	hard resetting link
09/06/2012 01:53:39	ata5.00	SATA link up 3.0 Gbps (SStatus 123 SControl 320)
09/06/2012 01:53:39	ata5.01	hard resetting link
09/06/2012 01:53:39	ata5.01	SATA link down (SStatus 0 SControl 320)
09/06/2012 01:53:39	ata5.00	configured for UDMA/133
09/06/2012 01:53:40	ata5	EH complete
09/06/2012 01:53:40	ata5.00	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:40	ata5.01	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:40	ata5.15	exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:40	ata5.15	irq_stat 0x08000000, interface fatal error
09/06/2012 01:53:40	ata5.00	exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:40	ata5.00	failed command: READ FPDMA QUEUED
09/06/2012 01:53:40	ata5.00	cmd 60/08:00:00:00:00/00:00:00:00:00/40 tag 0 ncq 4096 in
09/06/2012 01:53:40	         res 50/00	0:00:00:00/00:00:00:00:00/00 Emask 0x100 (unknown error)
09/06/2012 01:53:40	ata5.00	status: { DRDY }
09/06/2012 01:53:40	ata5.01	exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:40	ata5.15	hard resetting link
09/06/2012 01:53:40	ata5.15	SATA link up 3.0 Gbps (SStatus 123 SControl 300)
09/06/2012 01:53:40	ata5.00	hard resetting link
09/06/2012 01:53:41	ata5.00	SATA link up 3.0 Gbps (SStatus 123 SControl 320)
09/06/2012 01:53:41	ata5.01	hard resetting link
09/06/2012 01:53:41	ata5.01	SATA link down (SStatus 0 SControl 320)
09/06/2012 01:53:41	ata5.00	configured for UDMA/133
09/06/2012 01:53:41	ata5	EH complete
09/06/2012 01:53:41	ata5.00	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:41	ata5.01	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:41	ata5.15	exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:41	ata5.15	irq_stat 0x08000000, interface fatal error
09/06/2012 01:53:41	ata5.00	exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:41	ata5.00	failed command: READ FPDMA QUEUED
09/06/2012 01:53:41	ata5.00	cmd 60/08:00:00:00:00/00:00:00:00:00/40 tag 0 ncq 4096 in
09/06/2012 01:53:41	         res 50/00	0:00:00:00/00:00:00:00:00/00 Emask 0x100 (unknown error)
09/06/2012 01:53:41	ata5.00	status: { DRDY }
09/06/2012 01:53:41	ata5.01	exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:41	ata5.15	hard resetting link
09/06/2012 01:53:42	ata5.15	SATA link up 3.0 Gbps (SStatus 123 SControl 300)
09/06/2012 01:53:42	ata5.01	limiting SATA link speed to 1.5 Gbps
09/06/2012 01:53:42	ata5.00	hard resetting link
09/06/2012 01:53:42	ata5.00	SATA link up 3.0 Gbps (SStatus 123 SControl 320)
09/06/2012 01:53:42	ata5.01	hard resetting link
09/06/2012 01:53:42	ata5.01	SATA link down (SStatus 0 SControl 310)
09/06/2012 01:53:43	ata5.00	configured for UDMA/133
09/06/2012 01:53:43	ata5	EH complete
09/06/2012 01:53:43	ata5.00	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:43	ata5.01	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:43	ata5.15	limiting SATA link speed to 1.5 Gbps
09/06/2012 01:53:43	ata5.15	exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:43	ata5.15	irq_stat 0x08000000, interface fatal error
09/06/2012 01:53:43	ata5.00	exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:43	ata5.00	failed command: READ FPDMA QUEUED
09/06/2012 01:53:43	ata5.00	cmd 60/08:00:00:00:00/00:00:00:00:00/40 tag 0 ncq 4096 in
09/06/2012 01:53:43	         res 50/00	0:00:00:00/00:00:00:00:00/00 Emask 0x100 (unknown error)
09/06/2012 01:53:43	ata5.00	status: { DRDY }
09/06/2012 01:53:43	ata5.01	exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:43	ata5.15	hard resetting link
09/06/2012 01:53:43	ata5.15	SATA link up 1.5 Gbps (SStatus 113 SControl 310)
09/06/2012 01:53:43	ata5.01	limiting SATA link speed to 1.5 Gbps
09/06/2012 01:53:43	ata5.00	hard resetting link
09/06/2012 01:53:44	ata5.00	SATA link up 3.0 Gbps (SStatus 123 SControl 310)
09/06/2012 01:53:44	ata5.01	hard resetting link
09/06/2012 01:53:44	ata5.01	SATA link down (SStatus 0 SControl 310)
09/06/2012 01:53:44	ata5.00	configured for UDMA/133
09/06/2012 01:53:44	ata5	EH complete
09/06/2012 01:53:44	ata5.00	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:44	ata5.01	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:44	ata5.15	exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:44	ata5.15	irq_stat 0x08000000, interface fatal error
09/06/2012 01:53:44	ata5.00	exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:44	ata5.00	failed command: READ FPDMA QUEUED
09/06/2012 01:53:44	ata5.00	cmd 60/08:00:00:00:00/00:00:00:00:00/40 tag 0 ncq 4096 in
09/06/2012 01:53:44	         res 50/00	0:00:00:00/00:00:00:00:00/00 Emask 0x100 (unknown error)
09/06/2012 01:53:44	ata5.00	status: { DRDY }
09/06/2012 01:53:44	ata5.01	exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:44	ata5.15	hard resetting link
09/06/2012 01:53:45	ata5.15	SATA link up 1.5 Gbps (SStatus 113 SControl 310)
09/06/2012 01:53:45	ata5.01	limiting SATA link speed to 1.5 Gbps
09/06/2012 01:53:45	ata5.00	hard resetting link
09/06/2012 01:53:45	ata5.00	hard resetting link
09/06/2012 01:53:45	ata5.00	SATA link up 3.0 Gbps (SStatus 123 SControl 310)
09/06/2012 01:53:45	ata5.01	hard resetting link
09/06/2012 01:53:46	ata5.01	SATA link down (SStatus 0 SControl 310)
09/06/2012 01:53:46	ata5.00	configured for UDMA/133
09/06/2012 01:53:46	ata5	EH complete
09/06/2012 01:53:46	ata5.00	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:46	ata5.01	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:46	ata5.15	exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:46	ata5.15	irq_stat 0x08000000, interface fatal error
09/06/2012 01:53:46	ata5.00	exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:46	ata5.00	failed command: READ FPDMA QUEUED
09/06/2012 01:53:46	ata5.00	cmd 60/08:00:00:00:00/00:00:00:00:00/40 tag 0 ncq 4096 in
09/06/2012 01:53:46	         res 50/00	0:00:00:00/00:00:00:00:00/00 Emask 0x100 (unknown error)
09/06/2012 01:53:46	ata5.00	status: { DRDY }
09/06/2012 01:53:46	ata5.01	exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:46	ata5.15	hard resetting link
09/06/2012 01:53:46	ata5.15	SATA link up 1.5 Gbps (SStatus 113 SControl 310)
09/06/2012 01:53:46	ata5.01	limiting SATA link speed to 1.5 Gbps
09/06/2012 01:53:46	ata5.00	hard resetting link
09/06/2012 01:53:47	ata5.00	SATA link up 3.0 Gbps (SStatus 123 SControl 310)
09/06/2012 01:53:47	ata5.01	hard resetting link
09/06/2012 01:53:47	ata5.01	SATA link down (SStatus 0 SControl 310)
09/06/2012 01:53:47	ata5.00	configured for UDMA/133
09/06/2012 01:53:47	sd 4	:0:0: [sdb] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
09/06/2012 01:53:47	sd 4	:0:0: [sdb] Sense Key : Aborted Command [current] [descriptor]
09/06/2012 01:53:47		Descriptor sense data with sense descriptors (in hex):
09/06/2012 01:53:47		72 0b 00 00 00 00 00 0c 00 0a 80 00 00 00 00 00
09/06/2012 01:53:47		00 00 00 00
09/06/2012 01:53:47	sd 4	:0:0: [sdb] Add. Sense: No additional sense information
09/06/2012 01:53:47	sd 4	:0:0: [sdb] CDB: Read(10): 28 00 00 00 00 00 00 00 08 00
09/06/2012 01:53:47	end_request	I/O error, dev sdb, sector 0
09/06/2012 01:53:47		Buffer I/O error on device sdb, logical block 0
09/06/2012 01:53:47	ata5	EH complete
09/06/2012 01:53:47	ata5.00	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:47	ata5.01	failed to read SCR 1 (Emask=0x40)
09/06/2012 01:53:47	ata5.15	exception Emask 0x10 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:47	ata5.15	irq_stat 0x08000000, interface fatal error
09/06/2012 01:53:47	ata5.00	exception Emask 0x100 SAct 0x1 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:47	ata5.00	failed command: READ FPDMA QUEUED
09/06/2012 01:53:47	ata5.00	cmd 60/08:00:00:00:00/00:00:00:00:00/40 tag 0 ncq 4096 in
09/06/2012 01:53:47	         res 50/00	0:00:00:00/00:00:00:00:00/00 Emask 0x100 (unknown error)
09/06/2012 01:53:47	ata5.00	status: { DRDY }
09/06/2012 01:53:47	ata5.01	exception Emask 0x100 SAct 0x0 SErr 0x0 action 0x6 frozen
09/06/2012 01:53:47	ata5.15	hard resetting link
...

Comment 1 Alan 2012-06-12 09:37:00 UTC

Do you know where between 2.6.34 and 2.6.37 it broke ?

Comment 2 Richard 2012-06-12 14:38:03 UTC

Hi Alan,
Not sure where you got 2.6.34 from, anything with a version of 2.6.37 (or later) is broken, anything with a version 2.6.36 (or earlier) seems to work, but have only tried Ubuntu mainline kernel releases. The last that worked had version 2.6.36.4.
I have yet to find a changelog on the ahci driver that might tell me what was changed for the 2.6.37 release.

Comment 3 Alan 2012-06-18 10:42:13 UTC

You can actually find out exactly what broke by building kernels between 2.6.36 and 2.6.37 using "git bisect" to narrow down the cause. Before that however you might want to try 3.4 just to be sure it hasn't been fixed !

Comment 4 Richard 2012-06-18 11:19:06 UTC

Okay will keep it in mind but I've only compiled a kernel a couple of times and know how long it can take.
As stated above I have tested 3.4.0 and it is also broken.

Note You need to log in before you can comment on or make changes to this bug.