pata_via cd/dvd timeout problems

pata_via cd/dvd timeout problems

[richard kennedy]

I have both a dvd RW drive & a cd rom drive connected the second ide
interface on my motherboard with a via chipset, using pata_via I see
timeout messages in the log & after some time both drives lockup and are
unable to mount any disks. 

This problem is present in at least 2.6.22 & 2.6.23-rc5.
This is a AMD Athlon X2 smp machine running fedora -- untainted.
sorry I didn't spot this sooner but I don't use these drives all that
often.   
Any suggestions for what is going wrong or how to get any more debug
info? 

lspci -v
00:0f.1 IDE interface: VIA Technologies, Inc. VT82C586A/B/VT82C686/A/B/VT823x/A/C PIPC Bus Master IDE (rev 06) (prog-if 8a [Master SecP PriP])
        Subsystem: ABIT Computer Corp. Unknown device 1415
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
        Latency: 32
        Interrupt: pin A routed to IRQ 20
        Region 0: [virtual] Memory at 000001f0 (32-bit, non-prefetchable) [size=8]
        Region 1: [virtual] Memory at 000003f0 (type 3, non-prefetchable) [size=1]
        Region 2: [virtual] Memory at 00000170 (32-bit, non-prefetchable) [size=8]
        Region 3: [virtual] Memory at 00000370 (type 3, non-prefetchable) [size=1]
        Region 4: I/O ports at e400 [size=16]
        Capabilities: [c0] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 PME-Enable- DSel=0 DScale=0 PME-
 
both drives are seen ok at boot time :- 

Sep  3 13:49:27 castor kernel: scsi2 : pata_via
Sep  3 13:49:27 castor kernel: scsi3 : pata_via
Sep  3 13:49:27 castor kernel: ata3: PATA max UDMA/133 cmd 0x00000000000101f0 ctl 0x00000000000103f6 bmdma 0x000000000001e400 irq 14
Sep  3 13:49:27 castor kernel: ata4: PATA max UDMA/133 cmd 0x0000000000010170 ctl 0x0000000000010376 bmdma 0x000000000001e408 irq 15
Sep  3 13:49:27 castor kernel: ata3.00: ATA-7: Maxtor 6B300R0, BAH41BM0, max UDMA/133
Sep  3 13:49:27 castor kernel: ata3.00: 586114704 sectors, multi 16: LBA48 
Sep  3 13:49:28 castor kernel: ata3.00: configured for UDMA/133
Sep  3 13:49:28 castor kernel: ata4.00: ATAPI: _NEC DVD_RW ND-3520A, 1.04, max UDMA/33
Sep  3 13:49:28 castor kernel: ata4.01: ATAPI: TSSTcorpDVD-ROM TS-H352A, TS03, max UDMA/33
Sep  3 13:49:28 castor kernel: ata4.00: configured for UDMA/33
Sep  3 13:49:28 castor kernel: ata4.01: configured for UDMA/33
Sep  3 13:49:28 castor kernel: scsi 2:0:0:0: Direct-Access     ATA      Maxtor 6B300R0   BAH4 PQ: 0 ANSI: 5
Sep  3 13:49:28 castor kernel: sd 2:0:0:0: [sdb] 586114704 512-byte hardware sectors (300091 MB)
Sep  3 13:49:28 castor kernel: sd 2:0:0:0: [sdb] Write Protect is off
Sep  3 13:49:28 castor kernel: sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Sep  3 13:49:28 castor kernel: sd 2:0:0:0: [sdb] 586114704 512-byte hardware sectors (300091 MB)
Sep  3 13:49:28 castor kernel: sd 2:0:0:0: [sdb] Write Protect is off
Sep  3 13:49:28 castor kernel: sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Sep  3 13:49:28 castor kernel:  sdb: sdb1 sdb2
Sep  3 13:49:28 castor kernel: sd 2:0:0:0: [sdb] Attached SCSI disk
Sep  3 13:49:29 castor kernel: scsi 3:0:0:0: CD-ROM            _NEC     DVD_RW ND-3520A  1.04 PQ: 0 ANSI: 5
Sep  3 13:49:29 castor kernel: scsi 3:0:1:0: CD-ROM            TSSTcorp DVD-ROM TS-H352A TS03 PQ: 0 ANSI: 5


