Created attachment 11113 [details]
Complete dmesg output.

Created attachment 11114 [details]
lspci -vvv output

Created attachment 11115 [details]
cdrecord dev=/dev/sr0 -inq -vvVV output

> Judging that the dmesg output is exactly the same as bug #8244,
> I think the two bugs are somehow related.

The patch for bug 8244 is in 2.6.21-rc6.
Could you please build and reboot to 2.6.21-rc6 and see if the problem persists?

Seeing the CVS of archlinux - http://cvs.archlinux.org/cgi-
bin/viewcvs.cgi/kernels/kernel26/?cvsroot=Current&only_with_tag=CURRENT - that 
patch has been applied, "libata-eh.patch". I will still try kernel 2.6.21-rc6, 
but is there any way to manually "induce" or "stimulate" the bug. Waiting for 
the bug to occur is unpredictable at times.

> I will still try kernel 2.6.21-rc6, 

Yes, please.

> but is there any way to manually "induce" or "stimulate" the bug.
>  Waiting for the bug to occur is unpredictable at times.

This bug looks different from bug #8244, which always happens during boot.
Currently I guess the only way is be patient and capture the dmesg when the 
problem happens.

Created attachment 11117 [details]
Complete dmesg on kernel 2.6.21-rc6

The above attachment is when the pc was running on 2.6.21-rc6, with no other
patches applied. Please tell me if I need to attach any other information. The
cdrecord output remains the same.

Any updates, Albert ?

> Any updates, Albert?

1. This bug is not bug 8244.
2. From the dmesg, libata can initialize without problem during boot.
3. The "qc timeout message" might be caused by lost irq or something else.
From both dmesgs, the problem happened when "cdb 0x0" (TEST UNIT READY) was 
issued to the drive.

Rohan,
Since the machine is at your hand, could you please

1. try if any reliable method to reproduce the problem?
   e.g. "dd if=/dev/scd0 | md5sum" 
   e.g. stress both the hard drive and the dvd drive at the same time.
   e.g. Leave a cd in the dvd drive and check if the problem disappears.

2. observe any other symptom or clue when such "qc timeout" happens?
   Say, the system appears to be frozen? mouse/key board not responding for a 
moment? The LED of the USB web cam flashing?

3. Collect more dmesgs when such timeout happens. We can check whether this is 
related to specific command.

Yes, keyboard and mouse stop responding when this happens. The Webcam light does
not flash, though. All the applications stop responding, but resume from the
same point. E.g. if i am playing music when this happens, music stops
playing,but resumes from the same point. I will try to get more dmesg's.

Created attachment 11153 [details]
One more :)

http://bugzilla.kernel.org/attachment.cgi?id=11153&action=view

This dmesg was captured when i used the command "eject" to eject the CD. The
media in CD Drive was a cdrw which has been working great. I had done the done
md5sum command you suggested, but it worked perfectly and no errors during that
time.

This time, during eject, as you can see, I got some buffer IO errors in dmesg.
And after eject, when i inserted the tray back in (manually), the usual symptoms
- pc lag, no kbd/mouse, and the error in dmesg. 

Also, I don't know whether it is related or no - but while the 30 second lag, I
had left mplayer on; the music started playing suddenly at HIGH volume for short
intervals. And then after 30 secs it was playing normally.

I guess maybe something occupied the CPU. Say, a long busy delay in the 
interrupt handler or the device appears to be busy when the interrupt happens.

I'll be out for several days and be back on 4/21. Will try to make a debug 
patch to check the activity in the irq handler when back.

OK, I will try to investigate and find some way of reliably reproducing the
error till then :)

Attaching a dmesg taken on ubuntu 7.04 feisty. It has libata enabled, too.

Created attachment 11248 [details]
Dmesg on ubuntu 7.04

Maybe this gives more clues ?

Created attachment 11253 [details]
dmesg output on 2.6.21-rc7

Just for the record, problem is not solved in 2.6.21-rc7 :)

Hi albert,

I noticed something. From a day or two I've intentionally kept a CD in the drive
at all times. All during that period, I never had a single problem. 

Hope that helps,
Rohan.

More data point: Both the hard drive and the DVD drive are PATA, connected to 
the ICH7 IDE port in master/slave configuration.

From the dmesg, the timeout happens on command 0x43, 0x1e, 0x0 and 0x25.
=> Looks not related to specific command.

> From a day or two I've intentionally kept a CD in the drive
> at all times. All during that period, I never had a single problem.

So, if no periodic commands issued to the DVD drive, then no timeout.
=> This looks like something related to the DVD device. Maybe drive did not 
response to the command, lost irq or something...

Hi Rohan,

Could you please try updating the firmware of the DVD drive first?
On the TSST website, there is a new firmware "SC03" for the TS-L632D drive, 
dated 2007-02-15:
http://www.samsungodd.com/eng/Firmware/liveupdate.asp

