Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Jeff Garzik]

akpm@osdl.org wrote:
> The patch titled
> 
>      VIA PATA controller xfer fixes
> 
> has been added to the -mm tree.  Its filename is
> 
>      via-pata-controller-xfer-fixes.patch
> 
> See http://www.zip.com.au/~akpm/linux/patches/stuff/added-to-mm.txt to find
> out what to do about this
> 
> ------------------------------------------------------
> Subject: VIA PATA controller xfer fixes
> From: matthieu castet <castet.matthieu@free.fr>
> 
> 
> On via controller(vt8235) and pata via, some ATAPI devices (CDR-6S48) fail
> in the xfer mode initialisation.  This make the boot slow and the drive
> unsuable.
> 
> It seems the interrupt for xfer mode is done before the drive is ready, so
> the current libata code skip the interrupt.  But no new interrupt is done
> by the controller, so the xfer mode fails.
> 
> A quirk is to wait for 10 us (by step of 1 us) and see if the device
> becomes ready in the case of SETFEATURES_XFER feature.  The problem seems
> pata_via only, so the quirk is put in the pata_via interrupt handler as
> Tejun Heo request.
> 
> It won't affect working devices, as we don't wait if the device is already
> ready.  It will adds an extra ata_altstatus in order to avoid to duplicate
> ata_host_intr, but only in the case of SETFEATURES_XFER (with should happen
> only few times).
> 
> Sorry for the lack of changelog in my previous mail, I tought the old
> changelog + move it in pata via interrupt was enought.  And sorry again, I
> sent you a bad patch (I forgot a quitl refresh).

Data point #1:

Here I quote from drivers/ide generic code ide_config_drive_speed() in 
ide-iops.c:

    /*
     * Allow status to settle, then read it again.
     * A few rare drives vastly violate the 400ns spec here,
     * so we'll wait up to 10usec for a "good" status
     * rather than expensively fail things immediately.
     * This fix courtesy of Matthew Faupel & Niccolo Rigacci.
     */
    for (i = 0; i < 10; i++) {
            udelay(1);
            if (OK_STAT((stat = hwif->INB(IDE_STATUS_REG)),
			  DRIVE_READY, BUSY_STAT|DRQ_STAT|ERR_STAT)) {
                    error = 0;
                    break;
            }
    }

And there is similar logic in ide_wait_stat().  wait_drive_not_busy() in 
ide-taskfile.c waits for up to 1 ms.


Data point #2:

libata was originally based on the "highly correct" (or one version 
thereof) programming sequences found in Hale Landis's free ATADRVR 
(http://www.ata-atapi.com/).  Hale's ATADRVR, which was MS-DOS based and 
not threaded or asynchronous at all, did the following after every 
command execution (sent taskfile to hardware):

	if (device is ATAPI)
		sleep(150 ms)


Overall, I've no clue what to do on older PATA hardware, so my 
"insightful" suggestions are largely (a) follow drivers/ide code and/or 
(b) listen to any old fogies with deep historical knowledge.

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Jeff Garzik]

Data point #3 (or #0...):

This appears to be a _device_ that sends its interrupt early.

If that is the case, the device may appear on any controller, not just 
VIA, and we would have to handle it globally via a device special-case 
in libata-core.

	Jeff

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[matthieu castet]

Jeff Garzik wrote:
> Data point #3 (or #0...):
> 
> This appears to be a _device_ that sends its interrupt early.
> 
> If that is the case, the device may appear on any controller, not just 
> VIA, and we would have to handle it globally via a device special-case 
> in libata-core.
> 

For the record, the cdrom writer that need this quirk on pata via, works 
on pata sil680.
But 3 microsecond is very short, and the problem could be hidden by the 
controller, or other stuffs.

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Albert Lee]

matthieu castet wrote:
> Jeff Garzik wrote:
> 
>> Data point #3 (or #0...):
>>
>> This appears to be a _device_ that sends its interrupt early.

Hi,

I've tested the 4KUS CDR-6S48 drive + Promise pdc20275 controller
with current libata upstream (to be 2.6.18. I guess current upstream doesn't
have the via-pata-controller-xfer-fixes.patch). However, cannot reproduce
the early interrupt problem on my machine.