this is the first timeout message 

Sep  3 14:12:48 castor kernel: ata4.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Sep  3 14:12:48 castor kernel: ata4.00: cmd a0/00:00:00:00:20/00:00:00:00:00/a0 tag 0 cdb 0x4a data 8 in
Sep  3 14:12:48 castor kernel:          res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  3 14:12:48 castor kernel: ata4: soft resetting port
Sep  3 14:12:48 castor kernel: ata4.00: configured for UDMA/33
Sep  3 14:12:49 castor kernel: ata4.01: configured for UDMA/33
Sep  3 14:12:49 castor kernel: ata4: EH complete

this gets repeated 3 or 4 times then changes to this

Sep  3 14:16:45 castor kernel: ata4.00: limiting speed to UDMA/25:PIO4
Sep  3 14:16:45 castor kernel: ata4.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Sep  3 14:16:45 castor kernel: ata4.00: cmd a0/00:00:00:00:20/00:00:00:00:00/a0 tag 0 cdb 0x1e data 0 
Sep  3 14:16:45 castor kernel:          res 40/00:02:00:08:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
Sep  3 14:16:45 castor kernel: ata4: soft resetting port
Sep  3 14:16:45 castor kernel: ata4.00: configured for UDMA/25
Sep  3 14:16:46 castor kernel: ata4.01: configured for UDMA/33
Sep  3 14:16:46 castor kernel: ata4: EH complete

repeats multiple times then

Sep  3 14:23:27 castor kernel: ata4.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Sep  3 14:23:27 castor kernel: ata4.00: cmd a0/00:00:00:00:20/00:00:00:00:00/a0 tag 0 cdb 0x1e data 0 
Sep  3 14:23:27 castor kernel:          res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  3 14:23:27 castor kernel: ata4: soft resetting port
Sep  3 14:23:27 castor kernel: ata4.00: configured for PIO4
Sep  3 14:23:28 castor kernel: ata4.01: configured for UDMA/33
Sep  3 14:23:28 castor kernel: ata4: EH complete
Sep  3 14:23:28 castor kernel: sr 3:0:0:0: ioctl_internal_command return code = 8000002
Sep  3 14:23:28 castor kernel:    : Sense Key : Aborted Command [current] [descriptor]
Sep  3 14:23:28 castor kernel:    : Add. Sense: No additional sense information
Sep  3 14:23:58 castor kernel: ata4.01: limiting speed to UDMA/25:PIO4
Sep  3 14:23:58 castor kernel: ata4.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Sep  3 14:23:58 castor kernel: ata4.01: cmd a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0 
Sep  3 14:23:58 castor kernel:          res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  3 14:23:58 castor kernel: ata4: soft resetting port
Sep  3 14:23:58 castor kernel: ata4.00: configured for PIO4
Sep  3 14:23:58 castor kernel: ata4.01: configured for UDMA/25
Sep  3 14:23:58 castor kernel: ata4: EH complete

By this point neither drive will mount a disk.

thanks
Richard

Re: pata_via cd/dvd timeout problems

[Vlad]

Hi,

> I have both a dvd RW drive & a cd rom drive connected
> the second ide interface on my motherboard with a via
> chipset, using pata_via I see timeout messages in the
> log & after some time both drives lockup and are
> unable to mount any disks. 

I would suggest trying the following things:

1) Add both drives ("_NEC DVD_RW ND-3520" and "TSSTcorpDVD-ROM
TS-H352A") to ata_device_blacklist in drivers/ata/libata-core.c using
the ATA_HORKAGE_NODMA and ATA_HORKAGE_MAX_SEC_128 keywords and then
recompile the kernel.

2) Move the CD and DVD RW drives to a computer with another chipset to
determine whether they or the chipset are to blame.

Vlad


       
____________________________________________________________________________________
Pinpoint customers who are looking for what you sell. 
http://searchmarketing.yahoo.com/

Re: pata_via cd/dvd timeout problems

[fredm]

Hi,

Re: pata_via cd/dvd timeout problems

[fredm]

(take 2)
Hi,

Quoting Vlad <vladc6@yahoo.com>:
>> I have both a dvd RW drive & a cd rom drive connected
>> the second ide interface on my motherboard with a via
>> chipset, using pata_via I see timeout messages in the
>> log & after some time both drives lockup and are
>> unable to mount any disks.

