readcd hangs in blk_execute_rq

readcd hangs in blk_execute_rq

[Meelis Roos]

I'm trying to readcd a cd, in 2.6.9+todays BK snapshot.

I got an error the first time so I started it (readcd dev=/dev/hdc)
the second time and chose c2scan. This resulted in the messages
...
end:    328460
C2 in sector: 1864 first at byte: 2256 (0xF0) total:   72 errors
C2 in sector: 1865 first at byte:   12 (0x0F) total: 2335 errors
addr:     2499 cnt: 49

And here it hangs. ps shows readcd is in D state, in blk_execute_rq.
dmesg shows lines of

hdc: lost interrupt

every no and then.

This a IDE CD on Intel ICH2 ide controller:

ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
ICH2: IDE controller at PCI slot 0000:00:1f.1
ICH2: chipset revision 2
ICH2: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0xffa0-0xffa7, BIOS settings: hda:DMA, hdb:pio
    ide1: BM-DMA at 0xffa8-0xffaf, BIOS settings: hdc:DMA, hdd:pio

hdc: CDU5211, ATAPI CD/DVD-ROM drive
hdc: ATAPI 52X CD-ROM drive, 120kB Cache, UDMA(33)

And after every boot it gets DMA timeout on first read and switches to
PIO mode and works fine there reading data cd-s (even browsing the same
CD):

ide-cd: cmd 0x28 timed out
hdc: DMA interrupt recovery
hdc: lost interrupt
hdc: status timeout: status=0xd0 { Busy }
hdc: status timeout: error=0x00
hdc: DMA disabled
hdc: drive not ready for command
hdc: ATAPI reset complete


-- 
Meelis Roos (mroos@linux.ee)

Re: readcd hangs in blk_execute_rq

[Jens Axboe]

On Thu, Oct 21 2004, Meelis Roos wrote:
> I'm trying to readcd a cd, in 2.6.9+todays BK snapshot.
> 
> I got an error the first time so I started it (readcd dev=/dev/hdc)
> the second time and chose c2scan. This resulted in the messages
> ...
> end:    328460
> C2 in sector: 1864 first at byte: 2256 (0xF0) total:   72 errors
> C2 in sector: 1865 first at byte:   12 (0x0F) total: 2335 errors
> addr:     2499 cnt: 49
> 
> And here it hangs. ps shows readcd is in D state, in blk_execute_rq.
> dmesg shows lines of
> 
> hdc: lost interrupt
> 
> every no and then.
> 
> This a IDE CD on Intel ICH2 ide controller:
> 
> ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
> ICH2: IDE controller at PCI slot 0000:00:1f.1
> ICH2: chipset revision 2
> ICH2: not 100% native mode: will probe irqs later
>     ide0: BM-DMA at 0xffa0-0xffa7, BIOS settings: hda:DMA, hdb:pio
>     ide1: BM-DMA at 0xffa8-0xffaf, BIOS settings: hdc:DMA, hdd:pio
> 
> hdc: CDU5211, ATAPI CD/DVD-ROM drive
> hdc: ATAPI 52X CD-ROM drive, 120kB Cache, UDMA(33)
> 
> And after every boot it gets DMA timeout on first read and switches to
> PIO mode and works fine there reading data cd-s (even browsing the same
> CD):
> 
> ide-cd: cmd 0x28 timed out
> hdc: DMA interrupt recovery
> hdc: lost interrupt
> hdc: status timeout: status=0xd0 { Busy }
> hdc: status timeout: error=0x00
> hdc: DMA disabled
> hdc: drive not ready for command
> hdc: ATAPI reset complete

Did it previously work reliably with dma (which kernel)? Does it now
work reliably without dma now? Do send your entire dmesg after a boot
too, btw.

-- 
Jens Axboe

Re: readcd hangs in blk_execute_rq

[Meelis Roos]

> > And here it hangs. ps shows readcd is in D state, in blk_execute_rq.
> > dmesg shows lines of
> >
> > hdc: lost interrupt

Meanwhile I found out that if I eject the CD by pressing button, it
resumes its work and reports error to the user process.

> > ide-cd: cmd 0x28 timed out
> > hdc: DMA interrupt recovery
> > hdc: lost interrupt
> > hdc: status timeout: status=0xd0 { Busy }
> > hdc: status timeout: error=0x00
> > hdc: DMA disabled
> > hdc: drive not ready for command
> > hdc: ATAPI reset complete
>
> Did it previously work reliably with dma (which kernel)? Does it now
> work reliably without dma now? Do send your entire dmesg after a boot
> too, btw.

