Intermittent SATA failures ("link offline, clearing class 1 to NONE")

Heya,

I've been seeing intermittent failures of one of the SATA ports on a
new machine. I've tried swapping out hard drives and cables, and even gotten a new motherboard from Dell, but it seems to persist. It manifests as:

[    2.512022] ata2.00: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    2.512037] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    2.512043] ata2.01: SATA link up <unknown> (SStatus 300 SControl 123)
[    2.512057] ata2.00: link offline, clearing class 1 to NONE
[    2.512064] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300)

ata2.00 is always the port which is reset. The only other person to see that error seems to have been Tim Blechmann, in <[email protected]>, which had similar symtoms. lspci -v for this machine's IDE controllers is:

00:1f.2 IDE interface: Intel Corporation 82801JI (ICH10 Family) 4 port SATA IDE Controller (prog-if 8f [Master SecP SecO PriP PriO])

        Subsystem: Dell Device 028c
        Flags: bus master, 66MHz, medium devsel, latency 0, IRQ 23
        I/O ports at f8e0 [size=8]
        I/O ports at f8d0 [size=4]
        I/O ports at f8e8 [size=8]
        I/O ports at f8d4 [size=4]
        I/O ports at fc00 [size=16]
        I/O ports at fc10 [size=16]
        Capabilities: [70] Power Management version 3
        Capabilities: [b0] PCIe advanced features <?>
        Kernel driver in use: ata_piix

00:1f.5 IDE interface: Intel Corporation 82801JI (ICH10 Family) 2 port SATA IDE Controller (prog-if 85 [Master SecO PriO])
Subsystem: Dell Device 028c
Flags: bus master, 66MHz, medium devsel, latency 0, IRQ 22
I/O ports at f8f0 [size=8]
I/O ports at f8d8 [size=4]
I/O ports at f8f8 [size=8]
I/O ports at f8dc [size=4]
I/O ports at fc20 [size=16]
I/O ports at fc30 [size=16]
Capabilities: [70] Power Management version 3
Capabilities: [b0] PCIe advanced features <?>
Kernel driver in use: ata_piix

dmesg logs for a good and bad boot are attached. Any suggestions on how to proceed from here?

Thanks,
- Alex

Networking -- only one letter away from not working

Can you please attach full dmesg output after such event?

tejun

My original post included both 'goodboot' and 'badboot' files, which were the dmesg output from a successful boot, and a failed boot with the event -- is that not what you are looking for? Apologies if I'm misunderstanding.

I tried 2.6.32-rc6 at the time as well -- it happened to have the fault much more often, and showed that both ata2.00 and ata2.01 could be affected. I've attached dmesg output from a successful boot, as well as dmesg output from a boot which affected sdc, and a boot which affected sdd.

- Alex

Networking -- only one letter away from not working

Hello,

Ooh... sorry, I missed them. A problem with large screen is that those attachments show up so far down in the screen that they become pretty easy to miss. :-)

Hmmm... Okay, the problem is that, ata_piix has SCR regs but doesn't have PHY event notification. libata reset protocol does the following during reset.

1. plug interrupts.
2. reset and determine device presence.
3. clear PHY events.
4. unplug interrupts.
5. check link status and retry if link status doesn't match device presence so that no hotplug event is lost.

The assumption is that a controller which reports link status will notify EH if something happens after #4. ata_piix doesn't have such thing and #5 sees that the link is offline (this sometimes happens after hardreset, links bounces between on and offline states) and marks that the device is not present. As the link was temporarily down, when it gets back up, it would notify another link event and libata will retry probing but that never happens with ata_piix so it misses the devices.

Removing PIIX_FLAG_SIDPR from ich8_sata and ich8_2port_sata entries in ata_piix.c::piix_port_info fixes the problem, right?

Thanks.

tejun

Hello,

Can you please apply the attached patch and post the good and bad boot logs?

Thanks.

tejun

index dc72690..c501e1e 100644
@@ -3731,7 +3731,7 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 	unsigned long interval = params[0];
 	unsigned long duration = params[1];
 	unsigned long last_jiffies, t;
-	u32 last, cur;
+	u32 last, cur, xxx;
 	int rc;
 
 	t = ata_deadline(jiffies, params[2]);

@@ -3740,7 +3740,9 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 
 	if ((rc = sata_scr_read(link, SCR_STATUS, &cur)))
 		return rc;
+	xxx = cur;
 	cur &= 0xf;
+	ata_link_printk(link, KERN_INFO, "XXX debounce start, SStatus=%x\n", xxx);
 
 	last = cur;
 	last_jiffies = jiffies;

@@ -3749,6 +3751,7 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 		msleep(interval);
 		if ((rc = sata_scr_read(link, SCR_STATUS, &cur)))
 			return rc;
+		xxx = cur;
 		cur &= 0xf;
 
 		/* DET stable? */

@@ -3756,8 +3759,12 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 			if (cur == 1 && time_before(jiffies, deadline))
 				continue;
 			if (time_after(jiffies,
-				       ata_deadline(last_jiffies, duration)))
+				       ata_deadline(last_jiffies, duration))) {
+				ata_link_printk(link, KERN_INFO,
+						"XXX debounce done, SStatus=%x, DET stable for %u msecs\n",
+						xxx, jiffies_to_msecs(jiffies - last_jiffies));
 				return 0;
+			}
 			continue;
 		}
 

Attached.
- Alex

Networking -- only one letter away from not working

Hello,

Can you please try this one?

Thanks.

tejun

index 9ac4e37..f50bba6 100644
@@ -173,6 +173,8 @@ static int piix_sidpr_scr_read(struct ata_link *link,
 			       unsigned int reg, u32 *val);
 static int piix_sidpr_scr_write(struct ata_link *link,
 				unsigned int reg, u32 val);