Just a "me too". On 2.6.22 without via_pata I get the following and  
the DVD drive always seems to work:
Aug 31 12:53:13 nelson kernel: hdd: LITE-ON DVD SOHD-167T, ATAPI  
CD/DVD-ROM drive
Aug 31 12:53:13 nelson kernel: hdd: ATAPI 48X DVD-ROM drive, 512kB  
Cache, UDMA(33)
Aug 31 15:05:22 nelson kernel: hdd: lost interrupt
Aug 31 15:06:22 nelson kernel: hdd: lost interrupt

With via_pata, I get the following, more info available if required:
Sep  4 11:56:41 nelson kernel: scsi2 : pata_via
Sep  4 11:56:41 nelson kernel: scsi3 : pata_via
Sep  4 11:56:41 nelson kernel: ata3: PATA max UDMA/133 cmd  
0x00000000000101f0 ctl 0x00000000000103f6 bmdma 0x000000000001dc00 irq  
14
Sep  4 11:56:41 nelson kernel: ata4: PATA max UDMA/133 cmd  
0x0000000000010170 ctl 0x0000000000010376 bmdma 0x000000000001dc08 irq  
15
Sep  4 11:56:41 nelson kernel: ata4.01: ATAPI: LITE-ON DVD SOHD-167T,  
9S1B, max UDMA/33
Sep  4 11:56:41 nelson kernel: ata4.01: configured for UDMA/33
Sep  4 11:56:41 nelson kernel: scsi 3:0:1:0: CD-ROM            LITE-ON  
  DVD SOHD-167T    9S1B PQ: 0 ANSI: 5