Let's see if firmware update can fix this problem...

Thanks a lot for pointing me to the update. I have updated to AC01 update, dated
01-Jan-07, because it is Acer OEM. If that does not work, I will update to the
SC03 Samsung firmware. After that, I'll comment whether it worked or no. 

Problem is not solved on upgrading the Acer firmware. Now I am going to upgrade
to the samsung SC03 firmware, to see if it helps.

I am attaching the dmesg on a kernel 2.6.20, on ubuntu install. Is that ok ? Or
do I still attach dmesg of 2.6.21, the released newest kernel ?

Created attachment 11369 [details]
dmesg after firmware upgrade to Acer AC01

So the problem occurs even after firmware upgrade to Acer AC01 version. Now I
will try upgrade to the Samsung SC03 version. 

http://www.toshibaer.com/firmware/index.php?path=TS-L632D/

It's unable to update to the SC03 firmware. The flashing utility says that "The
version of firmware selected is incompatible with your hardware." when I select
the SC03 update.

However, right now, my drive is updated to the latest Acer OEM upgrade - AC01,
released on 20-Jan-07.

Please tell me the next step to take :)

Created attachment 11370 [details]
Error occurs on 2.6.21.1

OK, the error occurred on a custom compiled kernel 2.6.21.1 which has no
outside patches applied. The firmware, as I said, is updated to the latest
provided by Acer.

I have a Acer TravelMate 5610 laptop with a TSSTcorp CD/DVDW TS-L632D using a 
shared PATA bus with the WDC WD1200UE-22K hard drive and I have experienced 
this same problem.

After finding that hald was causing the timeout issue and after disabling hald 
the timeouts stopped.
I had a look at the commands that hald was sending to the cdrom and then wrote 
a test program to determine the cause of the timeouts.

I've attached two test programs that I have created to isolate the calls and 
use of the cdrom device pertaining to this timeout issue.

The first test program, by calling the open and close command for the cdrom 
device every second, causes a timeout after a few hours of execution in an 
apparent random fashion.
This seems to be how hald currently queries the cdrom.
I have tested this code with the query commands included but they had no impact 
on it's ability to cause a timeout issue so I've dropped them from the test 
program.
It is my understanding that the cause of the timeout issue is related directly 
to the repeated calls to the open and close command when referencing a TSSTcorp 
CD/DVDW TS-L632D drive.

I have attached a second program to show that by keeping the cdrom device open 
and then repeatedly performing cdrom querying calls I have been unable to cause 
any cdrom timeouts events even after continuous running for many hours.

My conclusion is that the timeout is caused by the repeated use of the open 
and/or close commands on this cdrom device.

Created attachment 11390 [details]
dmesg output

Created attachment 11391 [details]
lspci -vvv output

Created attachment 11392 [details]
cdrecord dev=/dev/sr0 -inq -vvVV output

Created attachment 11393 [details]
cdstatus_1.c

This is the first test program.

Created attachment 11394 [details]
cdstatus_2.c

This is the second test program.

Matthew, I can confirm that the same program causes timeouts for me too. But
isn't the method used by HAL very crude ? I have no experience in hardware
related programming, but constantly pinging a cd-rom device to check for new
media seems strange. Also, would it not drain the laptop battery very fast ?

After doing some debugging in the kernel I've found that the timeouts seem to be
from the sr scsi cdrom driver always executing certain commands in certain
functions that should only be executed when media is in the drive.  In the
sr_media_changed function, it calls scsi_test_unit_ready which sets the changed
flag and returns 0 if the drive returns NOT_READY which my drive returns if no
media is in the drive.  This causes sr_cd_check and get_sectorsize to be called
on every call to sr_media_changed when no media is in the drive which causes the
drive to often timeout.  Also, in sr_release, sr_set_blocklength is called which
sometimes causes a timeout on my drive as well.

I looked through the code of the ide-cd driver and it looks like its
media_changed function doesn't changed flag if the drive returns NOT_READY. 
Even when a media change is detected it defers checking of multisession and
sectorsize info to the cdrom_read_toc function.

When I commented out these three calls, my test programs didn't cause a timeout
when no media was in the drive.

Perhaps now that libata supports PATA devices some of the code from the ide-cd
driver should be ported over to enhance either the sr driver or the Uniform
cdrom driver.

Created attachment 11569 [details]
A quick patch to try to workaround some of the cdrom timeouts.

Created attachment 11579 [details]
cdstatus_5.c

With the new changes, it looks like I'm still getting occasional timeouts from
TEST UNIT READY.  Here is my latest test program which just calls TEST UNIT
READY every second.

I have noticed that I seem to get more timeouts if I add lots of extra
debugging output to the cdrom driver which gets logged to the hard drive via
syslog.

Any updates ?

