ata, pcmcia: problem with irq and ata_dev_read_id()

ata, pcmcia: problem with irq and ata_dev_read_id()

[Heiko Schocher]

Hello Jeff,

I have ported Linux 2.6.34 for a 8xx based board using the m8xx_pcmcia.c
driver in drivers/pcmcia/ with two slots and CONFIG_ATA, CONFIG_PATA_PCMCIA
defined.

All works fine, except with one CF card type, I get:

rtc-pcf8563 0-0051: setting system clock to 2010-05-31 05:18:41 UTC (1275283121)
pcmcia_socket pcmcia_socket0: pccard: PCMCIA card inserted into slot 0
pcmcia 0.0: pcmcia: registering new device pcmcia0.0
scsi0 : pata_pcmcia
ata1: PATA max PIO4 cmd 0x0 ctl 0xe irq 25
ata1.00: CFA: TOSHIBA THNCF512MDG, 3.00, max MWDMA2
ata1.00: 1000944 sectors, multi 1: LBA
ata1.00: configured for PIO4
ata1.00: configured for PIO4
ata1: EH complete
isa bounce pool size: 16 pages
scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA THNCF512 3.00 PQ: 0 ANSI: 5
sd 0:0:0:0: [sda] 1000944 512-byte logical blocks: (512 MB/488 MiB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sda: sda1 sda2 sda3 sda4
pcmcia_socket pcmcia_socket1: pccard: PCMCIA card inserted into slot 1
pcmcia 1.0: pcmcia: registering new device pcmcia1.0
sd 0:0:0:0: [sda] Attached SCSI removable disk
scsi1 : pata_pcmcia
ata2: PATA max PIO4 cmd 0x10 ctl 0x1e irq 26
irq 26: nobody cared (try booting with the "irqpoll" option)
Call Trace:
[c0327c70] [c0006ac0] show_stack+0x44/0x16c (unreliable)
[c0327cb0] [c004b7b4] __report_bad_irq+0x34/0xb8
[c0327cd0] [c004b9f0] note_interrupt+0x1b8/0x224
[c0327d00] [c004c9a8] handle_level_irq+0xa8/0x124
[c0327d10] [c0004de8] do_IRQ+0x98/0xb4
[c0327d30] [c000e788] ret_from_except+0x0/0x14
[c0327df0] [00009032] 0x9032
[c0327e30] [c0004b38] do_softirq+0x58/0x5c
[c0327e40] [c0023d90] irq_exit+0x98/0x9c
[c0327e50] [c0004dec] do_IRQ+0x9c/0xb4
[c0327e70] [c000e788] ret_from_except+0x0/0x14
[c0327f30] [c00440ac] tick_nohz_stop_sched_tick+0x404/0x4d0
[c0327f90] [c0007ac8] cpu_idle+0x50/0xe8
[c0327fb0] [c0002930] rest_init+0x5c/0x6c
[c0327fc0] [c02f088c] start_kernel+0x240/0x2c4
[c0327ff0] [c000222c] start_here+0x4c/0xb0
handlers:
[<c0193bc4>] (ata_sff_interrupt+0x0/0x208)
Disabling IRQ #26
IP-Config: Complete:
     device=eth0, addr=192.168.120.4, mask=255.255.0.0, gw=192.168.1.254,
     host=kup4k, domain=, nis-domain=(none),
     bootserver=192.168.1.1, rootserver=192.168.1.1, rootpath=
ata2.00: CFA: TOSHIBA THNCF032MBA, 2.00, max PIO2
ata2.00: 63488 sectors, multi 0: LBA
ata2.00: configured for PIO2
ata2.00: configured for PIO2
ata2: EH complete
scsi 1:0:0:0: Direct-Access     ATA      TOSHIBA THNCF032 2.00 PQ: 0 ANSI: 5
sd 1:0:0:0: [sdb] 63488 512-byte logical blocks: (32.5 MB/31.0 MiB)
sd 1:0:0:0: [sdb] Write Protect is off
sd 1:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sdb: sdb1
sd 1:0:0:0: [sdb] Attached SCSI removable disk
Looking up port of RPC 100003/2 on 192.168.1.1
[...]

-bash-3.2# cat /proc/interrupts
           CPU0
 17:          0   CPM PIC          Level        error
 18:          0   MPC8XX SIU       Level        tbint
 19:         59   CPM PIC          Level        cpm_uart
 21:          4   CPM PIC          Level        mpc8xxx_spi
 22:          0   MPC8XX SIU       Edge         ads7846
 23:      19950   MPC8XX SIU       Level        fs_enet-mac
 24:          0   MPC8XX SIU       Level        m8xx-pcmcia
 25:          9   MPC8XX SIU       Level        pata_pcmcia
 26:     100000   MPC8XX SIU       Level        pata_pcmcia
 27:         55   CPM PIC          Level        cpm_i2c
LOC:      15403   Local timer interrupts
SPU:          0   Spurious interrupts
CNT:          0   Performance monitoring interrupts
MCE:          0   Machine check exceptions
-bash-3.2#

I found out, that this card raise an irq when
ata_dev_read_id() is called, and because
ata_dev_read_id() sets the ATA_TFLAG_POLLING flag,
the irq don;t get acked in ata_sff_interrupt()
(So the irq comes endless (100000 times before it
 get disabled))

... so I tried the following patch (I think this
is not the right fix for it, but ...):

 drivers/ata/libata-core.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 49cffb6..6cad1e9 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -2132,7 +2132,7 @@ retry:
 	/* Device presence detection is unreliable on some
 	 * controllers.  Always poll IDENTIFY if available.
 	 */
-	tf.flags |= ATA_TFLAG_POLLING;
+//	tf.flags |= ATA_TFLAG_POLLING;

 	if (ap->ops->read_id)
 		err_mask = ap->ops->read_id(dev, &tf, id);

... it works:

pcmcia_socket pcmcia_socket0: pccard: PCMCIA card inserted into slot 0
pcmcia 0.0: pcmcia: registering new device pcmcia0.0
scsi0 : pata_pcmcia
ata1: PATA max PIO4 cmd 0x0 ctl 0xe irq 25
ata1.00: CFA: TOSHIBA THNCF512MDG, 3.00, max MWDMA2
ata1.00: 1000944 sectors, multi 1: LBA
ata1.00: configured for PIO4
ata1.00: configured for PIO4
ata1: EH complete
isa bounce pool size: 16 pages
scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA THNCF512 3.00 PQ: 0 ANSI: 5
sd 0:0:0:0: [sda] 1000944 512-byte logical blocks: (512 MB/488 MiB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sda: sda1 sda2 sda3 sda4
sd 0:0:0:0: [sda] Attached SCSI removable disk
pcmcia_socket pcmcia_socket1: pccard: PCMCIA card inserted into slot 1
pcmcia 1.0: pcmcia: registering new device pcmcia1.0
scsi1 : pata_pcmcia
ata2: PATA max PIO4 cmd 0x10 ctl 0x1e irq 26
ata2.00: CFA: TOSHIBA THNCF032MBA, 2.00, max PIO2
ata2.00: 63488 sectors, multi 0: LBA
ata2.00: configured for PIO2
ata2.00: configured for PIO2
ata2: EH complete
scsi 1:0:0:0: Direct-Access     ATA      TOSHIBA THNCF032 2.00 PQ: 0 ANSI: 5
sd 1:0:0:0: [sdb] 63488 512-byte logical blocks: (32.5 MB/31.0 MiB)
sd 1:0:0:0: [sdb] Write Protect is off
sd 1:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sdb: sdb1
sd 1:0:0:0: [sdb] Attached SCSI removable disk
IP-Config: Complete:
[...]
cat /-bash-3.2# cat /proc/interrupts
           CPU0
 17:          0   CPM PIC          Level        error
 18:          0   MPC8XX SIU       Level        tbint
 19:         28   CPM PIC          Level        cpm_uart
 21:          4   CPM PIC          Level        mpc8xxx_spi
 22:          0   MPC8XX SIU       Edge         ads7846
 23:      20083   MPC8XX SIU       Level        fs_enet-mac
 24:          0   MPC8XX SIU       Level        m8xx-pcmcia
 25:         14   MPC8XX SIU       Level        pata_pcmcia
 26:         14   MPC8XX SIU       Level        pata_pcmcia
 27:        473   CPM PIC          Level        cpm_i2c
LOC:       7413   Local timer interrupts
SPU:          0   Spurious interrupts
CNT:          0   Performance monitoring interrupts
MCE:          0   Machine check exceptions
-bash-3.2#

I mounted a FAT fs on this (buggy?) CF card, also did
some stress tests with reading/writing the whole card,
all worked fine with this patch ... (again, all other
cf cards I have, work fine without this patch)

Do you have an idea for that behaviour? (Or better an idea,
where to fix it right?)

thanks!

bye
Heiko
-- 
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Robert Hancock]

On 05/30/2010 11:57 PM, Heiko Schocher wrote:
> Hello Jeff,
>
> I have ported Linux 2.6.34 for a 8xx based board using the m8xx_pcmcia.c
> driver in drivers/pcmcia/ with two slots and CONFIG_ATA, CONFIG_PATA_PCMCIA
> defined.
>
> All works fine, except with one CF card type, I get:
>
> rtc-pcf8563 0-0051: setting system clock to 2010-05-31 05:18:41 UTC (1275283121)
> pcmcia_socket pcmcia_socket0: pccard: PCMCIA card inserted into slot 0
> pcmcia 0.0: pcmcia: registering new device pcmcia0.0
> scsi0 : pata_pcmcia
> ata1: PATA max PIO4 cmd 0x0 ctl 0xe irq 25
> ata1.00: CFA: TOSHIBA THNCF512MDG, 3.00, max MWDMA2
> ata1.00: 1000944 sectors, multi 1: LBA
> ata1.00: configured for PIO4
> ata1.00: configured for PIO4
> ata1: EH complete
> isa bounce pool size: 16 pages
> scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA THNCF512 3.00 PQ: 0 ANSI: 5
> sd 0:0:0:0: [sda] 1000944 512-byte logical blocks: (512 MB/488 MiB)
> sd 0:0:0:0: [sda] Write Protect is off
> sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
>   sda: sda1 sda2 sda3 sda4
> pcmcia_socket pcmcia_socket1: pccard: PCMCIA card inserted into slot 1
> pcmcia 1.0: pcmcia: registering new device pcmcia1.0
> sd 0:0:0:0: [sda] Attached SCSI removable disk
> scsi1 : pata_pcmcia
> ata2: PATA max PIO4 cmd 0x10 ctl 0x1e irq 26
> irq 26: nobody cared (try booting with the "irqpoll" option)
> Call Trace:
> [c0327c70] [c0006ac0] show_stack+0x44/0x16c (unreliable)
> [c0327cb0] [c004b7b4] __report_bad_irq+0x34/0xb8
> [c0327cd0] [c004b9f0] note_interrupt+0x1b8/0x224
> [c0327d00] [c004c9a8] handle_level_irq+0xa8/0x124
> [c0327d10] [c0004de8] do_IRQ+0x98/0xb4
> [c0327d30] [c000e788] ret_from_except+0x0/0x14
> [c0327df0] [00009032] 0x9032
> [c0327e30] [c0004b38] do_softirq+0x58/0x5c
> [c0327e40] [c0023d90] irq_exit+0x98/0x9c
> [c0327e50] [c0004dec] do_IRQ+0x9c/0xb4
> [c0327e70] [c000e788] ret_from_except+0x0/0x14
> [c0327f30] [c00440ac] tick_nohz_stop_sched_tick+0x404/0x4d0
> [c0327f90] [c0007ac8] cpu_idle+0x50/0xe8
> [c0327fb0] [c0002930] rest_init+0x5c/0x6c
> [c0327fc0] [c02f088c] start_kernel+0x240/0x2c4
> [c0327ff0] [c000222c] start_here+0x4c/0xb0
> handlers:
> [<c0193bc4>] (ata_sff_interrupt+0x0/0x208)
> Disabling IRQ #26
> IP-Config: Complete:
>       device=eth0, addr=192.168.120.4, mask=255.255.0.0, gw=192.168.1.254,
>       host=kup4k, domain=, nis-domain=(none),
>       bootserver=192.168.1.1, rootserver=192.168.1.1, rootpath=
> ata2.00: CFA: TOSHIBA THNCF032MBA, 2.00, max PIO2
> ata2.00: 63488 sectors, multi 0: LBA
> ata2.00: configured for PIO2
> ata2.00: configured for PIO2
> ata2: EH complete
> scsi 1:0:0:0: Direct-Access     ATA      TOSHIBA THNCF032 2.00 PQ: 0 ANSI: 5
> sd 1:0:0:0: [sdb] 63488 512-byte logical blocks: (32.5 MB/31.0 MiB)
> sd 1:0:0:0: [sdb] Write Protect is off
> sd 1:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
>   sdb: sdb1
> sd 1:0:0:0: [sdb] Attached SCSI removable disk
> Looking up port of RPC 100003/2 on 192.168.1.1
> [...]
>
> -bash-3.2# cat /proc/interrupts
>             CPU0
>   17:          0   CPM PIC          Level        error
>   18:          0   MPC8XX SIU       Level        tbint
>   19:         59   CPM PIC          Level        cpm_uart
>   21:          4   CPM PIC          Level        mpc8xxx_spi
>   22:          0   MPC8XX SIU       Edge         ads7846
>   23:      19950   MPC8XX SIU       Level        fs_enet-mac
>   24:          0   MPC8XX SIU       Level        m8xx-pcmcia
>   25:          9   MPC8XX SIU       Level        pata_pcmcia
>   26:     100000   MPC8XX SIU       Level        pata_pcmcia
>   27:         55   CPM PIC          Level        cpm_i2c
> LOC:      15403   Local timer interrupts
> SPU:          0   Spurious interrupts
> CNT:          0   Performance monitoring interrupts
> MCE:          0   Machine check exceptions
> -bash-3.2#
>
> I found out, that this card raise an irq when
> ata_dev_read_id() is called, and because
> ata_dev_read_id() sets the ATA_TFLAG_POLLING flag,
> the irq don;t get acked in ata_sff_interrupt()
> (So the irq comes endless (100000 times before it
>   get disabled))

Sounds like that card doesn't obey the nIEN flag to disable the 
interrupt, at least not on the identify command. Ugh.. Maybe we should 
be acking the interrupt anyway if we get one on a polling command? Not 
sure if that risks breaking anything or not..

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Heiko Schocher]

