Re: sata_nv ADMA controller lockup investigation

Previous thread: [PATCH 2/2] autofs4 - check for directory re-create in lookup by Ian Kent on Wednesday, February 14, 2007 - 9:23 pm. (1 message)

Next thread: GPL vs non-GPL device drivers by v j on Wednesday, February 14, 2007 - 10:16 pm. (122 messages)
From: Robert Hancock
Date: Wednesday, February 14, 2007 - 9:30 pm

While testing out some libata FUA changes I was working on, I was 
inadvertently able to reproduce the kind of NCQ command timeouts in 
sata_nv that a few people have reported. I since verified that the FUA 
stuff had nothing to do with it as it still happens even with FUA 
disabled. However I'm somewhat at a loss as to how to further debug 
this, so I'm posting my findings in the hope that somebody has some more 
ideas (or anyone at NVIDIA decides to come forth with a tip or two).

The conditions in which I can reproduce this are with:

ext3 filesystem mounted with -o barrier=1
Two instances of a program which truncates a file, then writes single bytes
to it, fsyncing after each one.
Simultaneously, repeatedly writing 100MB from /dev/zero to a file
using dd.

A command timeout usually happens within a few minutes. With my working copy
loaded up with a ton of extra debugging, the exception report for one of
these looks like this. My comments are indented.

ata4: EH in ADMA mode, notifier 0x0 notifier_error 0x0 gen_ctl 0x1501000 status 0x400 cpb count 0x0 next cpb idx 0x0
	This is just dumping all of the ADMA registers when the timeout
	happened.
ata4: last intr at 1171511467:501179, status 0x1540
	This shows the time of the last interrupt in seconds:microseconds and the
	ADMA status register contents at that time.
ata4: cmd 61/08:00:40:36:75/00:00:0c:00:00/40 tag 0 at 1171511467:360525 done 1171511467:393064, stat before 0x400 after 0x400
ata4: cmd 61/40:00:80:a1:64/00:00:0a:00:00/40 tag 0 at 1171511467:393928 done 1171511467:394345, stat before 0x500 after 0x400
ata4: cmd ea/00:00:00:00:00/00:00:00:00:00/a0 tag 0 at 1171511467:394400 done 1171511467:425548, stat before 0x500 after 0x400
ata4: cmd 61/08:00:c0:a1:64/00:00:0a:00:00/40 tag 0 at 1171511467:425556 done 1171511467:425694, stat before 0x500 after 0x400
ata4: cmd ea/00:00:00:00:00/00:00:00:00:00/a0 tag 0 at 1171511467:425699 done 1171511467:433896, stat before 0x500 after 0x400
ata4: cmd ...
From: Jeff Garzik
Date: Thursday, February 15, 2007 - 3:46 am

If you take cache flush out of the equation, what happens when NCQ is 
enabled with a queue depth of 1 (to reproduce tag-0-used-repeatedly 
condition)?

	Jeff


-

From: Robert Hancock
Date: Thursday, February 15, 2007 - 9:52 pm

I was able to reproduce it in my same test case with NCQ depth set to 1.
Of course, there were still some cache flushes going on there, so I'm not
certain that test really told us anything new. I'm rather doutbful that it's
related to reusing the same tag now, though, based on the tests I've been
doing. It may be something to do with switching between NCQ and non-NCQ
commands, maybe the controller isn't able to handle doing that too rapidly.
This patch seems to fix the problem - or at least it hasn't failed the tests that
I've run so far. It's not really ideal though, so I'd like to do some more
investigation/testing before proclaiming it as a fix. Experimentally, it
appears that 10 microseconds is not enough delay, but 20 seems to work better.

Hints from the peanut gallery remain welcome.

--- linux-2.6.20-git6edit/drivers/ata/sata_nv.c.before_hacking	2007-02-15 18:19:13.000000000 -0600
+++ linux-2.6.20-git6edit/drivers/ata/sata_nv.c	2007-02-15 22:36:02.000000000 -0600
@@ -219,6 +219,7 @@
 	void __iomem *		gen_block;
 	void __iomem *		notifier_clear_block;
 	u8			flags;