>>
>> If that is the case, the device may appear on any controller, not just
>> VIA, and we would have to handle it globally via a device special-case
>> in libata-core.
>>
> 
> For the record, the cdrom writer that need this quirk on pata via, works
> on pata sil680.
> But 3 microsecond is very short, and the problem could be hidden by the
> controller, or other stuffs.
> 
> 

If it is the problem of the specific ATAPI device, all controllers
should be affected, not only VIA. So, strange not seeing the problem on
Promise.

Could you please test the current libata-upstream tree and
turn on ATA_DEBUG and ATA_VERBOSE_DEBUG in include/linux/libata.h.

If possible, could you also submit the libata log related to the
early/lost irq.

(Heard about the ATAPI early interrupt problem, but never had chance to see
how libata behaves with such device. Really curious about this problem.)

Thanks,

Albert
---
boot dmesg of the CDR-6S48 on my box.
xfer mode set to UDMA/33 without problem.

pata_pdc2027x 0000:02:05.0: version 0.74-ac3
ACPI: PCI Interrupt 0000:02:05.0[A] -> Link [LNK1] -> GSI 10 (level, low) -> IRQ 10
pata_pdc2027x 0000:02:05.0: PLL input clock 16740 kHz
ata3: PATA max UDMA/133 cmd 0xE09E17C0 ctl 0xE09E1FDA bmdma 0xE09E1000 irq 10
ata4: PATA max UDMA/133 cmd 0xE09E15C0 ctl 0xE09E1DDA bmdma 0xE09E1008 irq 10
scsi2 : pata_pdc2027x
ata3.00: configured for UDMA/33
ata3.01: configured for UDMA/33
scsi3 : pata_pdc2027x
ata4.00: configured for UDMA/33
  Vendor: LITE-ON   Model: CD-RW SOHR-5238S  Rev: 4S07
  Type:   CD-ROM                             ANSI SCSI revision: 05
  Vendor: HL-DT-ST  Model: DVDRAM GSA-4163B  Rev: A101
  Type:   CD-ROM                             ANSI SCSI revision: 05
  Vendor: CD-RW     Model: CDR-6S48          Rev: 2SG1
  Type:   CD-ROM                             ANSI SCSI revision: 05
sr0: scsi3-mmc drive: 93x/52x writer cd/rw xa/form2 cdda tray
Uniform CD-ROM driver Revision: 3.20
sr 2:0:0:0: Attached scsi CD-ROM sr0
sr1: scsi3-mmc drive: 40x/40x writer dvd-ram cd/rw xa/form2 cdda tray
sr 2:0:1:0: Attached scsi CD-ROM sr1
sr2: scsi3-mmc drive: 48x/48x writer cd/rw xa/form2 cdda tray
sr 3:0:0:0: Attached scsi CD-ROM sr2

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[castet.matthieu]

Hi,

Selon Albert Lee <albertcc@tw.ibm.com>:

>
> Could you please test the current libata-upstream tree and
> turn on ATA_DEBUG and ATA_VERBOSE_DEBUG in include/linux/libata.h.
>
Is there a easy way to get libata-upstream tree ?
Do I need to install git for that or there are some snapshots somewhere ?


> If possible, could you also submit the libata log related to the
> early/lost irq.
Where are this infos ?

IRRC, libata counts lost irq, but display only a message each 1000 losts irq.

Matthieu

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Albert Lee]

castet.matthieu@free.fr wrote:
> 
> 
>>Could you please test the current libata-upstream tree and
>>turn on ATA_DEBUG and ATA_VERBOSE_DEBUG in include/linux/libata.h.
>>
> 
> Is there a easy way to get libata-upstream tree ?
> Do I need to install git for that or there are some snapshots somewhere ?
> 
> 

Hi Matthieu,

Tejun has a patch against 2.6.17:
http://home-tj.org/files/libata-tj-stable/libata-tj-2.6.17-20060625-1.tar.bz2