+static int piix_sidpr_hardreset(struct ata_link *link, unsigned int *class,
+				unsigned long deadline);
 #ifdef CONFIG_PM
 static int piix_pci_device_suspend(struct pci_dev *pdev, pm_message_t mesg);
 static int piix_pci_device_resume(struct pci_dev *pdev);

@@ -334,9 +336,9 @@ static struct ata_port_operations piix_sata_ops = {
 
 static struct ata_port_operations piix_sidpr_sata_ops = {
 	.inherits		= &piix_sata_ops,
-	.hardreset		= sata_std_hardreset,
 	.scr_read		= piix_sidpr_scr_read,
 	.scr_write		= piix_sidpr_scr_write,
+	.hardreset		= piix_sidpr_hardreset,
 };
 
 static const struct piix_map_db ich5_map_db = {

@@ -962,6 +964,18 @@ static int piix_sidpr_scr_write(struct ata_link *link,
 	return 0;
 }
 
+static int piix_sidpr_hardreset(struct ata_link *link, unsigned int *class,
+				unsigned long deadline)
+{
+	const unsigned long *timing = sata_deb_timing_hotplug;
+	bool online;
+	int rc;
+
+	/* do hardreset */
+	rc = sata_link_hardreset(link, timing, deadline, &online, NULL);
+	return online ? -EAGAIN : rc;
+}
+
 #ifdef CONFIG_PM
 static int piix_broken_suspend(void)
 {

index dc72690..c501e1e 100644
@@ -3731,7 +3731,7 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 	unsigned long interval = params[0];
 	unsigned long duration = params[1];
 	unsigned long last_jiffies, t;
-	u32 last, cur;
+	u32 last, cur, xxx;
 	int rc;
 
 	t = ata_deadline(jiffies, params[2]);

@@ -3740,7 +3740,9 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 
 	if ((rc = sata_scr_read(link, SCR_STATUS, &cur)))
 		return rc;
+	xxx = cur;
 	cur &= 0xf;
+	ata_link_printk(link, KERN_INFO, "XXX debounce start, SStatus=%x\n", xxx);
 
 	last = cur;
 	last_jiffies = jiffies;

@@ -3749,6 +3751,7 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 		msleep(interval);
 		if ((rc = sata_scr_read(link, SCR_STATUS, &cur)))
 			return rc;
+		xxx = cur;
 		cur &= 0xf;
 
 		/* DET stable? */

@@ -3756,8 +3759,12 @@ int sata_link_debounce(struct ata_link *link, const unsigned long *params,
 			if (cur == 1 && time_before(jiffies, deadline))
 				continue;
 			if (time_after(jiffies,
-				       ata_deadline(last_jiffies, duration)))
+				       ata_deadline(last_jiffies, duration))) {
+				ata_link_printk(link, KERN_INFO,
+						"XXX debounce done, SStatus=%x, DET stable for %u msecs\n",
+						xxx, jiffies_to_msecs(jiffies - last_jiffies));
 				return 0;
+			}
 			continue;
 		}
 

Good and bad dmesg output attached.
- Alex

Networking -- only one letter away from not working

That's interesting. The link state seems to oscillates for quite long time. Can you please try the followings?

1. Change sata_deb_timing_hotplug to sata_deb_timing_long in ata_piix.c::piidx_sidpr_hardreset() and see whether it solves the problem?

2. Switch the controller into ahci mode in BIOS if possible and see whether the problem goes away.

3. Try kernel parameter "libata.force=nohrst" and see whether it makes any difference.

Thanks.

tejun

One more thing to try.

4. You can tell libata to reset the port by running the following command.

echo "- - -" > /sys/class/scsi_host/hostN/scan

N would be 0 or 1 on your configuration. Can you please run the above command repeatedly and see whether it triggers a reset failure? If so, the above will be far more convenient way to test than rebooting repeatedly.

Thanks.

tejun

Sorry for taking so long to get back to this.

Nope -- in fact, _three_ of the drives failed to come up once, with this change.

Sadly, the BIOS doesn't have an option for this.

I wasn't able to replicate the problem with this kernel parameter. dmesg for such a boot is attached.

I wasn't able to get this to fail, sadly. If the boot _had_ failed, however, this technique did bring the drive online.
- Alex

Networking -- only one letter away from not working

Hello,

Wow, that's unexpected. Can you please post log of this with the debugging patch applied?

Ah... that's sad.

Alright, thanks for verifying.

Hmmm... interesting. So, the boot time probing is somehow different from probing initiated by manual scan (they both use hardreset). Can you please post log of manual scans with debug patch applied?

Thanks.

tejun

I've only been able to replicate this once, and I didn't manage to save its dmesg, sadly. I'll see if I can get it to crop up again, though.

The output of a manual scan is:

[  255.236938] ata1.00: hard resetting link
[  255.465422] ata1.00: XXX debounce start, SStatus=123
[  257.551239] ata1.00: XXX debounce done, SStatus=123, DET stable for 2090 msecs
[  257.551246] ata1.01: hard resetting link
[  257.780776] ata1.01: XXX debounce start, SStatus=123
[  259.866589] ata1.01: XXX debounce done, SStatus=123, DET stable for 2090 msecs
[  260.026328] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[  260.026342] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[  260.087511] ata1.00: configured for UDMA/133
[  260.127736] ata1.01: configured for UDMA/133
[  260.127740] ata1: EH complete

- Alex

Networking -- only one letter away from not working

Hello,

Any failing trace witfffh long debounce timing would be helpful because it really shouldn't be failing with long debounce timing.

Thanks.

tejun