So, it seems somehow TEST UNIT ready triggered the timeiut.

Could you please turn on libata debug trace by
 - edit include/linux/libata.h
   #define ATA_DEBUG
   #define ATA_VERBOSE_DEBUG
 - rebuild the kernel and reboot
 - /var/log/messages will be flooded with ton of libata debug trace
 - Try to reproduce the timeout with Matthew's test program
 - Capture and attach full dmesg with the timeout to this bugzilla

Hopefully we can find some clue about the timeout. Thanks.

After doing the above, Alex, and upgrading to kernel 2.6.21.5, I am unable to reproduce the timeout under any circumstances, atleast for now. I have tried loading the system, running Matthew's test program number 5, but no success. 

Previously, under 2.6.21.3 and libata debug disabled, I had timeouts every now and then, very very frequently. However, I am still attaching the dmesg and /var/log/messages.log, hope it gives some clue.

Matthew, can you please also try it out ? Thanks

Created attachment 11740 [details]
dmesg on 2.6.21.5

On this kernel, and with libata debug enabled, the problem DOES NOT occur. However, still attaching the dmesg hoping that it might help.

Created attachment 11741 [details]
messages.log on 2.6.21.5

Problem does not occur on 2.6.21.5, but still attaching messages.log hoping that it might help.

Created attachment 11743 [details]
FINALLY the timeout occcurred :)

After waiting for 2 hours or so, the timeout occurred, and attached is the captured dmesg. Bingo :)

Hi Rohan,

The attachment #11743 [details] doesn't contain the traces with the timeout. :(

Could you please attach the full /var/log/messages with the timeout by
1. cd /var/log
2. cp messages messages-libata
3. bzip2 messages-libata
4. attach the "messages-libata.bz2" to this bugzilla

Thanks.

Created attachment 11745 [details]
The traces

Oh, here they are. I thought that because they are exactly the same as previous messages.log attachment it'd be ok not to attach them. But anyway :)

Created attachment 11746 [details]
Patch to limit the TSSTcorp TS-L632D ATAPI DMA to R/W only