It worked in earlier 2.4 kernels (2.4.18?) with DMA - I don't remember
if it had some reliability problems. Since then, it's no dma. We have 3
such computers here (Intel D816EEA2 mainboard, this specific Sony CDrom)
and they all behave the same.

-- 
Meelis Roos (mroos@linux.ee)

Re: readcd hangs in blk_execute_rq

[Jens Axboe]

On Thu, Oct 21 2004, Meelis Roos wrote:
> > > And here it hangs. ps shows readcd is in D state, in blk_execute_rq.
> > > dmesg shows lines of
> > >
> > > hdc: lost interrupt
> 
> Meanwhile I found out that if I eject the CD by pressing button, it
> resumes its work and reports error to the user process.
> 
> > > ide-cd: cmd 0x28 timed out
> > > hdc: DMA interrupt recovery
> > > hdc: lost interrupt
> > > hdc: status timeout: status=0xd0 { Busy }
> > > hdc: status timeout: error=0x00
> > > hdc: DMA disabled
> > > hdc: drive not ready for command
> > > hdc: ATAPI reset complete
> >
> > Did it previously work reliably with dma (which kernel)? Does it now
> > work reliably without dma now? Do send your entire dmesg after a boot
> > too, btw.
> 
> It worked in earlier 2.4 kernels (2.4.18?) with DMA - I don't remember
> if it had some reliability problems. Since then, it's no dma. We have 3
> such computers here (Intel D816EEA2 mainboard, this specific Sony CDrom)
> and they all behave the same.

2.4.x never used dma for this operation. Does 2.6.9 work if you turn off
dma first?

-- 
Jens Axboe

Re: readcd hangs in blk_execute_rq

[Meelis Roos]

> > > > ide-cd: cmd 0x28 timed out
> > > > hdc: DMA interrupt recovery
> > > > hdc: lost interrupt
> > > > hdc: status timeout: status=0xd0 { Busy }
> > > > hdc: status timeout: error=0x00
> > > > hdc: DMA disabled
> > > > hdc: drive not ready for command
> > > > hdc: ATAPI reset complete

> > It worked in earlier 2.4 kernels (2.4.18?) with DMA - I don't remember
> > if it had some reliability problems. Since then, it's no dma. We have 3
> > such computers here (Intel D816EEA2 mainboard, this specific Sony CDrom)
> > and they all behave the same.
>
> 2.4.x never used dma for this operation. Does 2.6.9 work if you turn off
> dma first?

I have not tried this operation before. Reading data disks with DMA
worked and that's what I have used. I did read the same disk with
readdisk subcommand on readcd currently, it was successful until the end
of disk (6xx MB - maybe the end of the disk).

Will try it with turning DMA off first.

-- 
Meelis Roos (mroos@linux.ee)

Re: readcd hangs in blk_execute_rq

[Jens Axboe]

On Thu, Oct 21 2004, Meelis Roos wrote:
> > > > > ide-cd: cmd 0x28 timed out
> > > > > hdc: DMA interrupt recovery
> > > > > hdc: lost interrupt
> > > > > hdc: status timeout: status=0xd0 { Busy }
> > > > > hdc: status timeout: error=0x00
> > > > > hdc: DMA disabled
> > > > > hdc: drive not ready for command
> > > > > hdc: ATAPI reset complete
> 
> > > It worked in earlier 2.4 kernels (2.4.18?) with DMA - I don't remember
> > > if it had some reliability problems. Since then, it's no dma. We have 3
> > > such computers here (Intel D816EEA2 mainboard, this specific Sony CDrom)
> > > and they all behave the same.
> >
> > 2.4.x never used dma for this operation. Does 2.6.9 work if you turn off
> > dma first?
> 
> I have not tried this operation before. Reading data disks with DMA
> worked and that's what I have used. I did read the same disk with
> readdisk subcommand on readcd currently, it was successful until the end
> of disk (6xx MB - maybe the end of the disk).

Yes you are right, readcd should use dma.

> Will try it with turning DMA off first.

Ok

-- 
Jens Axboe

Re: readcd hangs in blk_execute_rq

[Meelis Roos]

