Alan >So the correct sequence is >this: 31 bytes OUT (NYET, PING, ACK), 512 bytes OUT (ACK), 13 bytes IN >(ACK), and repeat.
ok. My intrepretation was obviously wrong. I agree with all the subsequent obeservations made by you. >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. Clearly the hardware is mis-behaving. >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. That helps. >You could also try reading the list of errata for your host controller >hardware. It may be available on the manufacturer's web site Will do. I really appreciate your help in narrowing down the issue. It wouldn't have been possible without your help. many 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