+	int			last_issue_ncq;
 };
 
 struct nv_host_priv {
@@ -1260,6 +1261,7 @@
 {
 	struct nv_adma_port_priv *pp = qc->ap->private_data;
 	void __iomem *mmio = pp->ctl_block;
+	int curr_ncq = (qc->tf.protocol == ATA_PROT_NCQ);
 
 	VPRINTK("ENTER\n");
 
@@ -1274,6 +1276,14 @@
 	/* write append register, command tag in lower 8 bits
 	   and (number of cpbs to append -1) in top 8 bits */
 	wmb();
+
+	if(curr_ncq != pp->last_issue_ncq) {
+	   	/* Seems to need some delay before switching between NCQ and non-NCQ
+		   commands, else we get command timeouts and such. */
+		udelay(20);
+		pp->last_issue_ncq = curr_ncq;
+	}
+
 	writew(qc->tag, mmio + NV_ADMA_APPEND);
 
 	DPRINTK("Issued tag %u\n",qc->tag);
-

From: Neil Schemenauer
Date: Tuesday, March 20, 2007 - 3:01 pm

Not sure if this helps.  I'm getting this reset with 2.6.21-rc4.
After the reset the controller seems to work again.

sata_nv 0000:00:07.0: version 3.3
ACPI: PCI Interrupt Link [APSI] enabled at IRQ 22
ACPI: PCI Interrupt 0000:00:07.0[A] -> Link [APSI] -> GSI 22 (level, low) -> IRQ 22
sata_nv 0000:00:07.0: Using ADMA mode
PCI: Setting latency timer of device 0000:00:07.0 to 64
ata1: SATA max UDMA/133 cmd 0xffffc2000001e480 ctl 0xffffc2000001e4a0 bmdma 0x000000000001cc00 irq 22
ata2: SATA max UDMA/133 cmd 0xffffc2000001e580 ctl 0xffffc2000001e5a0 bmdma 0x000000000001cc08 irq 22
scsi0 : sata_nv
ata1: SATA link down (SStatus 0 SControl 300)
scsi1 : sata_nv
ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata2.00: ATA-7: Maxtor 6V300F0, VA111630, max UDMA/133
ata2.00: 586114704 sectors, multi 16: LBA48 NCQ (depth 31/32)
ata2.00: configured for UDMA/133
scsi 1:0:0:0: Direct-Access     ATA      Maxtor 6V300F0   VA11 PQ: 0 ANSI: 5
ata2: bounce limit 0xFFFFFFFFFFFFFFFF, segment boundary 0xFFFFFFFF, hw segs 61
SCSI device sda: 586114704 512-byte hdwr sectors (300091 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
SCSI device sda: 586114704 512-byte hdwr sectors (300091 MB)
sda: Write Protect is off
sda: Mode Sense: 00 3a 00 00
SCSI device sda: write cache: enabled, read cache: enabled, doesn't support DPO or FUA
 sda: sda1 sda2 sda3 sda4 < sda5 sda6 sda7 sda8 sda9 >
sd 1:0:0:0: Attached scsi disk sda
sd 1:0:0:0: Attached scsi generic sg0 type 0
ACPI: PCI Interrupt Link [APSJ] enabled at IRQ 21
ACPI: PCI Interrupt 0000:00:08.0[A] -> Link [APSJ] -> GSI 21 (level, low) -> IRQ 21
sata_nv 0000:00:08.0: Using ADMA mode
PCI: Setting latency timer of device 0000:00:08.0 to 64
ata3: SATA max UDMA/133 cmd 0xffffc20000020480 ctl 0xffffc200000204a0 bmdma 0x000000000001b800 irq 21
ata4: SATA max UDMA/133 cmd 0xffffc20000020580 ctl 0xffffc200000205a0 bmdma 0x000000000001b808 irq 21
scsi2 : ...
From: Robert Hancock
Date: Tuesday, March 20, 2007 - 4:24 pm

That one looks like a drive-side issue. CPB resp_flags 2 indicates the 
drive accepted the command and the controller is still waiting for a 
response.

Could be that this is another drive that needs to be added to the NCQ 
blacklist, some similar Maxtor models seem to have issues..

-- 
Robert Hancock      Saskatoon, SK, Canada
To email, remove "nospam" from hancockr@nospamshaw.ca
Home Page: http://www.roberthancock.com/

-

Previous thread: [PATCH 2/2] autofs4 - check for directory re-create in lookup by Ian Kent on Wednesday, February 14, 2007 - 9:23 pm. (1 message)

Next thread: GPL vs non-GPL device drivers by v j on Wednesday, February 14, 2007 - 10:16 pm. (122 messages)