Sep  4 12:50:47 nelson kernel: ata4.01: qc timeout (cmd 0xa0)
Sep  4 12:50:47 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:50:47 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:50:47 nelson kernel:          res  
51/20:03:00:00:20/00:00:00:00:00/b0 Emask 0x5 (timeout)
Sep  4 12:50:47 nelson kernel: ata4: soft resetting port
Sep  4 12:50:47 nelson kernel: ata4.01: configured for UDMA/33
Sep  4 12:50:47 nelson kernel: ata4: EH complete
Sep  4 12:51:17 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:51:17 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:51:17 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:51:17 nelson kernel: ata4: soft resetting port
Sep  4 12:51:18 nelson kernel: ata4.01: configured for UDMA/33
Sep  4 12:51:18 nelson kernel: ata4: EH complete
Sep  4 12:51:48 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:51:48 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:51:48 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:51:48 nelson kernel: ata4: soft resetting port
Sep  4 12:51:49 nelson kernel: ata4.01: configured for UDMA/33
Sep  4 12:51:49 nelson kernel: ata4: EH complete
Sep  4 12:52:19 nelson kernel: ata4.01: limiting speed to UDMA/25:PIO4
Sep  4 12:52:19 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:52:19 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:52:19 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:52:19 nelson kernel: ata4: soft resetting port
Sep  4 12:52:19 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:52:19 nelson kernel: ata4: EH complete
Sep  4 12:52:49 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:52:49 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:52:49 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:52:49 nelson kernel: ata4: soft resetting port
Sep  4 12:52:50 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:52:50 nelson kernel: ata4: EH complete
Sep  4 12:53:20 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:53:20 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:53:20 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:53:20 nelson kernel: ata4: soft resetting port
Sep  4 12:53:20 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:53:20 nelson kernel: ata4: EH complete
Sep  4 12:53:50 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:53:50 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:53:50 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:53:50 nelson kernel: ata4: soft resetting port
Sep  4 12:53:51 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:53:51 nelson kernel: ata4: EH complete
Sep  4 12:54:21 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:54:21 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:54:21 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:54:21 nelson kernel: ata4: soft resetting port
Sep  4 12:54:22 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:54:22 nelson kernel: ata4: EH complete
Sep  4 12:54:22 nelson kernel: sr0: CDROM (ioctl) error, command: Test  
Unit Ready 00 00 00 00 00 00
Sep  4 12:54:22 nelson kernel: sr: Sense Key : Aborted Command  
[current] [descriptor]
Sep  4 12:54:22 nelson kernel: sr: Add. Sense: No additional sense information
Sep  4 12:54:32 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:54:32 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:54:32 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:54:32 nelson kernel: ata4: soft resetting port
Sep  4 12:54:32 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:54:32 nelson kernel: ata4: EH complete
Sep  4 12:54:42 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:54:42 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:54:42 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:54:42 nelson kernel: ata4: soft resetting port
Sep  4 12:54:43 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:54:43 nelson kernel: ata4: EH complete
Sep  4 12:54:53 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:54:53 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:54:53 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:54:53 nelson kernel: ata4: soft resetting port
Sep  4 12:54:53 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:54:53 nelson kernel: ata4: EH complete
Sep  4 12:55:03 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:55:03 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:55:03 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:55:03 nelson kernel: ata4: soft resetting port
Sep  4 12:55:04 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:55:04 nelson kernel: ata4: EH complete
Sep  4 12:55:14 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:55:14 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:55:14 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:55:14 nelson kernel: ata4: soft resetting port
Sep  4 12:55:15 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:55:15 nelson kernel: ata4: EH complete
Sep  4 12:55:25 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:55:25 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:55:25 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:55:25 nelson kernel: ata4: soft resetting port
Sep  4 12:55:25 nelson kernel: ata4.01: configured for UDMA/25
Sep  4 12:55:25 nelson kernel: ata4: EH complete
Sep  4 12:55:25 nelson kernel: sr 3:0:1:0: ioctl_internal_command  
return code = 8000002
Sep  4 12:55:25 nelson kernel:    : Sense Key : Aborted Command  
[current] [descriptor]
Sep  4 12:55:25 nelson kernel:    : Add. Sense: No additional sense  
information
Sep  4 12:55:57 nelson kernel: ata4.01: limiting speed to PIO4
Sep  4 12:55:57 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:55:57 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:55:57 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:55:57 nelson kernel: ata4: soft resetting port
Sep  4 12:55:58 nelson kernel: ata4.01: configured for PIO4
Sep  4 12:55:58 nelson kernel: ata4: EH complete
Sep  4 12:56:28 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:56:28 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:56:28 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:56:28 nelson kernel: ata4: soft resetting port
Sep  4 12:56:29 nelson kernel: ata4.01: configured for PIO4
Sep  4 12:56:29 nelson kernel: ata4: EH complete
Sep  4 12:56:59 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:56:59 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:56:59 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:56:59 nelson kernel: ata4: soft resetting port
Sep  4 12:56:59 nelson kernel: ata4.01: configured for PIO4
Sep  4 12:56:59 nelson kernel: ata4: EH complete
Sep  4 12:57:29 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:57:29 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:57:29 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:57:29 nelson kernel: ata4: soft resetting port
Sep  4 12:57:30 nelson kernel: ata4.01: configured for PIO4
Sep  4 12:57:30 nelson kernel: ata4: EH complete
Sep  4 12:58:00 nelson kernel: ata4.01: limiting speed to PIO3
Sep  4 12:58:00 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:58:00 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:58:00 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:58:00 nelson kernel: ata4: soft resetting port
Sep  4 12:58:00 nelson kernel: ata4.01: configured for PIO3
Sep  4 12:58:00 nelson kernel: ata4: EH complete
Sep  4 12:58:30 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:58:30 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:58:30 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:58:30 nelson kernel: ata4: soft resetting port
Sep  4 12:58:31 nelson kernel: ata4.01: configured for PIO3
Sep  4 12:58:31 nelson kernel: ata4: EH complete
Sep  4 12:59:01 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:59:01 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:59:01 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:59:01 nelson kernel: ata4: soft resetting port
Sep  4 12:59:02 nelson kernel: ata4.01: configured for PIO3
Sep  4 12:59:02 nelson kernel: ata4: EH complete
Sep  4 12:59:32 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:59:32 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 12:59:32 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:59:32 nelson kernel: ata4: soft resetting port
Sep  4 12:59:32 nelson kernel: ata4.01: configured for PIO3
Sep  4 12:59:32 nelson kernel: ata4: EH complete
Sep  4 12:59:32 nelson kernel: sr0: CDROM (ioctl) error, command: Test  
Unit Ready 00 00 00 00 00 00
Sep  4 12:59:32 nelson kernel: sr: Sense Key : Aborted Command  
[current] [descriptor]
Sep  4 12:59:32 nelson kernel: sr: Add. Sense: No additional sense information
Sep  4 12:59:42 nelson kernel: ata4.01: limiting speed to PIO0
Sep  4 12:59:42 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:59:42 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:59:42 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:59:42 nelson kernel: ata4: soft resetting port
Sep  4 12:59:43 nelson kernel: ata4.01: configured for PIO0
Sep  4 12:59:43 nelson kernel: ata4: EH complete
Sep  4 12:59:53 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 12:59:53 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 12:59:53 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 12:59:53 nelson kernel: ata4: soft resetting port
Sep  4 12:59:54 nelson kernel: ata4.01: configured for PIO0
Sep  4 12:59:54 nelson kernel: ata4: EH complete
Sep  4 13:00:04 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 13:00:04 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 13:00:04 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 13:00:04 nelson kernel: ata4: soft resetting port
Sep  4 13:00:04 nelson kernel: ata4.01: configured for PIO0
Sep  4 13:00:04 nelson kernel: ata4: EH complete
Sep  4 13:00:14 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 13:00:14 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 13:00:14 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 13:00:14 nelson kernel: ata4: soft resetting port
Sep  4 13:00:15 nelson kernel: ata4.01: configured for PIO0
Sep  4 13:00:15 nelson kernel: ata4: EH complete
Sep  4 13:00:25 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 13:00:25 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 13:00:25 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 13:00:25 nelson kernel: ata4: soft resetting port
Sep  4 13:00:25 nelson kernel: ata4.01: configured for PIO0
Sep  4 13:00:25 nelson kernel: ata4: EH complete
Sep  4 13:00:35 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 13:00:35 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x1e data 0
Sep  4 13:00:35 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 13:00:35 nelson kernel: ata4: soft resetting port
Sep  4 13:00:36 nelson kernel: ata4.01: configured for PIO0
Sep  4 13:00:36 nelson kernel: ata4: EH complete
Sep  4 13:00:36 nelson kernel: sr 3:0:1:0: ioctl_internal_command  
return code = 8000002
Sep  4 13:00:36 nelson kernel:    : Sense Key : Aborted Command  
[current] [descriptor]
Sep  4 13:00:36 nelson kernel:    : Add. Sense: No additional sense  
information
Sep  4 13:01:08 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 13:01:08 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 13:01:08 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 13:01:08 nelson kernel: ata4: soft resetting port
Sep  4 13:01:09 nelson kernel: ata4.01: configured for PIO0
Sep  4 13:01:09 nelson kernel: ata4: EH complete
Sep  4 13:01:39 nelson kernel: ata4.01: exception Emask 0x0 SAct 0x0  
SErr 0x0 action 0x2 frozen
Sep  4 13:01:39 nelson kernel: ata4.01: cmd  
a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0
Sep  4 13:01:39 nelson kernel:          res  
40/00:03:00:00:20/00:00:00:00:00/b0 Emask 0x4 (timeout)
Sep  4 13:01:39 nelson kernel: ata4: soft resetting port
Sep  4 13:01:39 nelson kernel: ata4.01: configured for PIO0

