Messages in this thread | | | From | Alan Chandler <> | Subject | ide-cd problem revisited - more brainpower needed | Date | Fri, 10 Dec 2004 21:32:41 +0000 |
| |
A couple of weeks ago, I posted in relation to a problem I have burning CDs.
Ever since, I have solidly been looking for what might be the cause of the problem, and although I have identified what goes wrong, I can not see why that should be the case or whether it can be corrected. Hence the request here.
All the above output is a result of the command (as root) using linux 2.6.10-rc2 (with acpi turned off to avoid that bug)·
cdrecord -dev /dev/hdc blank=fast
The device is identified as CW078D CD-R/RW a generic no name rewriter.
There is also a DVD reader on this ide channel (/dev/hdd) but it is not doing anything through out the testing. I have tried removing it, 2.6.9 still gives the same symptoms (although I have no printk's in it), 2.6.10-rc panics during boot. ...
On Tuesday 30 November 2004 08:59, Alan Chandler wrote: > On Tuesday 23 November 2004 21:49, Alan Chandler wrote: > > > Firstly, the symptoms are the same between 2.6.9 and 2.6.10-rc2. The > > halt seem to always be in exactly the same place. If it was a timing > > problem I would have thought it would have varied. > > > > Secondly, the command before seems to have an expectation of a 2048 > > transfer rather than the 0 in the command, before the problem and then > > you get the strange DRQ=1 but 0 in the len register. > > > > Nov 23 20:37:33 kanger kernel: ide-cd:ide_do_rq_cdrom - cmd = 0x0 > > Nov 23 20:37:33 kanger kernel: ide-cd:cdrom_newpc_intr - cmd=0x0 > > stat=0x50 ireason=3 len=2048 rq len=0 > > Nov 23 20:37:33 kanger kernel: ide-cd:ide_do_rq_cdrom - cmd = 0x1b > > Nov 23 20:37:33 kanger kernel: ide-cd:cdrom_newpc_intr - cmd=0x1b > > stat=0x58 ireason=2 len=0 rq len=0
For the past couple of weeks I have been trying different things with printk statements to get to the bottom of what is actually happening - I have now got to the point where I do not know how to get more out of it, and the device is behaving so strangely that I am not sure how it ever worked - although it does under linux 2.4 series.
The lines above are misleading - because as can be seen from below, interrupts occur after the command has supposedly finished - and the next request has already arrived. I have added a msleep(10) in the back-end of sg_io so that there is a short delay before cdrecord gets control back, and its therefore possible to see the interrupts beyond the end of processing and before the next command starts. Before I did that, I think the commands were overlapping in some way - and therefore the symptoms were not visable immediately.
Comments are inserted into the output to my log from printk statements below. the "time" is the current value of "jiffies". I have also removed some of the "bodges" in ide_wait_stat to loop for 10uS - Does not appear necessary and I did not want to confuse the issue with them. Alan Cox's patch and various other ndelay(400) statements are in to ensure that nowhere can a statement to clear INTR re-interrupt by the command exiting too fast (although in most cases it appears to make no difference if they are there or not).
Dec 10 20:00:54 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom - do block pc Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_start_packet_command with feature reg=0x0
I check feature reg here which indicates whether a dma (or in this case not) is about to happen
Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_do_newpc_cont at time=4294941469 for cmd=0x0
This is routine called after issuing the PACKET command to load the packet into the device.
Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941469 with cmd=0x0 stat=0x50, req len=0, len=0, ireason=3
This is the interrupt at command completion - showing the length expected in the request and the len read from the device at this point. Its after cdrom_decode_status has read and checked that there is not error. "stat" is the value returned in the status register.
Dec 10 20:00:54 kanger kernel: scsi_ioctl:sg_io completed in time 0
This is back in the sg_io route, with the calculated time (in jiffies) to execute the command.
Dec 10 20:00:54 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom - do block pc Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_start_packet_command with feature reg=0x0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_do_newpc_cont at time=4294941480 for cmd=0x5a Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941481 with cmd=0x5a stat=0x58, req len=60, len=60, ireason=2 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941481 with cmd=0x5a stat=0x50, req len=0, len=60, ireason=3 Dec 10 20:00:54 kanger kernel: scsi_ioctl:sg_io completed in time 1
This is similar, with a pio data transfer. Note how cdrom_newpc_intr is called twice, once when the device is ready for the transfer, and then at the end of the transfer (command complete).
Dec 10 20:00:54 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom - do block pc Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_start_packet_command with feature reg=0x0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_do_newpc_cont at time=4294941492 for cmd=0x0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941492 with cmd=0x0 stat=0x50, req len=0, len=0, ireason=3 Dec 10 20:00:54 kanger kernel: scsi_ioctl:sg_io completed in time 0 Dec 10 20:00:54 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom - do block pc Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_start_packet_command with feature reg=0x0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_do_newpc_cont at time=4294941503 for cmd=0x0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941503 with cmd=0x0 stat=0x50, req len=0, len=0, ireason=3 Dec 10 20:00:54 kanger kernel: scsi_ioctl:sg_io completed in time 0 Dec 10 20:00:54 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom - do block pc Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_start_packet_command with feature reg=0x0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_do_newpc_cont at time=4294941514 for cmd=0x55 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941514 with cmd=0x55 stat=0x58, req len=60, len=60, ireason=0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941516 with cmd=0x55 stat=0x50, req len=0, len=60, ireason=3 Dec 10 20:00:54 kanger kernel: scsi_ioctl:sg_io completed in time 2 Dec 10 20:00:54 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom - do block pc Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_start_packet_command with feature reg=0x0 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_do_newpc_cont at time=4294941527 for cmd=0x3c Dec 10 20:00:54 kanger kernel: cmd[0]=0x3c Dec 10 20:00:54 kanger kernel: cmd[1]=0x0 Dec 10 20:00:54 kanger kernel: cmd[2]=0x0 Dec 10 20:00:54 kanger kernel: cmd[3]=0x0 Dec 10 20:00:54 kanger kernel: cmd[4]=0x0 Dec 10 20:00:54 kanger kernel: cmd[5]=0x0 Dec 10 20:00:54 kanger kernel: cmd[6]=0x0 Dec 10 20:00:54 kanger kernel: cmd[7]=0x0 Dec 10 20:00:54 kanger kernel: cmd[8]=0x4 Dec 10 20:00:54 kanger kernel: cmd[9]=0x0
This is the first time something goes wrong - and its always on this READ BUFFER command (0x3c). I therefore dump out the command at this stage - showing the internal length of 4 bytes, matching the len below.
Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941527 with cmd=0x3c stat=0x58, req len=4, len=4, ireason=2 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr done at time=4294941527 with cmd=0x3c stat=0x50, req len=0, len=4, ireason=3 Dec 10 20:00:54 kanger kernel: scsi_ioctl:sg_io completed in time 0
IO should be complete here - its the standard termination - but ...
Dec 10 20:00:54 kanger kernel: ide-io:ide_intr - seems we interrupted ourselves at time=4294941527, stat=0x58, ireason=0x2,len=4
This printk detects inside ide-io:ide_intr where it checks to see if a null handler is defined. It is, and so tries to wack the status register. I have added in code to not only do that, but if "ireason==2" to read in the data register "len" times (If I do not do this, the next command fails in ide_wait_stat failing to get a good status). There is also an added ndelay(400) here to ensure the interrupt does not remain pending after the return.
Dec 10 20:00:54 kanger kernel: ide-io:ide_intr - seems we interrupted ourselves at time=4294941527, stat=0x50, ireason=0x3,len=4 Dec 10 20:00:54 kanger kernel: ide-io:ide_intr - seems we interrupted ourselves at time=4294941527, stat=0x50, ireason=0x3,len=4
I am not sure why there are two more interrupts - in case I hadn't got a long enough delay I increased it from ndelay(400) to ndelay(800) but it made no difference.
As you can all of these at at the same jiffy (ie within 1 millisec) of each other. bits 6:5 of word 0 of the identify data is set to 10 (50uS) for length of time for command to complete.
However, eventually the command is seen to complete....
Dec 10 20:00:54 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom Dec 10 20:00:54 kanger kernel: ide-cd:ide_do_rw_cdrom - do block pc Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_start_packet_command with feature reg=0x1
The first time with dma.
Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_do_newpc_cont at time=4294941538 for cmd=0x3c Dec 10 20:00:54 kanger kernel: cmd[0]=0x3c Dec 10 20:00:54 kanger kernel: cmd[1]=0x0 Dec 10 20:00:54 kanger kernel: cmd[2]=0x0 Dec 10 20:00:54 kanger kernel: cmd[3]=0x0 Dec 10 20:00:54 kanger kernel: cmd[4]=0x0 Dec 10 20:00:54 kanger kernel: cmd[5]=0x0 Dec 10 20:00:54 kanger kernel: cmd[6]=0x0 Dec 10 20:00:54 kanger kernel: cmd[7]=0xfc Dec 10 20:00:54 kanger kernel: cmd[8]=0x0 Dec 10 20:00:54 kanger kernel: cmd[9]=0x0
With a lot larger transfer
Dec 10 20:00:54 kanger kernel: ide-dma:ide_dma_start - with command 0x8 Dec 10 20:00:54 kanger kernel: ide-cd:cdrom_newpc_intr - assuming just finished dma at time=4294941538 with cmd=0x3c, rq len=64512, stat=0x50 Dec 10 20:00:54 kanger kernel: scsi_ioctl:sg_io completed in time 0 Dec 10 20:00:59 kanger kernel: scsi-ioctl: SG_IO Dec 10 20:00:59 kanger kernel: ide-iops:ide_wait_stat - was busy when I arrived
What this means is that when ide_wait_stat was entered the BSY bit was set on the first time the routine is entered. Given the timing, it has in fact had BSY showing with no sign of it clearing for a full 5 secs.
Dec 10 20:00:59 kanger kernel: hdc: status timeout: status=0xd0 { Busy } Dec 10 20:00:59 kanger kernel: hdc: status timeout: error=0xd0LastFailedSense 0x0d Dec 10 20:00:59 kanger kernel: hdc: DMA disabled Dec 10 20:00:59 kanger kernel: hdc: drive not ready for command
And so we eventually fail completely.
This pattern is fully predictable - its not a timing issue that varies from run to run - every time exactly the same thing happens.
So what do I do next? Why would the hardware work this way - is it a bug in the firmware?, is there a subtle timing problem causing interrupts to re-enter... should I just junk the hardware and start again? Help!
-- Alan Chandler alan@chandlerfamily.org.uk First they ignore you, then they laugh at you, then they fight you, then you win. --Gandhi - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
| |