Strangely /var/log/messages only contains the "ata1: ata_dev_select: ENTER, device 0, wait 1" and no libata HSM trace. :(

Anyway, I guess maybe this is ATAPI DMA problem.

Hi Rohan/Matthew,

Could you please verify if the attached patch fixes the timeout problem? Thanks.

Albert, can you please tell me which line to specifically look out for, in dmesg, which signifies that the timeout occurred ? I sometimes leave the pc on, and am away - so if the timeout occurs at that time, I can capture it .. But with so many  debug messages, I cannot understand ..

Also, I have applied the patch, and Matthew's test program number 5 is running as we speak ..

> ... which line to specifically look out for in dmesg

Hi Rohan,

1. Please find something with the "timeout" keyword like:

ata1.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata1.01: cmd a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0 
         res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
ata1: port is slow to respond, please be patient (Status 0xd0)
ata1: port failed to respond (30 secs, Status 0xd0)
ata1: soft resetting port
ata1.00: configured for UDMA/100
ata1.01: configured for UDMA/33
ata1: EH complete


===========
2. If such timeout is seen, please capture the log of whole transation, from CDB (1:0,1,0), the timeout itself until the EH traces. Something like below:

ata_scsi_dump_cdb: CDB (1:0,1,0) 00 00 00 00 00 00 00 00 00
ata_scsi_translate: ENTER
ata1: ata_dev_select: ENTER, device 1, wait 1
ata_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20
ata_tf_load: device 0xB0
ata_exec_command: ata1: cmd 0xA0
ata_scsi_translate: EXIT
ata_hsm_move: ata1: protocol 6 task_state 1 (dev_stat 0x58)
atapi_send_cdb: send cdb
ata_host_intr: ata1: protocol 6 task_state 3
ata_hsm_move: ata1: protocol 6 task_state 3 (dev_stat 0x51)
ata_hsm_move: ata1: protocol 6 task_state 4 (dev_stat 0x51)
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_error: ENTER
ata_port_flush_task: ENTER
ata_port_flush_task: flush #1
ata1: ata_port_flush_task: flush #2
ata1: ata_port_flush_task: EXIT
ata_eh_autopsy: ENTER
atapi_eh_request_sense: ATAPI request sense
ata1: ata_dev_select: ENTER, device 1, wait 1
ata_tf_load: feat 0x0 nsect 0x0 lba 0x0 0x0 0x20
ata_tf_load: device 0xB0
ata_exec_command: ata1: cmd 0xA0
ata_hsm_move: ata1: protocol 5 task_state 1 (dev_stat 0x58)
atapi_send_cdb: send cdb
ata_host_intr: ata1: protocol 5 task_state 2
ata_hsm_move: ata1: protocol 5 task_state 2 (dev_stat 0x58)
atapi_pio_bytes: ata1: xfering 18 bytes
__atapi_pio_bytes: data read
ata_host_intr: ata1: protocol 5 task_state 2
ata_hsm_move: ata1: protocol 5 task_state 2 (dev_stat 0x50)
ata_hsm_move: ata1: protocol 5 task_state 3 (dev_stat 0x50)
ata_hsm_move: ata1: dev 1 command complete, drv_stat 0x50
ata_port_flush_task: ENTER
ata_port_flush_task: flush #1
ata1: ata_port_flush_task: flush #2
ata1: ata_port_flush_task: EXIT
ata_eh_autopsy: EXIT
ata_eh_recover: ENTER
ata_eh_prep_resume: ENTER
ata_eh_prep_resume: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_resume: ENTER
ata_eh_resume: EXIT
ata_eh_suspend: ENTER
ata_eh_suspend: EXIT
ata_eh_recover: EXIT, rc=0
atapi_qc_complete: ENTER, err_mask 0x0
ata_scsi_error: EXIT

No time out as yet with that patch .. Matthew's program has been constantly running too .. Anything else I can try to stimulate the problem ?

> Anything else I can try to stimulate the problem ?

If it didn't happen, please try with the libata debug trace turned off by:
  #undef ATA_DEBUG
  #undef ATA_VERBOSE_DEBUG

Please keep the patch "Limit ATAPI DMA to Read/Write only" applied.

Thanks.

I've just compiled a 2.6.22-rc4 kernel with the added debug and limit atapi dma patches and with SMP and Preempt turned off and am currently running my cdstatus_5 program.

Albert, after using that patch for so long, and with libata debug disabled, the timeout did not occur even once.. Great going ! 

Matthew, any timeouts on your system ? BTW, Albert, does this patch limit or slow down the performance of the CD-ROM drive ?

After running cdstatus_5 for a few hours, I did not get any timeouts.  Then I disabled the debug patches and ran hald and cdstatus_5 at the same time and got lots of timeouts not long after my desktop gui had finished loading.

I'm still running the original ac00 firmware though.  Rohan, are you getting any timeouts with hald running with this patch?  If not I might upgrade the firmware to see if that helps.

I'm going to try cdstatus_1 now with full debugging enabled.

Matthew, all the time I was running cdstatus_5 and hald simultaneously. I did not get any timeouts. I will try again today, though...

Ok, I still haven't got any timeouts after that patch being applied, and using the computer for long periods .. Any news from your side, Matthew ? Anything else for us to try, Albert ?

Created attachment 11771 [details]
Timeout after patch too

I am very sorry, I spoke to soon I think.. The timeout occurs even _after_ I apply the patch.. Here's the dmesg :)

Yes I updated the firmware on my cdrom to AC01 and am still getting timeouts.  I'm hoping to do some more testing in a few days in single user mode and then gradually adding options to see if the timeouts still occur then.

This bugs happens in ubuntu, a long thread can be found here:
https://bugs.launchpad.net/linux/+bug/84603

what type of informations do you need?

a fix so far is to crossflah your cd drive as per:

https://bugs.launchpad.net/linux/+bug/84603/comments/46

Thanks a lot Chantra. Is it confirmed that the bug is the fault of the CD-ROM drive ? And if so, why is the timeout not caused when libata is disabled ?

However, I have upgraded to SC03 and will try for some time whether timeout occurs or no :)

> why is the timeout not caused when libata is disabled ?

I guess this is due to hald/scsi mid don't issue as many of commands that triggers the problem under libata.

Anyway, if Samsung's SC03 firmware works well but Acer's AC01 firmware doesn't, maybe we should notify Acer about the problem. Hopefully Acer could come up with better firmware, say "AC03"...

Do we know which commands are problematic?

From the dmesg, the timeout happens on command 0x43 (READ_TOC), 0x1e (ALLOW_MEDIUM_REMOVAL), 0x00 (TEST_UNIT_READY) and 0x25 (READ_CAPACITY).