Hello Robert,

Robert Hancock wrote:
> On 05/30/2010 11:57 PM, Heiko Schocher wrote:
>> Hello Jeff,
>>
>> I have ported Linux 2.6.34 for a 8xx based board using the m8xx_pcmcia.c
>> driver in drivers/pcmcia/ with two slots and CONFIG_ATA,
>> CONFIG_PATA_PCMCIA
>> defined.
>>
>> All works fine, except with one CF card type, I get:
>>
>> rtc-pcf8563 0-0051: setting system clock to 2010-05-31 05:18:41 UTC
>> (1275283121)
>> pcmcia_socket pcmcia_socket0: pccard: PCMCIA card inserted into slot 0
>> pcmcia 0.0: pcmcia: registering new device pcmcia0.0
>> scsi0 : pata_pcmcia
>> ata1: PATA max PIO4 cmd 0x0 ctl 0xe irq 25
>> ata1.00: CFA: TOSHIBA THNCF512MDG, 3.00, max MWDMA2
>> ata1.00: 1000944 sectors, multi 1: LBA
>> ata1.00: configured for PIO4
>> ata1.00: configured for PIO4
>> ata1: EH complete
>> isa bounce pool size: 16 pages
>> scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA THNCF512 3.00 PQ: 0
>> ANSI: 5
>> sd 0:0:0:0: [sda] 1000944 512-byte logical blocks: (512 MB/488 MiB)
>> sd 0:0:0:0: [sda] Write Protect is off
>> sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't
>> support DPO or FUA
>>   sda: sda1 sda2 sda3 sda4
>> pcmcia_socket pcmcia_socket1: pccard: PCMCIA card inserted into slot 1
>> pcmcia 1.0: pcmcia: registering new device pcmcia1.0
>> sd 0:0:0:0: [sda] Attached SCSI removable disk
>> scsi1 : pata_pcmcia
>> ata2: PATA max PIO4 cmd 0x10 ctl 0x1e irq 26
>> irq 26: nobody cared (try booting with the "irqpoll" option)
>> Call Trace:
>> [c0327c70] [c0006ac0] show_stack+0x44/0x16c (unreliable)
>> [c0327cb0] [c004b7b4] __report_bad_irq+0x34/0xb8
>> [c0327cd0] [c004b9f0] note_interrupt+0x1b8/0x224
>> [c0327d00] [c004c9a8] handle_level_irq+0xa8/0x124
>> [c0327d10] [c0004de8] do_IRQ+0x98/0xb4
>> [c0327d30] [c000e788] ret_from_except+0x0/0x14
>> [c0327df0] [00009032] 0x9032
>> [c0327e30] [c0004b38] do_softirq+0x58/0x5c
>> [c0327e40] [c0023d90] irq_exit+0x98/0x9c
>> [c0327e50] [c0004dec] do_IRQ+0x9c/0xb4
>> [c0327e70] [c000e788] ret_from_except+0x0/0x14
>> [c0327f30] [c00440ac] tick_nohz_stop_sched_tick+0x404/0x4d0
>> [c0327f90] [c0007ac8] cpu_idle+0x50/0xe8
>> [c0327fb0] [c0002930] rest_init+0x5c/0x6c
>> [c0327fc0] [c02f088c] start_kernel+0x240/0x2c4
>> [c0327ff0] [c000222c] start_here+0x4c/0xb0
>> handlers:
>> [<c0193bc4>] (ata_sff_interrupt+0x0/0x208)
>> Disabling IRQ #26
>> IP-Config: Complete:
>>       device=eth0, addr=192.168.120.4, mask=255.255.0.0,
>> gw=192.168.1.254,
>>       host=kup4k, domain=, nis-domain=(none),
>>       bootserver=192.168.1.1, rootserver=192.168.1.1, rootpath=
>> ata2.00: CFA: TOSHIBA THNCF032MBA, 2.00, max PIO2
>> ata2.00: 63488 sectors, multi 0: LBA
>> ata2.00: configured for PIO2
>> ata2.00: configured for PIO2
>> ata2: EH complete
>> scsi 1:0:0:0: Direct-Access     ATA      TOSHIBA THNCF032 2.00 PQ: 0
>> ANSI: 5
>> sd 1:0:0:0: [sdb] 63488 512-byte logical blocks: (32.5 MB/31.0 MiB)
>> sd 1:0:0:0: [sdb] Write Protect is off
>> sd 1:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't
>> support DPO or FUA
>>   sdb: sdb1
>> sd 1:0:0:0: [sdb] Attached SCSI removable disk
>> Looking up port of RPC 100003/2 on 192.168.1.1
>> [...]
>>
>> -bash-3.2# cat /proc/interrupts
>>             CPU0
>>   17:          0   CPM PIC          Level        error
>>   18:          0   MPC8XX SIU       Level        tbint
>>   19:         59   CPM PIC          Level        cpm_uart
>>   21:          4   CPM PIC          Level        mpc8xxx_spi
>>   22:          0   MPC8XX SIU       Edge         ads7846
>>   23:      19950   MPC8XX SIU       Level        fs_enet-mac
>>   24:          0   MPC8XX SIU       Level        m8xx-pcmcia
>>   25:          9   MPC8XX SIU       Level        pata_pcmcia
>>   26:     100000   MPC8XX SIU       Level        pata_pcmcia
>>   27:         55   CPM PIC          Level        cpm_i2c
>> LOC:      15403   Local timer interrupts
>> SPU:          0   Spurious interrupts
>> CNT:          0   Performance monitoring interrupts
>> MCE:          0   Machine check exceptions
>> -bash-3.2#
>>
>> I found out, that this card raise an irq when
>> ata_dev_read_id() is called, and because
>> ata_dev_read_id() sets the ATA_TFLAG_POLLING flag,
>> the irq don;t get acked in ata_sff_interrupt()
>> (So the irq comes endless (100000 times before it
>>   get disabled))
> 
> Sounds like that card doesn't obey the nIEN flag to disable the
> interrupt, at least not on the identify command. Ugh.. Maybe we should
> be acking the interrupt anyway if we get one on a polling command? Not
> sure if that risks breaking anything or not..