Thanks,
Fred

Re: pata_via cd/dvd timeout problems

[richard kennedy]

On Tue, 2007-09-04 at 17:40 -0700, Vlad wrote:
> Hi,
> 
> > I have both a dvd RW drive & a cd rom drive connected
> > the second ide interface on my motherboard with a via
> > chipset, using pata_via I see timeout messages in the
> > log & after some time both drives lockup and are
> > unable to mount any disks. 
> 
> I would suggest trying the following things:
> 
> 1) Add both drives ("_NEC DVD_RW ND-3520" and "TSSTcorpDVD-ROM
> TS-H352A") to ata_device_blacklist in drivers/ata/libata-core.c using
> the ATA_HORKAGE_NODMA and ATA_HORKAGE_MAX_SEC_128 keywords and then
> recompile the kernel.
> 
> 2) Move the CD and DVD RW drives to a computer with another chipset to
> determine whether they or the chipset are to blame.
> 
> Vlad
> 
Thanks for the suggestion I'll give it a try.

Unfortunately I don't have another machine to try these drives in. But
they both worked OK under the old ide code -- the problems only started
with the move to libata.

I guess the commands timing out are udev probing to see if a disk has
been inserted ?

thanks
Richard

Re: pata_via cd/dvd timeout problems

[Alan Cox]

