Alan >Vivek, can you please run the same test over again? This time also >collect the usb-storage verbose debugging log so we can see exactly what >happens from the host's point of view and compare it with the Catalyst's >record. We'd like to get as much detailed information as possible leading >up to the point where the problem occurs. You can stop the test as soon >as one of those 30-second timeouts occurs.
I re-ran the test with usb-storage verbose debugging enabled. The usb-storage log,usbmon log and Catalyst log are in aggrement with each other. I am reproducing the the usb-storage log below. nsferred 31/31 usb-storage: -- transfer complete usb-storage: Bulk command transfer result=0 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 0xa6 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 87 f3 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xa7 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 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 0xa7 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 87 f4 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xa8 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 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 0xa8 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 87 f5 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xa9 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 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 0xa9 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 87 f6 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xaa 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 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 0xaa 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 87 f7 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xab 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 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 0xab 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 87 f8 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xac 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 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 0xac 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 87 f9 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xad 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 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 0xad 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 87 fa 00 00 01 00 usb-storage: Bulk Command S 0x43425355 T 0xae 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 usb-storage: usb_stor_bulk_transfer_sglist: xfer 512 bytes, 1 entries 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 usb-storage: scsi command aborted usb-storage: queuecommand called usb-storage: *** thread sleeping. usb-storage: *** thread awakened. usb-storage: Command TEST_UNIT_READY (6 bytes) usb-storage: 00 00 00 00 00 00 usb-storage: Bulk Command S 0x43425355 T 0xae L 0 F 0 Trg 0 LUN 0 CL 6 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 usb-storage: Attempting to get CSW... usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes usb-storage: command_abort called usb-storage: usb_stor_stop_transport called usb-storage: -- cancelling URB usb-storage: Status code -131; transferred 0/13 usb-storage: -- transfer cancelled usb-storage: Bulk status result = 4 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 usb-storage: scsi command aborted usb-storage: device_reset called 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: *** thread sleeping. 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 The line "usb-storage: Status code -131; transferred 0/13" in the above log is where the 30 seconds delay occurs. The sequence leading to 30 seconds delay is as below. 1. The usb host driver queue 13 bytes handed over by scsi layer for transmission. 2. The device responds with NYET. 3. 30 seconds IDLE time on bus 4. The host issue class type request 0x21ff to reset the device and device ack it. 5. 6 seconds IDEL time on bus. 5. The host issue clear endpoint feature for IN and OUT endpoints. 6. The data transfer resumes. The above sequence get repeated quite a few times during the data transfer. As David suggested, is it possible to implement code in the host to pull the device out of NYET state ? I would like to experiment with such code if you can point to right place. Let me know if you need more details. I will be happy to provide them. Regards Vivek -----Original Message----- From: Alan Stern [mailto:[EMAIL PROTECTED] Sent: Monday, June 05, 2006 9:07 AM To: Vivek Dharmadhikari; David Brownell Cc: USB development list Subject: Re: [linux-usb-devel] Usb hangs during small and large file transfer On Mon, 5 Jun 2006, David Brownell wrote: > On Saturday 03 June 2006 9:33 am, Alan Stern wrote: > > On Fri, 2 Jun 2006, Vivek Dharmadhikari wrote: > > > > > > Host send OUT transcation with 31 Bytes > > > Device reponds with NYET. > > > 30 seconds IDLE time on bus. > > Where IDLE == only SOFs are seen? > > Or the hardware idle state, by which you mean the port was suspended? Good question... > If EHCI had sane timer handling, it would be easier to add > code doing things like forcing endpoints out of NYET mode > every few seconds. > > For paranoia's sake, it would be good to verify more of the > interactions with the host. The previous request and response > especially ... did they trigger an error of some kind? > If so, how was it recovered from? > That said, we could more easily change the host software. At least, if > someone with a hardware analyser could isolate the problem ... :) Forunately Vivek does have an analyzer! Vivek, can you please run the same test over again? This time also collect the usb-storage verbose debugging log so we can see exactly what happens from the host's point of view and compare it with the Catalyst's record. We'd like to get as much detailed information as possible leading up to the point where the problem occurs. You can stop the test as soon as one of those 30-second timeouts occurs. 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
