David The USB host controller in the SOC that i use has a hardware bug due to which the host controller do not send PING packets as often as it should. Alan actively helped me isolating the issue and descripton of the issue in his words is given below.
"So what happens is that usb-storage submits the 512-byte OUT URB, but the endpoint is in a NYET state and for some reason the host controller is not stimulated to send a PING packet. Therefore the data transfer never gets started, and 30 second later it times out." I want to handle this hardware bug in software. Per Alan's suggestion, i will start reading the ehci-driver code. Do you have any idea on how to handle this bug in the software ? Which portion of the ehci driver needs to be modified to handle this bug ? Any pointers will be helpful. Thanks. Regards Vivek -----Original Message----- From: Alan Stern [mailto:[EMAIL PROTECTED] Sent: Wednesday, June 07, 2006 11:50 AM To: Vivek Dharmadhikari Cc: David Brownell; USB development list Subject: RE: [linux-usb-devel] Usb hangs during small and large file transfer On Wed, 7 Jun 2006, Vivek Dharmadhikari wrote: > Alan > > Here are the results again. > > The few transactions for the time period before the "command_abort called" > are typically like below > > 1. Host sends 512 bytes OUT packet which is ACKED. > 2. Host sends 13 bytes IN packet which is ACKED. > 3. Host sends 31 bytes OUT packet which is NYETD. > 4. Host sends PING packet which is ACKED. > 5. Repeat of sequence 1-4 You haven't parsed this quite right. The interval between successive commands occurs between your steps 3 and 4. So the correct sequence is this: 31 bytes OUT (NYET, PING, ACK), 512 bytes OUT (ACK), 13 bytes IN (ACK), and repeat. Note also that from the host's point of view, the 31-byte OUT URB completes when the NYET packet is received, and the 512-byte OUT URB is submitted before the PING packet is sent. > I am producing the usb-storage log for transaction that happened right > before transaction that produced 30 seconds delay. > > usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries > usb-storage: Status code 0; transferred 512/512 > usb-storage: -- transfer complete > usb-storage: Bulk data transfer result 0x0 > usb-storage: Attempting to get CSW... > usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes > usb-storage: Status code 0; transferred 13/13 > usb-storage: -- transfer complete > usb-storage: Bulk status result = 0 > usb-storage: Bulk Status S 0x53425355 T 0x115 R 0 Stat 0x0 > usb-storage: scsi cmd done, result=0x0 > usb-storage: *** thread sleeping. > usb-storage: queuecommand called > usb-storage: *** thread awakened. > usb-storage: Command WRITE_10 (10 bytes) > usb-storage: 2a 00 00 01 8c ed 00 00 01 00 > usb-storage: Bulk Command S 0x43425355 T 0x116 L 512 F 0 Trg 0 LUN 0 CL 10 > usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes > usb-storage: Status code 0; transferred 31/31 > usb-storage: -- transfer complete > usb-storage: Bulk command transfer result=0 Call this sequence (A). > As you see,the above log follows the sequence that i described in the > begining. The catalyst log for the same period shows > > 1. Host sends 512 bytes OUT packet which is ACKED. > 2. Host sends 13 bytes IN packet which is ACKED. > 3. Host sends 31 bytes OUT packet which is NYETD. > 4. After 1ms,Host sends PING packet which is ACKED. > > Per usb-storage log,the above transcation is followed transaction that > is aborted. > > usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries This line actually belongs at the end of sequence (A), since it occurs before the PING is sent (in fact, this is what causes the PING). > usb-storage: command_abort called > usb-storage: usb_stor_stop_transport called > usb-storage: -- cancelling sg request > usb-storage: Status code -131; transferred 0/512 > usb-storage: -- transfer cancelled > usb-storage: Bulk data transfer result 0x4 > usb-storage: -- command was aborted > usb-storage: usb_stor_Bulk_reset called > usb-storage: usb_stor_control_msg: rq=ff rqtype=21 value=0000 index=00 len=0 > usb-storage: Soft reset: clearing bulk-in endpoint halt > usb-storage: usb_stor_control_msg: rq=01 rqtype=02 value=0000 index=82 len=0 > usb-storage: usb_stor_clear_halt: result = 0 > usb-storage: Soft reset: clearing bulk-out endpoint halt > usb-storage: usb_stor_control_msg: rq=01 rqtype=02 value=0000 index=01 len=0 > usb-storage: usb_stor_clear_halt: result = 0 > usb-storage: Soft reset done Call this sequence (B). > The catalyst log for the same period shows > > 1. Host sends 512 bytes OUT packet which is ACKED. > 2. Host sends 13 bytes IN packet which is ACKED. > 3. Host sends 31 bytes OUT packet which is NYETD. > 4. After 30 seconds,Host initiate control transfer to reset the device,clear > bulk-in ep halt abd clear bulk-out halt which matches usb-storage log. > > Even though "usb-storage: Status code -131; transferred 0/512" gives > impression that no bytes were transferred, the catalyst log in fact > shows that 512 bytes were tranmitted followd by IN-13 and OUT-31 > successfully. Note that usb-storage log did not have any entry for IN-13 > and OUT-31 transactions. Your conclusion is wrong. Probably you haven't correlated the Catalyst trace with the system log correctly. I suspect lines 1-3 of this Catalyst trace actually correspond to sequence (A), and only line 4 belongs to (B). So what happens is that usb-storage submits the 512-byte OUT URB, but the endpoint is in a NYET state and for some reason the host controller is not stimulated to send a PING packet. Therefore the data transfer never gets started, and 30 second later it times out. > It was hard for me to co-relate the usbmon with records from usb-storage > and catalyst.Perhaps,you can co-relate them. Below are the usbmon > entries for time periods before the 30 seconds transaction. The right > most column is difference between time-stamps in seconds. > > 810c93e0 1296380816 S Bo:002:01 -150 31 D > 0.006 > 810c93e0 1296386816 S Bo:002:01 -150 31 D > 0.006 > 810c93e0 1296392816 S Bo:002:01 -150 31 D > 0.006 > 810c93e0 1296398816 S Bo:002:01 -150 31 D > 0.009 > 810c93e0 1296407816 S Bo:002:01 -150 31 D > 0.006 > 810c93e0 1296413816 S Bo:002:01 -150 31 D > 0.006 > 810c93e0 1296419816 S Bo:002:01 -150 31 D > 0.006 > 810c93e0 1296425816 C Bi:002:02 0 13 D 0.008 > 814817a0 1296433816 C Bo:002:01 0 512 D 0.007 > 814817a0 1296440816 C Bo:002:01 0 32768 D > 0.009 > 81481740 1296449816 C Bo:002:01 0 40960 D > 0.01 > 810c93e0 1296459816 C Bi:002:02 0 13 D 0.008 > 81481740 1296467816 C Bo:002:01 0 40960 D > 0.007 > 814817a0 1296474816 C Bo:002:01 0 20480 D > 0.007 > 810c93e0 1296481816 C Bi:002:02 0 13 D 0.008 > 814817a0 1296489816 C Bo:002:01 0 512 D 0.009 > 814817a0 1296498816 C Bo:002:01 0 512 D 0.008 > 810c93e0 1296506816 C Bo:002:01 0 31 D 0.01 > 810c93e0 1296516816 C Bi:002:02 0 13 D 30.002 This usbmon log isn't useful, because it clearly has many dropped lines. No matter, the usb-storage log is clear enough. > I hope that i have provided the correct information. Let me know if you > need more info. This will do. It might give you a hint as to where to start looking in the ehci-hcd driver: where a new URB is added to an empty bulk-OUT queue. You could also try reading the list of errata for your host controller hardware. It may be available on the manufacturer's web site. Alan Stern _______________________________________________ linux-usb-devel@lists.sourceforge.net To unsubscribe, use the last form field at: https://lists.sourceforge.net/lists/listinfo/linux-usb-devel