> Unfortunately I don't have another machine to try these drives in. But
> they both worked OK under the old ide code -- the problems only started
> with the move to libata.
> 
> I guess the commands timing out are udev probing to see if a disk has
> been inserted ?

Probably. If you can file a bug in bugzilla and assign it to me I'll take
a look at this after the kernel summit. There are one or two reports with
pata_via and ATAPI (ie CD) that look similar.

Re: pata_via cd/dvd timeout problems

[richard kennedy]

On Thu, 2007-09-06 at 01:33 +0100, Alan Cox wrote:
> > Unfortunately I don't have another machine to try these drives in. But
> > they both worked OK under the old ide code -- the problems only started
> > with the move to libata.
> > 
> > I guess the commands timing out are udev probing to see if a disk has
> > been inserted ?
> 
> Probably. If you can file a bug in bugzilla and assign it to me I'll take
> a look at this after the kernel summit. There are one or two reports with
> pata_via and ATAPI (ie CD) that look similar.

Hi Alan,
I've created a bug for this

http://bugzilla.kernel.org/show_bug.cgi?id=8986

but somehow I messed up and it didn't get assigned to you and now I
can't change who it's assigned too. Can you take ownership or should I
delete it and start again ?
sorry
Richard
 

Re: pata_via cd/dvd timeout problems

[richard kennedy]

On Thu, 2007-09-06 at 01:33 +0100, Alan Cox wrote:

> Probably. If you can file a bug in bugzilla and assign it to me I'll take
> a look at this after the kernel summit. There are one or two reports with
> pata_via and ATAPI (ie CD) that look similar.

Hi Alan,
your [PATCH] libata: Set transfer sizes properly for ATAPI fixes this
for me.
I've been running 2.6.23-rc7 + your patch since yesterday evening and
have not seen any timeout messages. I can mount and read disks on either
drive with no problems. 

thanks for tracking this down  
Richard

Re: pata_via cd/dvd timeout problems

[Alan Cox]

On Fri, 21 Sep 2007 09:53:05 +0100
richard kennedy <richard@rsk.demon.co.uk> wrote:

> On Thu, 2007-09-06 at 01:33 +0100, Alan Cox wrote:
> 
> > Probably. If you can file a bug in bugzilla and assign it to me I'll take
> > a look at this after the kernel summit. There are one or two reports with
> > pata_via and ATAPI (ie CD) that look similar.
> 
> Hi Alan,
> your [PATCH] libata: Set transfer sizes properly for ATAPI fixes this
> for me.

Yay - thanks for letting me know and for testing it.

Alan

Re: pata_via cd/dvd timeout problems

[richard kennedy]

On Fri, 2007-09-21 at 16:24 +0100, Alan Cox wrote:
> On Fri, 21 Sep 2007 09:53:05 +0100
> richard kennedy <richard@rsk.demon.co.uk> wrote:
> 
> > On Thu, 2007-09-06 at 01:33 +0100, Alan Cox wrote:
> > 
> > > Probably. If you can file a bug in bugzilla and assign it to me I'll take
> > > a look at this after the kernel summit. There are one or two reports with
> > > pata_via and ATAPI (ie CD) that look similar.
> > 
> > Hi Alan,
> > your [PATCH] libata: Set transfer sizes properly for ATAPI fixes this
> > for me.
> 
> Yay - thanks for letting me know and for testing it.
> 
> Alan
Hi Alan,
I've just been testing the git head v2.6.23-6636-g557ebb7 and there's
still a problem with this.