> 
>>If possible, could you also submit the libata log related to the
>>early/lost irq.
> 
> Where are this infos ?
> 

Please send the info related to set xfer mode and timeout
(any other timeouts seems caused by lost irq are also great.)

> IRRC, libata counts lost irq, but display only a message each 1000 losts irq.
> 

Yes, so we need ATA_DEBUG and ATA_VERBOSE_DEBUG being turned on to
see the following debug printk of ata_host_intr().

VPRINTK("ata%u: protocol %d task_state %d\n",
		ap->id, qc->tf.protocol, ap->hsm_task_state);

After recompiling the kernel, this will print something like
"ata_host_intr: ata3: protocol 6 task_state 5"
in the dmesg each time ata_host_intr() is entered.

If the irq is ignored due to device busy (early irq), then
ata_hsm_move() will be skipped and later we might see ata_scsi_timed_out() triggered.

Thanks,

Albert
---
A sample libata timeout transacation looks like:

Jun 27 18:10:55 xlinux19 kernel: ata_scsi_dump_cdb: CDB (3:0,0,0) 1b 00 00 00 02 00 00 00 00
Jun 27 18:10:55 xlinux19 kernel: ata_scsi_translate: ENTER
Jun 27 18:10:55 xlinux19 kernel: ata3: ata_dev_select: ENTER, ata3: device 0, wait 1
Jun 27 18:10:55 xlinux19 kernel: ata_tf_load_pio: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20
Jun 27 18:10:55 xlinux19 kernel: ata_tf_load_pio: device 0xA0
Jun 27 18:10:55 xlinux19 kernel: ata_exec_command_pio: ata3: cmd 0xA0
Jun 27 18:10:56 xlinux19 kernel: ata_scsi_translate: EXIT
Jun 27 18:10:56 xlinux19 kernel: ata_host_intr: ata3: protocol 6 task_state 5
Jun 27 18:10:56 xlinux19 kernel: ata_hsm_move: ata3: protocol 6 task_state 5 (dev_stat 0x58)
Jun 27 18:10:56 xlinux19 kernel: atapi_send_cdb: send cdb
                            (time out here.)
Jun 27 18:10:56 xlinux19 kernel: ata_scsi_timed_out: ENTER
Jun 27 18:10:56 xlinux19 kernel: ata_scsi_timed_out: EXIT, ret=0
Jun 27 18:10:56 xlinux19 kernel: ata_scsi_error: ENTER
Jun 27 18:10:56 xlinux19 kernel: ata_port_flush_task: ENTER
Jun 27 18:10:56 xlinux19 kernel: ata_port_flush_task: flush #1
Jun 27 18:10:56 xlinux19 kernel: __ata_port_freeze: ata3 port frozen
Jun 27 18:10:56 xlinux19 kernel: ata_eh_autopsy: ENTER
Jun 27 18:10:56 xlinux19 kernel: ata_eh_autopsy: EXIT
Jun 27 18:10:56 xlinux19 kernel: ata3.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Jun 27 18:10:56 xlinux19 kernel: ata3.00: tag 0 cmd 0xa0 Emask 0x4 stat 0x40 err 0x0 (timeout)
Jun 27 18:10:56 xlinux19 kernel: ata_eh_recover: ENTER

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[matthieu castet]

Hi Albert,

Albert Lee wrote:
> castet.matthieu@free.fr wrote:
> 
>>
>>>Could you please test the current libata-upstream tree and
>>>turn on ATA_DEBUG and ATA_VERBOSE_DEBUG in include/linux/libata.h.
>>>
>>
>>Is there a easy way to get libata-upstream tree ?
>>Do I need to install git for that or there are some snapshots somewhere ?
>>
>>
> 
> 
> Hi Matthieu,
> 
> Tejun has a patch against 2.6.17:
> http://home-tj.org/files/libata-tj-stable/libata-tj-2.6.17-20060625-1.tar.bz2
> 
I don't know if I did someting wrong, but it didn't apply cleanly.
So I enable the trace on lastest -mm kernel and I disable the via quirk.

But the printk in the interrupt handler takes some times and hides the 
altstatus delay.