I see.  All over the place. :-( I was hoping sr/cdrom was issuing commands after TUR failed.  That would be something we can fix.

We are seeing timeout issues for the TSSTcorp and Samsung drives, like this bug 8316 and another bug 8605.

Maybe increasing the timeout to the magic 7 seconds as Alan pointed out can help? (http://www.ussg.iu.edu/hypermail/linux/kernel/0701.0/0196.html)

AFAIK, we're using 7sec timeout.  drivers/cdrom/cdrom.c::CDROM_DEF_TIMEOUT or are you referring to a different one?

Ah, the timeout is already 7 secs... Originally I hoped we can workaround with longer timeout, if it is not long enough...

Regarding the timeout, maybe the hald is using its own timeout value via the sgio.timeout (even if drivers/cdrom/cdrom.c::CDROM_DEF_TIMEOUT is 7)?

I will check the hald code and see what the timeout value used there.

AFAIK, hald simply tries open the device but what do I know?  :-)

Hmm, instead of workaround from hald or scsi mid (per Matthew's comment 33), maybe firmware update that fixes the root cause is better way to go.

I've sent an e-mail to Acer asking if any TS-L632D firmware update available.

I've also sent a bug report to Asus, asking if they have firmware update newer than "AS99". The customer service staff replied "Sorry, Linux not supported." I said this is not Linux problem but more likely firmware problem, but the CSR insists "Linux is not supported on Asus notebooks."

Actually libata is not alone. The TS-L632D drive is also also causing trouble with old IDE subsystem.

https://bugs.launchpad.net/ubuntu/+source/linux-source-2.6.20/+bug/75295
https://bugs.launchpad.net/ubuntu/+source/hal/+bug/85695

Comment #69 is false. Ubuntu enabled libata since 2.6.17 (and problem occured since this migration)

Check https://launchpad.net/ubuntu/+spec/libata-for-all-ata-disks

> Comment #69 is false. Ubuntu enabled libata since 2.6.17 
> (and problem occured since this migration)

Really? How come the TS-L632D is driven by old IDE in that bug report?
======================
Linux version 2.6.20-6-generic (root@palmer) (gcc version 4.1.2 20070106 (prerelease) (Ubuntu 4.1.1-21ubuntu7)) #2 SMP Wed Jan 31 20:53:39 UTC 2007 (Ubuntu 2.6.20-6.11-generic)
 <snip>
[    3.444000] ICH6: IDE controller at PCI slot 0000:00:1f.1
[    3.444000] ACPI: PCI Interrupt 0000:00:1f.1[A] -> GSI 18 (level, low) -> IRQ 20
[    3.444000] ICH6: chipset revision 4
[    3.444000] ICH6: not 100% native mode: will probe irqs later
[    3.444000]     ide0: BM-DMA at 0xffa0-0xffa7, BIOS settings: hda:DMA, hdb:DMA
[    3.444000]     ide1: BM-DMA at 0xffa8-0xffaf, BIOS settings: hdc:pio, hdd:pio
[    3.444000] Probing IDE interface ide0...
[    3.684000] usb 1-1: configuration #1 chosen from 1 choice
[    4.152000] hda: ST9100825A, ATA DISK drive
[    4.396000] usb 4-1: new full speed USB device using uhci_hcd and address 2
[    5.116000] usb 4-1: configuration #1 chosen from 1 choice
[    5.120000] usbcore: registered new interface driver hiddev
[    5.132000] input: Logitech Optical USB Mouse as /class/input/input1
[    5.132000] input: USB HID v1.10 Mouse [Logitech Optical USB Mouse] on usb-0000:00:1d.0-1
[    5.132000] usbcore: registered new interface driver usbhid
[    5.132000] drivers/usb/input/hid-core.c: v2.6:USB HID core driver
[    5.520000] hdb: TSSTcorpCD/DVDW TS-L632D, ATAPI CD/DVD-ROM drive
[    8.180000] hdb: ATAPI 24X DVD-ROM DVD-R-RAM CD-R/RW drive, 2048kB Cache, UDMA(33)
<snip>
[ 681.880000] hdb: status timeout: status=0xd0 { Busy }
[ 681.880000] ide: failed opcode was: unknown
[ 681.880000] hdb: drive not ready for command

===========
And this:
https://bugs.launchpad.net/ubuntu/+source/linux-source-2.6.20/+bug/75295/comments/18

  "I have an HP Pavilion dv6106eu with a TSSTcorpCD/DVDW TS-L632D.
Killing hald-addon-storage: polling /dev/hda brings the system back to normal working speed."

Ok, my mistake. Indeed on my system, cdrom is still managed by ide-cd. Sorry

Created attachment 11883 [details]
Debug patch for the timeout

Hi Rohan/Laurent:

I guess maybe we still need detailed trace of this TS-L632D drive.

Need your help to
- Apply the debug patch to mainline 2.6.22-rc5 kernel
  (kernel should be configured to libata, instead of old IDE)
- Rebuild the kernel and reboot
- Hopefully /var/log/messages will be flooded with ton of libata debug trace
- Try to reproduce the timeout with Matthew's test program
- Capture and /var/log/messages with the timeout to this bugzilla

Hopefully we can have better understanding about the timeout. Thanks.

Albert, now that the SC03 firmware is flashed, I don't see a single timeout .. How can I induce one ? Should I downgrade my firmware ?

Rohan, nice to know that SC03 firmware yields good result. If not too inconvenient, please help to downgrade the firmware to AC0x and collect some libata traces. Thanks and appreciates.

Albert,

I am running SC03 too, but I can downgrade and test out the patch.
Will do tonight when I get home

Hi, 

I attached both my messages log and my syslog (it seems that all the debug messages are put into syslog). I kept both files unchanged.

FYI, cd-rom drive is ata1, hard drive is ata2

Created attachment 11890 [details]
messages logfile since last reboot

Created attachment 11891 [details]
syslog logfile since last reboot

I've downgraded to AC01 and running the cdstatus program. Will attach the log as soon as timeout occurs.

Been running the 2.6.22-rc6 kernel with hald killed, and Matthew's program running .. But not a single timeout experienced till now ..

> syslog logfile since last reboot

Hi Laurent,

Thanks for the debug trace. Could you also attach "dmesg" without the debug patch. (For the info during boot.) Thanks.

Albert, can you suggest me anything to induce the timeout ? The program's been running from a long time, with no timeout ..

Created attachment 11893 [details]
dmesg logfile

Here's the dmesg. There's the nvidia module which taints the kernel but it was disabled during the test.

> Albert, can you suggest me anything to induce the timeout ?
> The program's been running from a long time, with no timeout 

There is no clue yet about the root cause or how to trigger the timeout.
The only clue from Laurent's log is: the timeout only happens on REQUEST_SENSE. 

(This reminds of bug 8244 in which AOpen cdrom 56X/AKH also timeouts on REQUEST_SENSE. However, these two bugs are quite different. For bug 8244, the REQUEST_SENSE timeout is caused by garbage in the taskfile registers and always reproducible. For this bug, the TS-L632D seems timeout on indefinite REQUEST SENSE. The command that REQUEST_SENSE times out are READ_CAPACITY and TEST_UNTI_READY in Laurent's log.)

Created attachment 11894 [details]
Laurent's log filtered for ata1 messages only

Created attachment 11895 [details]
Tejun's patch to limit ATAPI DMA to multiple of 16 bytes

Hi Laurent,

Need your help to apply both the "Debug patch for the timeout" and Tejun's patch to "limit ATAPI DMA to multiple of 16 bytes" (and trigger the timeout for debug trace). 

Hopefully we could know more about how the TS-L632D behaves under Tejun's patch and any timeout behavior change.

Ok, I trimmed down my ubuntu kernel so I can now compile a new kernel in reasonable time.

I extracted the relevant part from the logs.
As I can't find a way to attach a file (pointers will be welcome), you can get them from http://www.debuntu.org/files/libata_debug.txt.bz2

Test done with ubuntu's 2.6.22-rc5 patch with both "Tejun's patch" and "Debug patch for the timeout"


Jun 28 22:13:46 gutsytop kernel: [ 1989.404000] ata1: xfering 18 bytes
Jun 28 22:13:46 gutsytop kernel: [ 1989.404000] ata1: protocol 5 task_state 2
Jun 28 22:13:46 gutsytop kernel: [ 1989.404000] ata1: protocol 5 task_state 2 (dev_stat 0x50)
Jun 28 22:13:46 gutsytop kernel: [ 1989.404000] ata1: protocol 5 task_state 3 (dev_stat 0x50)
Jun 28 22:13:46 gutsytop kernel: [ 1989.404000] ata1: dev 1 command complete, drv_stat 0x50
Jun 28 22:13:46 gutsytop kernel: [ 1989.404000] CDB (1:0,1,0) 00 00 00 00 00 00 00 00 00
Jun 28 22:14:16 gutsytop kernel: [ 2019.424000] ata1.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
Jun 28 22:14:16 gutsytop kernel: [ 2019.424000] ata1.01: cmd a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0 
Jun 28 22:14:16 gutsytop kernel: [ 2019.424000]          res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
Jun 28 22:14:22 gutsytop kernel: [ 2024.468000] ata1: port is slow to respond, please be patient (Status 0xd0)
Jun 28 22:14:27 gutsytop kernel: [ 2029.452000] ata1: device not ready (errno=-16), forcing hardreset
Jun 28 22:14:27 gutsytop kernel: [ 2029.452000] ata1: BUG: prereset() requested invalid reset type
Jun 28 22:14:27 gutsytop kernel: [ 2029.452000] ata1: soft resetting port
Jun 28 22:14:27 gutsytop kernel: [ 2029.788000] ata1: protocol 2 task_state 2 (dev_stat 0x58)

Hi chantra,

Thanks for the log. In your log, the timeout happens on TEST_UNIT_READY itself, not the coming REQUEST_SENSE. It seems the behavior somewhat changed under Tejun's patch (or, under different version of firmware?). I was thinking doing some workaround in REQUEST_SENSE. If timeout on the command itself, we have to find other clue.

BTW, the timeout is 30sec in this case, that's much longer than 7sec and what I guessed.

Do you have more timeout traces (under Tejun's patch) for analysis?
(accessing large log file from http://www.debuntu.org is ok for me)

Hi Albert,

I will boot my box on my libatadebug kernel tonight when I get home.
If you have a some code to trigger the REQUEST_SENSE , I will run it. 
Are cdstatus_1 and cdstatus_2 meant to trigger it?

Unfortunately I am not much aware of cd programming, so I can't code it without to much research.

Also, could you tell me how to spot a REQUEST_SENSE call. should it be:
ata1.01: cmdxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx tag x cdb 0x03 data x 

(cdb 0x03)?

Has I have compiled a light kernel, I can easily apply new patches if required without taking ages :D.

Created attachment 11904 [details]
syslog with Tejun's patch

Here's my syslog (untrimmed) with Tejun.

Created attachment 11905 [details]
syslog  cdb 0x0  cdb 0x25

I am rerunning the debug kernel. I have add 2 different errors: cdb 0x25 and cdb 0x0 (GPCMD_READ_CDVD_CAPACITY and TEST_UNIT_READY) if I am right.

I have attach a trimmed version, 40 lines befire and after the timeout. Hope it will do.
I will let the machine run and upload a big files later.

by the way, I am using firmware AC01.
I have had new errors: START_STOP (0x1b), ALLOW_MEDIUM_REMOVAL (0x1e) and READ_TOC (0x43)

Checked both Laurent and chantra's libata traces. With Tejun's patch, Laurent's drive still timeouts on REQUEST_SENSE, but chantra's drive times out on the command itself. I guess this might be due to firmware versions.

Hi Laurent, could you please provide your firmware version for reference.

(Adding Alan and Jeff to the cc list for advice.)
Summary:
From the log, most of the timeout happened on 0x25 (READ_CAPACITY) and 0x00 (TEST_UNIT_READY). It seems there is little we can do from libata since the commands timeouts randomly looks normal by libata.

The current workarounds for the TSSTcorp TS-L632D problem are:
 - update firmware to SC03 or some version that works (preferred)
 - kill hald-addon-storage
 - keep a disc in the drive

However, we might be able to do something in the Linux SCSI layer, as Matthew pointed out, the behavior of sr_media_change() and scsi_test_unit_ready() is strange:

When there is no disc in the drive, scsi_test_unit_ready() set sdev->changed = 1 and returns zero. This makes sr_media_change() keep issuing 0x43 and 0x25 to the drive, in a loop of clearing sdev->changed (and later setting sdev->changed by scsi_test_unit_ready).
There is a patch by Alan Stern might be helpful to this bug:
http://marc.info/?l=linux-kernel&m=115412002912837&w=2

Anyway, maybe the SCSI developers can look into this. Changing the bug component to SCSI.

I have a Asus Laptop: firmware version is AS04

can anybody confirm that updating firmware solve this problem? i have no ms windows and this is quite complicated to update for me. thanks for advice

yes, I can confirm that a firmware upgrade fixes the issue.

check  out this thread:
https://bugs.launchpad.net/linux/+bug/84603/comments/74

Yes, updating the firmware to SC03 solved the problem for me, too.

thank you chantra and rohan, i will try to update too

Unfortunately for me, it seems that Asus firmwares AS05 and AS99 don't solve the problem. (Moreover they have been removed from download some days ago and I haven't find another site)

Laurent, crossflash to SC03 -- I've done that for my Acer laptop. In windows, the SFNDWIN.exe tool accepts the command line /nocheck or -nocheck , that allows you to flash the drive regardless of the OEM. The SC03 firmware has been working perfectly, and I've not noticed and performance hits..

Created attachment 11935 [details]
more output

Some extra output, trimmed to 40 lines before and after the timeout.

Created attachment 12710 [details]
sr_media_change: avoid READ TOC/CAPACITY if no media present

(Patch based on http://marc.info/?l=linux-kernel&m=115412002912837&w=2)

Hi Rohan and Laurent,
 
Could you please crossflash the firmware of your TS-L632D to the original version and test if the attached patch fixes the TS-L632D timeout problem?
(The patch is against the lastest 2.6.23-rc5 kernel)

Thanks!

i have a dell precision m90 notebook, which also uses this drive.
it has firmware DE04 installed.
i am using opensuse10.2 with kernel 2.6.18.8.
and i am having similar problems with this drive.

whenever my cd-burning-program k3b (and some other applications) accesses the drive, the drive firstly "freezes". it takes about 30 seconds to respond.
when i check the output of dmesg at this time, i see the following:

ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
ata2.00: cmd a0/01:00:00:00:00/00:00:00:00:00/a0 tag 0 cdb 0xac data 8 in
         res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
ata2: port is slow to respond, please be patient (Status 0xd0)
ata2: port failed to respond (30 secs, Status 0xd0)
ata2: soft resetting port
ata2.00: configured for UDMA/33
ata2: EH complete

when i start burning it firstly does this again, and then burning works.
so it seems to me, that every access to the drive results in such an "soft reset".
if i am not patient enough, and killing the burning software while drive is not respondig, or ejecting the disc, than it gets even worse.
then the drive speed will be limited which each soft-reset down to PIO-4...

to which kernel versions do these patches from which you are talking about here belong?

will a 2.6.22 kernel also have these patches?

Hi Albert,

I patched a 2.6.22 kernel with

http://bugzilla.kernel.org/attachment.cgi?id=12710&action=view

Will update this bug report once I have tested it enough.

Thanks a million for the patch,

regards,
chantra
---- 


http://www.debuntu.org

Debuntu deb's repository


Debuntu Debian and Ubuntu Tips and Tricks


<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 TRANSITIONAL//EN">
<HTML>
<HEAD>
  <META HTTP-EQUIV="Content-Type" CONTENT="text/html; CHARSET=UTF-8">
  <META NAME="GENERATOR" CONTENT="GtkHTML/3.16.0">
</HEAD>
<BODY>
Hi Albert,<BR>
<BR>
I patched a 2.6.22 kernel with
<PRE>
<FONT COLOR="#000000"><A HREF="http://bugzilla.kernel.org/attachment.cgi?id=12710&action=view">http://bugzilla.kernel.org/attachment.cgi?id=12710&amp;action=view</A></FONT>
</PRE>
Will update this bug report once I have tested it enough.<BR>
<BR>
Thanks a million for the patch,<BR>
<BR>
regards,<BR>
chantra<BR>
<TABLE CELLSPACING="0" CELLPADDING="0" WIDTH="100%">
<TR>
<TD>
<FONT COLOR="#969696">----</FONT> 
<PRE>

<A HREF="http://www.debuntu.org">http://www.debuntu.org</A>

<A HREF="http://repository.debuntu.org">Debuntu deb's repository</A>
</PRE>
<BR>
<A HREF="http://www.debuntu.org/"><IMG SRC="cid:1191270106.4195.0.camel@gutsytop" ALIGN="bottom" ALT="Debuntu Debian and Ubuntu Tips and Tricks"></A><BR>
<BR>
<BR>
</TD>
</TR>
</TABLE>
</BODY>
</HTML>
Spam detection software, running on the system "murdock.linux-foundation.org", has
identified this incoming email as possible spam.  The original message
has been attached to this so you can view it (if it isn't spam) or label
similar future email.  If you have any questions, see
the administrator of that system for details.

Content preview:  Hi Albert, I patched a 2.6.22 kernel with
  http://bugzilla.kernel.org/attachment.cgi?id=12710&action=view [...] 

Content analysis details:   (6.6 points, 5.0 required)

 pts rule name              description
---- ---------------------- --------------------------------------------------
-1.0 OSDL_HEADER_SUBJECT_BRACKETED Subject starts with []'d phrase
 0.7 EXTRA_MPART_TYPE       Header has extraneous Content-type:...type= entry
 3.0 HTML_IMAGE_ONLY_12     BODY: HTML: images with 800-1200 bytes of words
 0.0 HTML_MESSAGE           BODY: HTML included in message
 0.1 HTML_70_80             BODY: Message is 70% to 80% HTML
-1.1 BAYES_05               BODY: Bayesian spam probability is 1 to 5%
                            [score: 0.0231]
 2.7 HTML_SHORT_LINK_IMG_2  HTML is very short with a linked image
 2.1 OSDL_IMAGE_SPAM        Nearly all HTML with nothing but images

Hi Albert,

Arg, the error is back. Here is what I have in dmesg:

[ 1152.096000] ata1.01: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x2 frozen
[ 1152.096000] ata1.01: cmd a0/00:00:00:00:20/00:00:00:00:00/b0 tag 0 cdb 0x0 data 0 
[ 1152.096000]          res 40/00:03:00:00:00/00:00:00:00:00/b0 Emask 0x4 (timeout)
[ 1157.136000] ata1: port is slow to respond, please be patient (Status 0xd0)
[ 1162.120000] ata1: device not ready (errno=-16), forcing hardreset
[ 1162.120000] ata1: soft resetting port
[ 1162.472000] ata1.00: configured for UDMA/100
[ 1162.660000] ata1.01: configured for UDMA/33
[ 1162.660000] ata1: EH complete
[ 1162.684000] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[ 1162.692000] sd 0:0:0:0: [sda] Write Protect is off
[ 1162.692000] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[ 1162.716000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 1163.052000] sd 0:0:0:0: [sda] 156301488 512-byte hardware sectors (80026 MB)
[ 1163.052000] sd 0:0:0:0: [sda] Write Protect is off
[ 1163.052000] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[ 1163.056000] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA

This happened while I was compiling a kernel, it seems that it mainly happens when running resource intensive process but I am not 100% positive on this assumption :).


Sorry for the spam earlier on, but my HTML mail was not really accepted by the spam filter.

Closing out old stale bug