Maybe the following patch is a better aproach, because it solves
my problem with a change only in the pata_pcmcia.c file:

ata, pcmcia: Work-around for interrupt-triggering IDENTIFY cmd.

In case the device does not honor nIEN when receiving the
IDENTIFY command, we disable polling mode, so that the
interrupt gets acknowledged nevertheless.

Suggested-by: Philippe Gerum <rpm@xenomai.org>
Signed-off-by: Heiko Schocher <hs@denx.de>
---
 drivers/ata/pata_pcmcia.c |   25 +++++++++++++++++++++++++
 1 files changed, 25 insertions(+), 0 deletions(-)

diff --git a/drivers/ata/pata_pcmcia.c b/drivers/ata/pata_pcmcia.c
index 87fb4ad..91a9669 100644
--- a/drivers/ata/pata_pcmcia.c
+++ b/drivers/ata/pata_pcmcia.c
@@ -103,6 +103,30 @@ static int pcmcia_set_mode_8bit(struct ata_link *link,
 }

 /**
+ *	pcmcia_read_id - Work-around for interrupt-triggering IDENTIFY
+ *	command
+ *
+ *	In case the device does not honor nIEN when receiving the
+ *	IDENTIFY command, we disable polling mode, so that the
+ *	interrupt gets acknowledged nevertheless.
+ */
+
+static unsigned int pcmcia_read_id(struct ata_device *adev,
+				   struct ata_taskfile *tf, u16 *id)
+{
+	unsigned int err_mask;
+
+	/*
+	 * Maybe we should clear the flag conditionally, depending on the
+	 * device id?
+	 */
+	tf->flags &= ~ATA_TFLAG_POLLING;
+	err_mask = ata_do_dev_read_id(adev, tf, id);
+
+	return err_mask;
+}
+
+/**
  *	ata_data_xfer_8bit	 -	Transfer data by 8bit PIO
  *	@dev: device to target
  *	@buf: data buffer
@@ -172,6 +196,7 @@ static struct ata_port_operations pcmcia_port_ops = {
 	.sff_data_xfer	= ata_sff_data_xfer_noirq,
 	.cable_detect	= ata_cable_40wire,
 	.set_mode	= pcmcia_set_mode,
+	.read_id	= pcmcia_read_id,
 };

 static struct ata_port_operations pcmcia_8bit_port_ops = {
-- 
1.6.2.5


-- 
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Tejun Heo]

Hello,

Can you please give a shot at the following branch and report
the kernel log?

  git://git.kernel.org/pub/scm/linux/kernel/git/tj/misc.git libata-irq-expect

Thanks.

-- 
tejun

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Heiko Schocher]

Hello Tejun,

Tejun Heo wrote:
> Can you please give a shot at the following branch and report
> the kernel log?
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/tj/misc.git libata-irq-expect

I tried it with above kernel, but same problem as I reported:

   Uncompressing Kernel Image ... OK
Using KUP4K machine description
Linux version 2.6.35-rc3-112005-gc44f4d3-dirty (hs@pollux.denx.de) (gcc version 4.2.2) #1 Mon Jul 5 10:11:11 CEST 2010
Zone PFN ranges:
  DMA      0x00000000 -> 0x00006000
  Normal   empty
Movable zone start PFN for each node
early_node_map[1] active PFN ranges
    0: 0x00000000 -> 0x00006000
MMU: Allocated 72 bytes of context maps for 16 contexts
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 24384
Kernel command line: root=/dev/nfs rw nfsroot=/opt/eldk-4.2/ppc_8xx,timeo=20,retrans=5 ip=192.168.120.4:192.168.1.1:192.168.1.254:255.255.0.0:kup4k:eth0:off console=ttyCPM0,115200
PID hash table entries: 512 (order: -1, 2048 bytes)
Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
Memory: 93912k/98304k available (3180k kernel code, 4392k reserved, 112k data, 106k bss, 132k init)
Kernel virtual memory layout:
  * 0xfffdf000..0xfffff000  : fixmap
  * 0xfde00000..0xfe000000  : consistent mem
  * 0xfddf9000..0xfde00000  : early ioremap
  * 0xc7000000..0xfddf9000  : vmalloc & ioremap
SLUB: Genslabs=12, HWalign=16, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
Hierarchical RCU implementation.
        RCU-based detection of stalled CPUs is disabled.
        Verbose stalled-CPUs detection is disabled.
NR_IRQS:512 nr_irqs:512
Decrementer Frequency = 0x4c4b40
clocksource: timebase mult[32000000] shift[22] registered
console [ttyCPM0] enabled
pid_max: default: 4096 minimum: 301
Mount-cache hash table entries: 512
NET: Registered protocol family 16
pwm_init
bio: create slab <bio-0> at 0
SCSI subsystem initialized
Switching to clocksource timebase
NET: Registered protocol family 2
IP route cache hash table entries: 1024 (order: 0, 4096 bytes)
TCP established hash table entries: 4096 (order: 3, 32768 bytes)
TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
TCP: Hash tables configured (established 4096 bind 4096)
TCP reno registered
NET: Registered protocol family 1
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
mpc8xx-gpt fff00980.pwm_m8xx_gpt: 4 channels
msgmni has been set to 183
io scheduler noop registered
io scheduler deadline registered (default)
s1d13xxxfb: chip production id 10 = S1D13706
s1d13xxxfb: chip revision 0
fff00a80.serial: ttyCPM0 at MMIO 0xc7034a80 (irq = 19) is a CPM UART
fff00a90.serial: ttyCPM1 at MMIO 0xc703ca90 (irq = 20) is a CPM UART
brd: module loaded
loop: module loaded
Found: AMD AM29LV800BB
40000000.flash: Found 1 x16 devices at 0x0 in 16-bit bank
number of JEDEC chips: 1
RedBoot partition parsing not available
mpc8xxx_spi fff00aa0.spi: at 0xc705aaa0 (irq = 21), CPM1 mode
eth0: fs_enet: 00:0b:64:00:0b:72
FEC MII Bus: probed
m8xx_pcmcia: Version 0.07, March 2010
m8xx_pcmcia: m8xx_probe: using SLOT_A and SLOT_B with IRQ 24  (13).
pcmcia_hardware_enable: Slot: 0 3.3V card found:
pcmcia_hardware_enable: Slot: 1 3.3V card found:
ads7846 spi32766.0: touchscreen, irq 22
input: ADS7846 Touchscreen as /class/input/input0
i2c /dev entries driver
pcf857x 0-0021: gpios 168..175 on a pcf8574
rtc-pcf8563 0-0051: chip found, driver version 0.4.3
rtc-pcf8563 0-0051: rtc core: registered rtc-pcf8563 as rtc0
WD: Software Watchdog Timer 1.1.0, timeout 300 sec.
TCP cubic registered
NET: Registered protocol family 17
rtc-pcf8563 0-0051: setting system clock to 2010-07-05 08:14:34 UTC (1278317674)
pcmcia_socket pcmcia_socket0: pccard: PCMCIA card inserted into slot 0
pcmcia_setup_irq: s->pcmcia_irq: 25
pcmcia 0.0: pcmcia: registering new device pcmcia0.0 (IRQ: 25)
scsi0 : pata_pcmcia
ata1: PATA max PIO4 cmd 0x0 ctl 0xe irq 25+
ata1.00: CFA: TOSHIBA THNCF512MDG, 3.00, max MWDMA2
ata1.00: 1000944 sectors, multi 1: LBA
ata1.00: configured for PIO4
ata1.00: configured for PIO4
ata1: EH complete
isa bounce pool size: 16 pages
scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA THNCF512 3.00 PQ: 0 ANSI: 5
sd 0:0:0:0: [sda] 1000944 512-byte logical blocks: (512 MB/488 MiB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sda: sda1 sda2 sda3 sda4
pcmcia_socket pcmcia_socket1: pccard: PCMCIA card inserted into slot 1
pcmcia_setup_irq: s->pcmcia_irq: 26
pcmcia 1.0: pcmcia: registering new device pcmcia1.0 (IRQ: 26)
sd 0:0:0:0: [sda] Attached SCSI removable disk
scsi1 : pata_pcmcia
ata2: PATA max PIO4 cmd 0x10 ctl 0x1e irq 26+
IRQ 26: too many spurious IRQs, disabling and polling for 10k 10msec intervals.
IRQ 26: system performance may be affected
handlers:
[<c0198d00>] (ata_sff_interrupt+0x0/0x204)
IP-Config: Complete:
     device=eth0, addr=192.168.120.4, mask=255.255.0.0, gw=192.168.1.254,
     host=kup4k, domain=, nis-domain=(none),
     bootserver=192.168.1.1, rootserver=192.168.1.1, rootpath=
ata2.00: CFA: TOSHIBA THNCF032MBA, 2.00, max PIO2
ata2.00: 63488 sectors, multi 0: LBA
ata2.00: configured for PIO2
ata2.00: configured for PIO2
ata2: EH complete
scsi 1:0:0:0: Direct-Access     ATA      TOSHIBA THNCF032 2.00 PQ: 0 ANSI: 5
sd 1:0:0:0: [sdb] 63488 512-byte logical blocks: (32.5 MB/31.0 MiB)
sd 1:0:0:0: [sdb] Write Protect is off
sd 1:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sdb: sdb1
sd 1:0:0:0: [sdb] Attached SCSI removable disk
Looking up port of RPC 100003/2 on 192.168.1.1
Looking up port of RPC 100005/1 on 192.168.1.1
VFS: Mounted root (nfs filesystem) on device 0:12.
Freeing unused kernel memory: 132k init
modprobe: FATAL: Could not load /lib/modules/2.6.35-rc3-112005-gc44f4d3-dirty/modules.dep: No such file or directory

modprobe: FATAL: Could not load /lib/modules/2.6.35-rc3-112005-gc44f4d3-dirty/modules.dep: No such file or directory

INIT: version 2.86 booting
                Welcome to DENX Embedded Linux Environment
                Press 'I' to enter interactive startup.
Setting clock : Mon Jul  5 08:14:41 CEST 2010 [  OK  ]
Building the cache [  OK  ]
Setting hostname kup4k:  [  OK  ]
Mounting local filesystems:  [  OK  ]
Enabling /etc/fstab swaps:  [  OK  ]
INIT: Entering runlevel: 3
Entering non-interactive startup
FATAL: Could not load /lib/modules/2.6.35-rc3-112005-gc44f4d3-dirty/modules.dep: No such file or directory
Bringing up loopback interface:  [  OK  ]
FATAL: Could not load /lib/modules/2.6.35-rc3-112005-gc44f4d3-dirty/modules.dep: No such file or directory
Starting system logger: [  OK  ]
Starting kernel logger: [  OK  ]
Starting rpcbind: [  OK  ]
Mounting NFS filesystems:  [  OK  ]
Mounting other filesystems:  [  OK  ]
Starting xinetd: [  OK  ]

DENX ELDK version 4.2 build 2008-04-01
Linux 2.6.35-rc3-112005-gc44f4d3-dirty on a ppc

kup4k login: root
Last login: Thu Jan  1 01:01:08 on console
reboot-bash-3.2#

I tried it with my posted patch, and it solved it also for this kernel:

   Uncompressing Kernel Image ... OK
Using KUP4K machine description
Linux version 2.6.35-rc3-112005-gc44f4d3-dirty (hs@pollux.denx.de) (gcc version 4.2.2) #2 Mon Jul 5 10:20:35 CEST 2010
Zone PFN ranges:
  DMA      0x00000000 -> 0x00006000
  Normal   empty
Movable zone start PFN for each node
early_node_map[1] active PFN ranges
[...]
m8xx_pcmcia: Version 0.07, March 2010
m8xx_pcmcia: m8xx_probe: using SLOT_A and SLOT_B with IRQ 24  (13).
pcmcia_hardware_enable: Slot: 0 3.3V card found:
pcmcia_hardware_enable: Slot: 1 3.3V card found:
ads7846 spi32766.0: touchscreen, irq 22
input: ADS7846 Touchscreen as /class/input/input0
i2c /dev entries driver
pcf857x 0-0021: gpios 168..175 on a pcf8574
rtc-pcf8563 0-0051: chip found, driver version 0.4.3
rtc-pcf8563 0-0051: rtc core: registered rtc-pcf8563 as rtc0
WD: Software Watchdog Timer 1.1.0, timeout 300 sec.
TCP cubic registered
NET: Registered protocol family 17
rtc-pcf8563 0-0051: setting system clock to 2010-07-05 08:16:30 UTC (1278317790)
pcmcia_socket pcmcia_socket0: pccard: PCMCIA card inserted into slot 0
pcmcia 0.0: pcmcia: registering new device pcmcia0.0 (IRQ: 25)
scsi0 : pata_pcmcia
ata1: PATA max PIO4 cmd 0x0 ctl 0xe irq 25+
ata1.00: CFA: TOSHIBA THNCF512MDG, 3.00, max MWDMA2
ata1.00: 1000944 sectors, multi 1: LBA
ata1.00: configured for PIO4
ata1.00: configured for PIO4
ata1: EH complete
isa bounce pool size: 16 pages
scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA THNCF512 3.00 PQ: 0 ANSI: 5
sd 0:0:0:0: [sda] 1000944 512-byte logical blocks: (512 MB/488 MiB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sda: sda1 sda2 sda3 sda4
sd 0:0:0:0: [sda] Attached SCSI removable disk
pcmcia_socket pcmcia_socket1: pccard: PCMCIA card inserted into slot 1
pcmcia 1.0: pcmcia: registering new device pcmcia1.0 (IRQ: 26)
scsi1 : pata_pcmcia
ata2: PATA max PIO4 cmd 0x10 ctl 0x1e irq 26+
ata2.00: CFA: TOSHIBA THNCF032MBA, 2.00, max PIO2
ata2.00: 63488 sectors, multi 0: LBA
ata2.00: configured for PIO2
ata2.00: configured for PIO2
ata2: EH complete
scsi 1:0:0:0: Direct-Access     ATA      TOSHIBA THNCF032 2.00 PQ: 0 ANSI: 5
sd 1:0:0:0: [sdb] 63488 512-byte logical blocks: (32.5 MB/31.0 MiB)
sd 1:0:0:0: [sdb] Write Protect is off
sd 1:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sdb: sdb1
sd 1:0:0:0: [sdb] Attached SCSI removable disk
IP-Config: Complete:
[...]

bye,
Heiko
-- 
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Tejun Heo]

On 07/05/2010 10:26 AM, Heiko Schocher wrote:
> IRQ 26: too many spurious IRQs, disabling and polling for 10k 10msec intervals.
> IRQ 26: system performance may be affected
> handlers:
> [<c0198d00>] (ata_sff_interrupt+0x0/0x204)

Yeah, that's the new polling code kicking in.  If the IRQ problem
doesn't persiste (which should be the case here), polling will step
down after a while and everything will return to normal.  If you keep
the system running more than ten minutes and use the CF device, does
the kernel complain anymore?

Thanks.

-- 
tejun

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Heiko Schocher]

Hello Tejun,

Tejun Heo wrote:
> On 07/05/2010 10:26 AM, Heiko Schocher wrote:
>> IRQ 26: too many spurious IRQs, disabling and polling for 10k 10msec intervals.
>> IRQ 26: system performance may be affected
>> handlers:
>> [<c0198d00>] (ata_sff_interrupt+0x0/0x204)
> 
> Yeah, that's the new polling code kicking in.  If the IRQ problem
> doesn't persiste (which should be the case here), polling will step
> down after a while and everything will return to normal.  If you keep
> the system running more than ten minutes and use the CF device, does
> the kernel complain anymore?

No, I can use the CF while kernel is in polling mode, also if the
kernel switched back to irq mode:

Log, direct after kernel is up:

[...]
Freeing unused kernel memory: 132k init
-bash-3.2# mount -t vfat /dev/sdb1 /home/hs/mnt
-bash-3.2# cat /proc/uptime
62.08 14.08
-bash-3.2# cat /proc/interrupts
           CPU0
 17:          0   CPM PIC          Level        error
 18:          0   MPC8XX SIU       Level        tbint
 19:        308   CPM PIC          Level        cpm_uart
 21:          4   CPM PIC          Level        mpc8xxx_spi
 22:          0   MPC8XX SIU       Edge         ads7846
 23:      20043   MPC8XX SIU       Level        fs_enet-mac
 24:          0   MPC8XX SIU       Level        m8xx-pcmcia
 25:          9   MPC8XX SIU       Level        pata_pcmcia
 26:      10000   MPC8XX SIU       Level        pata_pcmcia
 27:        129   CPM PIC          Level        cpm_i2c
LOC:       6408   Local timer interrupts
SPU:          0   Spurious interrupts
CNT:          0   Performance monitoring interrupts
MCE:          0   Machine check exceptions
-bash-3.2#

No irq is used.

-bash-3.2# dmesg
[...]
Freeing unused kernel memory: 132k init
IRQ 26: spurious polling finished, reenabling IRQ
-bash-3.2#

Now it is back in irq mode:

-bash-3.2# cat /proc/uptime
419.65 370.56
-bash-3.2#

-bash-3.2# mount -t vfat /dev/sdb1 /home/hs/mnt
-bash-3.2# cat /proc/interrupts
           CPU0
 17:          0   CPM PIC          Level        error
 18:          0   MPC8XX SIU       Level        tbint
 19:        956   CPM PIC          Level        cpm_uart
 21:          4   CPM PIC          Level        mpc8xxx_spi
 22:          0   MPC8XX SIU       Edge         ads7846
 23:      20414   MPC8XX SIU       Level        fs_enet-mac
 24:          0   MPC8XX SIU       Level        m8xx-pcmcia
 25:          9   MPC8XX SIU       Level        pata_pcmcia
 26:      10033   MPC8XX SIU       Level        pata_pcmcia
 27:        129   CPM PIC          Level        cpm_i2c
LOC:      10880   Local timer interrupts
SPU:          0   Spurious interrupts
CNT:          0   Performance monitoring interrupts
MCE:          0   Machine check exceptions
-bash-3.2#

Now it uses the irq ...

bye,
Heiko
-- 
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Tejun Heo]

Hello,

On 07/05/2010 11:25 AM, Heiko Schocher wrote:
>> Yeah, that's the new polling code kicking in.  If the IRQ problem
>> doesn't persiste (which should be the case here), polling will step
>> down after a while and everything will return to normal.  If you keep
>> the system running more than ten minutes and use the CF device, does
>> the kernel complain anymore?
> 
> No, I can use the CF while kernel is in polling mode, also if the
> kernel switched back to irq mode:
> 
> Log, direct after kernel is up:
> 
..
>  25:          9   MPC8XX SIU       Level        pata_pcmcia
>  26:      10000   MPC8XX SIU       Level        pata_pcmcia
...
> 
> No irq is used.
> 
> -bash-3.2# dmesg
> [...]
> Freeing unused kernel memory: 132k init
> IRQ 26: spurious polling finished, reenabling IRQ
> -bash-3.2#
> 
> Now it is back in irq mode:
> 
> -bash-3.2# cat /proc/uptime
> 419.65 370.56
> -bash-3.2#
> 
...
>  25:          9   MPC8XX SIU       Level        pata_pcmcia
>  26:      10033   MPC8XX SIU       Level        pata_pcmcia

Cool, so it works as expected.  With the new lost/spurious IRQ
handling in place, removing TFLAG_POLLING from read_id for all
controllers shouldn't cause much problem.  However, the CF device is a
pretty rare corner case and spurious IRQ handling can deal with it
without too much problem, so leaving things as it is is probably
better.

Thanks for testing.

-- 
tejun

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Heiko Schocher]

Hello Tejun,

Tejun Heo wrote:
> On 07/05/2010 11:25 AM, Heiko Schocher wrote:
>>> Yeah, that's the new polling code kicking in.  If the IRQ problem
>>> doesn't persiste (which should be the case here), polling will step
>>> down after a while and everything will return to normal.  If you keep
>>> the system running more than ten minutes and use the CF device, does
>>> the kernel complain anymore?
>> No, I can use the CF while kernel is in polling mode, also if the
>> kernel switched back to irq mode:
>>
>> Log, direct after kernel is up:
>>
> ..
>>  25:          9   MPC8XX SIU       Level        pata_pcmcia
>>  26:      10000   MPC8XX SIU       Level        pata_pcmcia
> ...
>> No irq is used.
>>
>> -bash-3.2# dmesg
>> [...]
>> Freeing unused kernel memory: 132k init
>> IRQ 26: spurious polling finished, reenabling IRQ
>> -bash-3.2#
>>
>> Now it is back in irq mode:
>>
>> -bash-3.2# cat /proc/uptime
>> 419.65 370.56
>> -bash-3.2#
>>
> ...
>>  25:          9   MPC8XX SIU       Level        pata_pcmcia
>>  26:      10033   MPC8XX SIU       Level        pata_pcmcia
> 
> Cool, so it works as expected.  With the new lost/spurious IRQ
> handling in place, removing TFLAG_POLLING from read_id for all
> controllers shouldn't cause much problem.  However, the CF device is a
> pretty rare corner case and spurious IRQ handling can deal with it
> without too much problem, so leaving things as it is is probably
> better.

Hmm.. I am not sure if "leaving things as it is" is the better way,
because this behaviour comes every time, I insert a card! And with
my patch I can prevent this behaviour ...

> Thanks for testing.

Thanks for your comments!

bye
Heiko
-- 
DENX Software Engineering GmbH,     MD: Wolfgang Denk & Detlev Zundel
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany

Re: ata, pcmcia: problem with irq and ata_dev_read_id()

[Tejun Heo]

Hello,

On 07/26/2010 02:59 PM, Heiko Schocher wrote:
> Hmm.. I am not sure if "leaving things as it is" is the better way,
> because this behaviour comes every time, I insert a card! And with
> my patch I can prevent this behaviour ...

Yes, it fixes the behavior which comes every time in your
configuration but it might at the same time break other configurations
which are more common.  ATA probing is a painful thing and we had
pretty good reasons to turn on TFLAG_POLLING for IDENTIFY by default.

The only side effect your configuration is going to have is IRQ
polling kicking in for short period of time after device insertion.
Please also note that the device can't be quirked as it's before its
identity is known.  So, yeah, I think it is better to leave things as
is as long as IRQ flakiness can be handled in acceptable manner which
we need to do anyway.

Thanks.

-- 
tejun