I will try to send you a trace, where I move the printk at the end of 
the interrupt handler.


Matthieu

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[matthieu castet]

[-- Attachment #1: Type: text/plain, Size: 994 bytes --]

matthieu castet wrote:
> Hi Albert,
> 
> Albert Lee wrote:
> 
>> castet.matthieu@free.fr wrote:
>>
>>>
>>>> Could you please test the current libata-upstream tree and
>>>> turn on ATA_DEBUG and ATA_VERBOSE_DEBUG in include/linux/libata.h.
>>>>
>>>
>>> Is there a easy way to get libata-upstream tree ?
>>> Do I need to install git for that or there are some snapshots 
>>> somewhere ?
>>>
>>>
>>
>>
>> Hi Matthieu,
>>
>> Tejun has a patch against 2.6.17:
>> http://home-tj.org/files/libata-tj-stable/libata-tj-2.6.17-20060625-1.tar.bz2 
>>
>>
> I don't know if I did someting wrong, but it didn't apply cleanly.
> So I enable the trace on lastest -mm kernel and I disable the via quirk.
> 
> But the printk in the interrupt handler takes some times and hides the 
> altstatus delay.
> 
> I will try to send you a trace, where I move the printk at the end of 
> the interrupt handler.
> 
> 
After apllying the following patch to -mm, I got 
http://castet.matthieu.free.fr/tmp/ata_log

Matthieu


[-- Attachment #2: test_trace --]
[-- Type: text/plain, Size: 2185 bytes --]

Index: linux-2.6.16/drivers/scsi/libata-core.c
===================================================================
--- linux-2.6.16.orig/drivers/scsi/libata-core.c	2006-07-02 10:32:33.000000000 +0200
+++ linux-2.6.16/drivers/scsi/libata-core.c	2006-07-02 10:38:03.000000000 +0200
@@ -4722,9 +4722,6 @@
 {
 	u8 status, host_stat = 0;
 
-	VPRINTK("ata%u: protocol %d task_state %d\n",
-		ap->id, qc->tf.protocol, ap->hsm_task_state);
-
 	/* Check whether we are expecting interrupt in this state */
 	switch (ap->hsm_task_state) {
 	case HSM_ST_FIRST:
@@ -4780,6 +4777,9 @@
 	ap->ops->irq_clear(ap);
 
 	ata_hsm_move(ap, qc, status, 0);
+	VPRINTK("ata%u: protocol %d task_state %d\n",
+		ap->id, qc->tf.protocol, ap->hsm_task_state);
+
 	return 1;	/* irq handled */
 
 idle_irq:
@@ -4792,6 +4792,9 @@
 		return 1;
 	}
 #endif
+	VPRINTK("ata%u: protocol %d task_state %d\n",
+		ap->id, qc->tf.protocol, ap->hsm_task_state);
+
 	return 0;	/* irq not handled */
 }
 
Index: linux-2.6.16/drivers/scsi/pata_via.c
===================================================================
--- linux-2.6.16.orig/drivers/scsi/pata_via.c	2006-07-01 19:38:41.000000000 +0200
+++ linux-2.6.16/drivers/scsi/pata_via.c	2006-07-01 19:38:54.000000000 +0200
@@ -324,7 +324,7 @@
 				continue;
 			if (!(qc->flags & ATA_QCFLAG_ACTIVE))
 				continue;
-			if (qc->tf.command == ATA_CMD_SET_FEATURES &&
+			if (0 && qc->tf.command == ATA_CMD_SET_FEATURES &&
 					qc->tf.feature == SETFEATURES_XFER) {
 				/*
 				 * With some ATAPI devices (CDR-6S48, ...), the
Index: linux-2.6.16/include/linux/libata.h
===================================================================
--- linux-2.6.16.orig/include/linux/libata.h	2006-07-01 19:37:51.000000000 +0200
+++ linux-2.6.16/include/linux/libata.h	2006-07-01 19:38:24.000000000 +0200
@@ -43,6 +43,8 @@
 #undef ATA_DEBUG		/* debugging output */
 #undef ATA_VERBOSE_DEBUG	/* yet more debugging output */
 #undef ATA_IRQ_TRAP		/* define to ack screaming irqs */
+#define ATA_DEBUG
+#define ATA_VERBOSE_DEBUG
 #undef ATA_NDEBUG		/* define to disable quick runtime checks */
 #define ATA_ENABLE_PATA		/* define to enable PATA support in some
 				 * low-level drivers */

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Albert Lee]

matthieu castet wrote:
> matthieu castet wrote:
> 
>> Hi Albert,
>>
>> Albert Lee wrote:
>>
>>> castet.matthieu@free.fr wrote:
>>>
>>>>
>>>>> Could you please test the current libata-upstream tree and
>>>>> turn on ATA_DEBUG and ATA_VERBOSE_DEBUG in include/linux/libata.h.
>>>>>
>>>>
>>>> Is there a easy way to get libata-upstream tree ?
>>>> Do I need to install git for that or there are some snapshots
>>>> somewhere ?
>>>>
>>>>
>>>
>>>
>>> Hi Matthieu,
>>>
>>> Tejun has a patch against 2.6.17:
>>> http://home-tj.org/files/libata-tj-stable/libata-tj-2.6.17-20060625-1.tar.bz2
>>>
>>>
>> I don't know if I did someting wrong, but it didn't apply cleanly.
>> So I enable the trace on lastest -mm kernel and I disable the via quirk.
>>
>> But the printk in the interrupt handler takes some times and hides the
>> altstatus delay.
>>
>> I will try to send you a trace, where I move the printk at the end of
>> the interrupt handler.
>>
>>
> After apllying the following patch to -mm, I got
> http://castet.matthieu.free.fr/tmp/ata_log
> 
> Matthieu

Hi Matthieu,

Thanks for the log. But could you please keep the 
VPRINTK() in the entrance of ata_host_intr() and add some message to
distinguish the three VPRINTK()s?

(This will make the log easier to read. Detail below.)


> 
> 
> ------------------------------------------------------------------------
> 
> Index: linux-2.6.16/drivers/scsi/libata-core.c
> ===================================================================
> --- linux-2.6.16.orig/drivers/scsi/libata-core.c	2006-07-02 10:32:33.000000000 +0200
> +++ linux-2.6.16/drivers/scsi/libata-core.c	2006-07-02 10:38:03.000000000 +0200
> @@ -4722,9 +4722,6 @@
>  {
>  	u8 status, host_stat = 0;
>  
> -	VPRINTK("ata%u: protocol %d task_state %d\n",
> -		ap->id, qc->tf.protocol, ap->hsm_task_state);
> -

Please keep this VPRINTK() and add "ENTER" to it. Something like
"ata%u: ENTER protocol...".

>  	/* Check whether we are expecting interrupt in this state */
>  	switch (ap->hsm_task_state) {
>  	case HSM_ST_FIRST:
> @@ -4780,6 +4777,9 @@
>  	ap->ops->irq_clear(ap);
>  
>  	ata_hsm_move(ap, qc, status, 0);
> +	VPRINTK("ata%u: protocol %d task_state %d\n",
> +		ap->id, qc->tf.protocol, ap->hsm_task_state);
> +
>  	return 1;	/* irq handled */
>  

Please add additional message "HANDLED" to this VPRINTK(). Something like
"ata%u: HANDLED protocol...".

>  idle_irq:
> @@ -4792,6 +4792,9 @@
>  		return 1;
>  	}
>  #endif
> +	VPRINTK("ata%u: protocol %d task_state %d\n",
> +		ap->id, qc->tf.protocol, ap->hsm_task_state);
> +
>  	return 0;	/* irq not handled */
>  }

Please add additional message "IGNORED" to this VPRINTK(). Something like
"ata%u: IGNORED protocol ...". 



Thanks,

Albert

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[matthieu castet]

Hi,

Albert Lee wrote:
> Hi Matthieu,
> 
> Thanks for the log. But could you please keep the 
> VPRINTK() in the entrance of ata_host_intr()
If I do that, everything works correctly : the printk should take more 
than 3 us, and the altsatus is not busy when we read it.
Here is the log without moving the printk : 
http://castet.matthieu.free.fr/tmp/ata_log.orig

The only thing I could do is to move the printk between altstatus and 
status check and add one in idle_irq.

Will it be usefull for you ?


Matthieu.

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Albert Lee]

matthieu castet wrote:
> Hi,
> 
> Albert Lee wrote:
> 
>> Hi Matthieu,
>>
>> Thanks for the log. But could you please keep the VPRINTK() in the
>> entrance of ata_host_intr()
> 
> If I do that, everything works correctly : the printk should take more
> than 3 us, and the altsatus is not busy when we read it.
> Here is the log without moving the printk :
> http://castet.matthieu.free.fr/tmp/ata_log.orig

Hmm, the Uncertainty principle also applies to kernel debugging. :)

> 
> The only thing I could do is to move the printk between altstatus and
> status check and add one in idle_irq.
> 
> Will it be usefull for you ?
> 
> 
> Matthieu.
> 
> 

>From your previous log, the timeout transacation is clearly logged
and it does look like early irq. Can compare/see both timeout and normal
behaviors of libata from both logs. So, the logs are good enough.

Thanks and appreciates for the logs, :)