if I don't mount a disk I start getting timeout messages approximately 1
hour after boot :-
...
Oct 22 15:08:31 castor kernel: pata_via 0000:00:0f.1: version 0.3.2
Oct 22 15:08:31 castor kernel: scsi2 : pata_via
Oct 22 15:08:31 castor kernel: scsi3 : pata_via
...
Oct 22 15:08:31 castor kernel: ata4.00: ATAPI: _NEC DVD_RW ND-3520A, 1.04, max UDMA/33
Oct 22 15:08:31 castor kernel: ata4.01: ATAPI: TSSTcorpDVD-ROM TS-H352A, TS03, max UDMA/33
Oct 22 15:08:32 castor kernel: ata4.00: configured for UDMA/33
Oct 22 15:08:32 castor kernel: ata4.01: configured for UDMA/33
...
Oct 22 15:59:10 castor kernel: ata4.01: qc timeout (cmd 0xa0)
Oct 22 15:59:10 castor kernel: ata4.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Oct 22 15:59:10 castor kernel: ata4.01: cmd a0/00:00:00:08:00/00:00:00:00:00/b0 tag 0 cdb 0x25 data 8 in
Oct 22 15:59:10 castor kernel:          res 51/20:03:00:00:00/00:00:00:00:00/b0 Emask 0x5 (timeout)
Oct 22 15:59:10 castor kernel: ata4.01: status: { DRDY ERR }
Oct 22 15:59:10 castor kernel: ata4: soft resetting link
Oct 22 15:59:11 castor kernel: ata4.00: configured for UDMA/33
Oct 22 15:59:11 castor kernel: ata4.01: configured for UDMA/33
Oct 22 15:59:11 castor kernel: ata4: EH complete

then repeats 

Oct 22 16:09:57 castor kernel: ata4.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Oct 22 16:09:57 castor kernel: ata4.01: cmd a0/00:00:00:00:00/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0 
Oct 22 16:09:57 castor kernel:          res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
Oct 22 16:09:57 castor kernel: ata4.01: status: { DRDY }
Oct 22 16:09:57 castor kernel: ata4: soft resetting link
Oct 22 16:09:57 castor kernel: ata4.00: configured for UDMA/33
Oct 22 16:09:58 castor kernel: ata4.01: configured for UDMA/33
Oct 22 16:09:58 castor kernel: ata4: EH complete

and keeps on getting reset trying different speeds

Oct 22 17:37:57 castor kernel: ata4.00: limiting speed to PIO0
Oct 22 17:37:57 castor kernel: ata4.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Oct 22 17:37:57 castor kernel: ata4.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 
Oct 22 17:37:57 castor kernel:          res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
Oct 22 17:37:57 castor kernel: ata4.00: status: { DRDY }
Oct 22 17:37:57 castor kernel: ata4: soft resetting link
Oct 22 17:37:57 castor kernel: ata4.00: configured for PIO0
Oct 22 17:37:57 castor kernel: ata4.01: configured for UDMA/25
Oct 22 17:37:57 castor kernel: ata4: EH complete

On a fresh boot if I mount a cd access it then unmount it, the timeouts
start within about 5 minutes of the unmount

Oct 23 09:11:46 castor hald: unmounted /dev/scd0 from '/media/Disgo' on behalf of uid 500
Oct 23 09:16:52 castor kernel: ata4.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Oct 23 09:16:52 castor kernel: ata4.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0x0 data 0 
Oct 23 09:16:52 castor kernel:          res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
Oct 23 09:16:52 castor kernel: ata4.00: status: { DRDY }
Oct 23 09:16:52 castor kernel: ata4: soft resetting link
Oct 23 09:16:53 castor kernel: ata4.00: configured for UDMA/33
Oct 23 09:16:53 castor kernel: ata4.01: configured for UDMA/33
Oct 23 09:16:53 castor kernel: ata4: EH complete
Oct 23 09:19:38 castor kernel: ata4.00: qc timeout (cmd 0xa0)
Oct 23 09:19:39 castor kernel: ata4.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Oct 23 09:19:39 castor kernel: ata4.00: cmd a0/00:00:00:0c:00/00:00:00:00:00/a0 tag 0 cdb 0x43 data 12 in
Oct 23 09:19:39 castor kernel:          res 51/24:03:00:0c:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
Oct 23 09:19:39 castor kernel: ata4.00: status: { DRDY ERR }
Oct 23 09:19:39 castor kernel: ata4: soft resetting link
Oct 23 09:19:39 castor kernel: ata4.00: configured for UDMA/33
Oct 23 09:19:39 castor kernel: ata4.01: configured for UDMA/33
Oct 23 09:19:39 castor kernel: ata4: EH complete
etc


Richard