> Does 2.6.9 work if you turn off
> dma first?

Turned DMA off with hdparm -d 0 /dev/hdc, still the same.
Turned ATAPI DMA support off completely (activated "Use DMA only for
disks" compile option), still the same half-hang.

BTW, the hang sector is different all the time - it varies from 980 to
3200 so far.

-- 
Meelis Roos (mroos@linux.ee)

Re: readcd hangs in blk_execute_rq

[Jens Axboe]

On Thu, Oct 21 2004, Meelis Roos wrote:
> > Does 2.6.9 work if you turn off
> > dma first?
> 
> Turned DMA off with hdparm -d 0 /dev/hdc, still the same.
> Turned ATAPI DMA support off completely (activated "Use DMA only for
> disks" compile option), still the same half-hang.
> 
> BTW, the hang sector is different all the time - it varies from 980 to
> 3200 so far.

Can I talk you into trying to find out when this broke? You mention
2.4.18 as working, did 2.4.19 break? Narrowing this down as much as
possible would be very helpful.

-- 
Jens Axboe

Re: readcd hangs in blk_execute_rq

[Meelis Roos]

> Can I talk you into trying to find out when this broke? You mention
> 2.4.18 as working, did 2.4.19 break? Narrowing this down as much as
> possible would be very helpful.

Might try on the weekend if I get time.

-- 
Meelis Roos (mroos@linux.ee)

Re: readcd hangs in blk_execute_rq

[Meelis Roos]

> > Turned DMA off with hdparm -d 0 /dev/hdc, still the same.
> > Turned ATAPI DMA support off completely (activated "Use DMA only for
> > disks" compile option), still the same half-hang.
>
> Can I talk you into trying to find out when this broke? You mention
> 2.4.18 as working, did 2.4.19 break? Narrowing this down as much as
> possible would be very helpful.

OK, did some testing.

2.4.18, 2.4.19 and 2.4.20 are the same - mostly working. This means that
it reads non-broken data CD-s with DMA with no problems, but it loses an
interrupt and disables DMA with a faulty data CD (dmesg below).

The IDE changes in 2.4.21-pre1 cause DMA to fail at first read attempt
and all later kernels behave the same.

The dmesg from 2.4.18 in case of CD read error (with a known faulty cd):

hdc: command error: status=0x51 { DriveReady SeekComplete Error }
hdc: command error: error=0x54
end_request: I/O error, dev 16:00 (hdc), sector 1274020
ide_dmaproc: chipset supported ide_dma_lostirq func only: 13
hdc: lost interrupt
hdc: status timeout: status=0xd0 { Busy }
hdc: DMA disabled
hdc: drive not ready for command
hdc: ATAPI reset complete


-- 
Meelis Roos (mroos@linux.ee)

Re: readcd hangs in blk_execute_rq

[Jens Axboe]

On Mon, Oct 25 2004, Meelis Roos wrote:
> > > Turned DMA off with hdparm -d 0 /dev/hdc, still the same.
> > > Turned ATAPI DMA support off completely (activated "Use DMA only for
> > > disks" compile option), still the same half-hang.
> >
> > Can I talk you into trying to find out when this broke? You mention
> > 2.4.18 as working, did 2.4.19 break? Narrowing this down as much as
> > possible would be very helpful.
> 
> OK, did some testing.
> 
> 2.4.18, 2.4.19 and 2.4.20 are the same - mostly working. This means that
> it reads non-broken data CD-s with DMA with no problems, but it loses an
> interrupt and disables DMA with a faulty data CD (dmesg below).
> 
> The IDE changes in 2.4.21-pre1 cause DMA to fail at first read attempt
> and all later kernels behave the same.
> 
> The dmesg from 2.4.18 in case of CD read error (with a known faulty cd):
> 
> hdc: command error: status=0x51 { DriveReady SeekComplete Error }
> hdc: command error: error=0x54
> end_request: I/O error, dev 16:00 (hdc), sector 1274020
> ide_dmaproc: chipset supported ide_dma_lostirq func only: 13
> hdc: lost interrupt
> hdc: status timeout: status=0xd0 { Busy }
> hdc: DMA disabled
> hdc: drive not ready for command
> hdc: ATAPI reset complete

Alan, any ideas? IIRC, the 2.4.21-pre1 huge ide update is all your
doing.

-- 
Jens Axboe