Albert

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Alan Cox]

Ar Gwe, 2006-06-30 am 15:09 +0800, ysgrifennodd Albert Lee:
> If it is the problem of the specific ATAPI device, all controllers
> should be affected, not only VIA. So, strange not seeing the problem on
> Promise.

That may be because of the way the chips handle buffering of interrupt
delivery and readahead/writebehind. I have two traces on the ALi
chipsets that look like the delayed response problem.

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Albert Lee]

Alan Cox wrote:
> Ar Gwe, 2006-06-30 am 15:09 +0800, ysgrifennodd Albert Lee:
> 
>>If it is the problem of the specific ATAPI device, all controllers
>>should be affected, not only VIA. So, strange not seeing the problem on
>>Promise.
> 
> 
> That may be because of the way the chips handle buffering of interrupt
> delivery and readahead/writebehind. I have two traces on the ALi
> chipsets that look like the delayed response problem.
> 
> 
> 

Understood. Thanks for the explanation. Checked Matthieu's log, and yes
it does look like early interrupt. Matthieu's Sil680 has no such problem.
Also the problem is not reproducible with the same CD-RW drive on my
Promise 20275 chip. So, the explanation makes sense.

BTW, even for VIA, the early irq problem occur on 'set features - xfer mode'
but IDENTIFY works ok. Just curious, does the ALi chip have the same
symptom? i.e. Besides the 'set features' command, are there any other
commands affected by the early irq problem? Say, any other PIO non-data
commands?

--
albert

(The relevant part from Matthieu's log.)

ata_dev_set_xfermode: set features - xfer mode
ata4: ata_dev_select: ENTER, ata4: device 1, wait 1
ata_tf_load_pio: feat 0x3 nsect 0x42 lba 0x0 0x0 0x0
ata_tf_load_pio: device 0xB0
ata_exec_command_pio: ata4: cmd 0xEF
ata_host_intr: ata4: protocol 1 task_state 3  <=== early irq
ata_port_flush_task: ENTER
ata_port_flush_task: flush #1
ata4: ata_port_flush_task: flush #2
ata4: ata_port_flush_task: EXIT
__ata_port_freeze: ata4 port frozen
ata4.01: qc timeout (cmd 0xef)
ata_dev_set_xfermode: EXIT, err_mask=4
ata4.01: failed to set xfermode (err_mask=0x4)
ata4.01: limiting speed to UDMA/25
ata4: failed to recover some devices, retrying in 5 secs
__ata_port_freeze: ata4 port frozen

Re: + via-pata-controller-xfer-fixes.patch added to -mm tree

[Alan Cox]

SETFEATURES_XFER stuff is magic anyway because some controllers snoop.
Also of course like the old IDE we send some rather iffy PIO requests
and that might have something to do with the problem of course.

I've got two reports that look similar and are from ALi controllers so
trying the 10uS version might be worth doing, at least for PATA