Felipe, Thanks for the tip about usbmon --- that looks interesting. Of course, as luck would have it, turning on usbmon changes behavior: dd'ing to a mass-storage device (/dev/sda1) used to fail after ~500KiB. With usbmon, it fails only after about 2MiB. I attached two logs: first one is the usb-storage debug output without usbmon (fails after about 500KB of writing to /dev/sda1), second is with usbmon (fails about 2MiB of writing to /dev/sda1). --david On Fri, Mar 7, 2014 at 7:49 PM, Felipe Balbi <balbi@xxxxxx> wrote: > On Fri, Mar 07, 2014 at 06:16:03PM -0700, David Mosberger wrote: >> So the MAX3421E driver is working quite well but one problem I'm >> seeing is that after running devices for a while, they seem to get >> into a mode where a bulk out transfer gets stuck soliciting and >> endless stream of NAKs. The MAX3421E retries NAK'd transfers in the >> next frame again, only to get the same response, forever. I see this >> both with a mass storage device and a WIFI adapter (which is >> specifically advertised as being USB 1.1 compatible). Anybody have >> any ideas where that might be coming from? > > take a look at usbmon and capture some traces of a live session. We need > pre- and post- data. The more the merrier ;-) > > You can read about usbmon on Documentation/usb/usbmon.txt in your kernel > source tree. > > cheers and good luck > > -- > balbi -- eGauge Systems LLC, http://egauge.net/, 1.877-EGAUGE1, fax 720.545.9768
[ 474.550000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 1024 bytes, 1 entries [ 474.560000] usb-storage: Status code 0; transferred 1024/1024 [ 474.560000] usb-storage: -- transfer complete [ 474.560000] usb-storage: Bulk data transfer result 0x0 [ 474.560000] usb-storage: Attempting to get CSW... [ 474.560000] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes [ 474.560000] usb-storage: Status code 0; transferred 13/13 [ 474.560000] usb-storage: -- transfer complete [ 474.560000] usb-storage: Bulk status result = 0 [ 474.560000] usb-storage: Bulk Status S 0x53425355 T 0x1ef R 0 Stat 0x0 [ 474.560000] usb-storage: scsi cmd done, result=0x0 [ 474.560000] usb-storage: *** thread sleeping. [ 474.560000] usb-storage: queuecommand_lck called [ 474.560000] usb-storage: *** thread awakened. [ 474.560000] usb-storage: Command READ_10 (10 bytes) [ 474.560000] usb-storage: 28 00 00 00 03 f2 00 00 02 00 [ 474.560000] usb-storage: Bulk Command S 0x43425355 T 0x1f0 L 1024 F 128 Trg 0 LUN 0 CL 10 [ 474.560000] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes [ 474.560000] usb-storage: Status code 0; transferred 31/31 [ 474.560000] usb-storage: -- transfer complete [ 474.560000] usb-storage: Bulk command transfer result=0 [ 474.560000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 1024 bytes, 1 entries [ 474.570000] usb-storage: Status code 0; transferred 1024/1024 [ 474.570000] usb-storage: -- transfer complete [ 474.570000] usb-storage: Bulk data transfer result 0x0 [ 474.570000] usb-storage: Attempting to get CSW... [ 474.570000] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes [ 474.570000] usb-storage: Status code 0; transferred 13/13 [ 474.570000] usb-storage: -- transfer complete [ 474.570000] usb-storage: Bulk status result = 0 [ 474.570000] usb-storage: Bulk Status S 0x53425355 T 0x1f0 R 0 Stat 0x0 [ 474.570000] usb-storage: scsi cmd done, result=0x0 [ 474.570000] usb-storage: *** thread sleeping. [ 474.570000] usb-storage: queuecommand_lck called [ 474.570000] usb-storage: *** thread awakened. [ 474.570000] usb-storage: Command READ_10 (10 bytes) [ 474.570000] usb-storage: 28 00 00 00 03 f4 00 00 02 00 [ 474.570000] usb-storage: Bulk Command S 0x43425355 T 0x1f1 L 1024 F 128 Trg 0 LUN 0 CL 10 [ 474.570000] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes [ 474.570000] usb-storage: Status code 0; transferred 31/31 [ 474.570000] usb-storage: -- transfer complete [ 474.570000] usb-storage: Bulk command transfer result=0 [ 474.570000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 1024 bytes, 1 entries [ 474.580000] usb-storage: Status code 0; transferred 1024/1024 [ 474.580000] usb-storage: -- transfer complete [ 474.580000] usb-storage: Bulk data transfer result 0x0 [ 474.580000] usb-storage: Attempting to get CSW... [ 474.580000] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes [ 474.580000] usb-storage: Status code 0; transferred 13/13 [ 474.580000] usb-storage: -- transfer complete [ 474.580000] usb-storage: Bulk status result = 0 [ 474.580000] usb-storage: Bulk Status S 0x53425355 T 0x1f1 R 0 Stat 0x0 [ 474.580000] usb-storage: scsi cmd done, result=0x0 [ 474.580000] usb-storage: *** thread sleeping. [ 474.580000] usb-storage: queuecommand_lck called [ 474.580000] usb-storage: *** thread awakened. [ 474.580000] usb-storage: Command READ_10 (10 bytes) [ 474.580000] usb-storage: 28 00 00 00 03 f6 00 00 02 00 [ 474.580000] usb-storage: Bulk Command S 0x43425355 T 0x1f2 L 1024 F 128 Trg 0 LUN 0 CL 10 [ 474.580000] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes [ 474.580000] usb-storage: Status code 0; transferred 31/31 [ 474.580000] usb-storage: -- transfer complete [ 474.580000] usb-storage: Bulk command transfer result=0 [ 474.580000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 1024 bytes, 1 entries [ 474.590000] usb-storage: Status code 0; transferred 1024/1024 [ 474.590000] usb-storage: -- transfer complete [ 474.590000] usb-storage: Bulk data transfer result 0x0 [ 474.590000] usb-storage: Attempting to get CSW... [ 474.590000] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes [ 474.590000] usb-storage: Status code 0; transferred 13/13 [ 474.590000] usb-storage: -- transfer complete [ 474.590000] usb-storage: Bulk status result = 0 [ 474.590000] usb-storage: Bulk Status S 0x53425355 T 0x1f2 R 0 Stat 0x0 [ 474.590000] usb-storage: scsi cmd done, result=0x0 [ 474.590000] usb-storage: *** thread sleeping. [ 474.590000] usb-storage: queuecommand_lck called [ 474.590000] usb-storage: *** thread awakened. [ 474.590000] usb-storage: Command READ_10 (10 bytes) [ 474.590000] usb-storage: 28 00 00 00 03 f8 00 00 02 00 [ 474.590000] usb-storage: Bulk Command S 0x43425355 T 0x1f3 L 1024 F 128 Trg 0 LUN 0 CL 10 [ 474.590000] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes [ 474.590000] usb-storage: Status code 0; transferred 31/31 [ 474.590000] usb-storage: -- transfer complete [ 474.590000] usb-storage: Bulk command transfer result=0 [ 474.590000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 1024 bytes, 1 entries [ 474.610000] usb-storage: Status code 0; transferred 1024/1024 [ 474.610000] usb-storage: -- transfer complete [ 474.610000] usb-storage: Bulk data transfer result 0x0 [ 474.610000] usb-storage: Attempting to get CSW... [ 474.610000] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes [ 474.610000] usb-storage: Status code 0; transferred 13/13 [ 474.610000] usb-storage: -- transfer complete [ 474.610000] usb-storage: Bulk status result = 0 [ 474.610000] usb-storage: Bulk Status S 0x53425355 T 0x1f3 R 0 Stat 0x0 [ 474.610000] usb-storage: scsi cmd done, result=0x0 [ 474.610000] usb-storage: *** thread sleeping. [ 474.610000] usb-storage: queuecommand_lck called [ 474.610000] usb-storage: *** thread awakened. [ 474.610000] usb-storage: Command READ_10 (10 bytes) [ 474.610000] usb-storage: 28 00 00 00 03 fa 00 00 02 00 [ 474.610000] usb-storage: Bulk Command S 0x43425355 T 0x1f4 L 1024 F 128 Trg 0 LUN 0 CL 10 [ 474.610000] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes [ 474.610000] usb-storage: Status code 0; transferred 31/31 [ 474.610000] usb-storage: -- transfer complete [ 474.610000] usb-storage: Bulk command transfer result=0 [ 474.610000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 1024 bytes, 1 entries [ 474.650000] usb-storage: Status code 0; transferred 1024/1024 [ 474.650000] usb-storage: -- transfer complete [ 474.650000] usb-storage: Bulk data transfer result 0x0 [ 474.650000] usb-storage: Attempting to get CSW... [ 474.650000] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes [ 474.650000] usb-storage: Status code 0; transferred 13/13 [ 474.650000] usb-storage: -- transfer complete [ 474.650000] usb-storage: Bulk status result = 0 [ 474.650000] usb-storage: Bulk Status S 0x53425355 T 0x1f4 R 0 Stat 0x0 [ 474.650000] usb-storage: scsi cmd done, result=0x0 [ 474.650000] usb-storage: *** thread sleeping. [ 474.650000] usb-storage: queuecommand_lck called [ 474.650000] usb-storage: *** thread awakened. [ 474.650000] usb-storage: Command WRITE_10 (10 bytes) [ 474.650000] usb-storage: 2a 00 00 00 00 3e 00 00 f0 00 [ 474.650000] usb-storage: Bulk Command S 0x43425355 T 0x1f5 L 122880 F 0 Trg 0 LUN 0 CL 10 [ 474.650000] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes [ 474.650000] usb-storage: Status code 0; transferred 31/31 [ 474.650000] usb-storage: -- transfer complete [ 474.650000] usb-storage: Bulk command transfer result=0 [ 474.650000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 18 entries [ 474.770000] max3421_handle_irqs: fnum 820 urb types 0 0 0 1394 errcnt 8710 0 0 0 55 0 0 0 0 0 0 0 0 0 0 0 [ 475.130000] pipetype 3 OK after 7 NAKS [ 475.170000] usb-storage: Status code 0; transferred 122880/122880 [ 475.170000] usb-storage: -- transfer complete [ 475.170000] usb-storage: Bulk data transfer result 0x0 [ 475.170000] usb-storage: Attempting to get CSW... [ 475.170000] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes [ 475.170000] usb-storage: Status code 0; transferred 13/13 [ 475.170000] usb-storage: -- transfer complete [ 475.170000] usb-storage: Bulk status result = 0 [ 475.170000] usb-storage: Bulk Status S 0x53425355 T 0x1f5 R 0 Stat 0x0 [ 475.170000] usb-storage: scsi cmd done, result=0x0 [ 475.170000] usb-storage: *** thread sleeping. [ 475.170000] usb-storage: queuecommand_lck called [ 475.170000] usb-storage: *** thread awakened. [ 475.170000] usb-storage: Command WRITE_10 (10 bytes) [ 475.170000] usb-storage: 2a 00 00 00 01 2e 00 00 f0 00 [ 475.170000] usb-storage: Bulk Command S 0x43425355 T 0x1f6 L 122880 F 0 Trg 0 LUN 0 CL 10 [ 475.170000] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes [ 475.170000] usb-storage: Status code 0; transferred 31/31 [ 475.170000] usb-storage: -- transfer complete [ 475.170000] usb-storage: Bulk command transfer result=0 [ 475.170000] usb-storage: usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 8 entries [ 475.180000] >8 NAKS: pipetype 3 len 12288 act 0 [ 475.440000] >8 NAKS: pipetype 3 len 12288 act 0 [ 475.700000] >8 NAKS: pipetype 3 len 12288 act 0 [ 475.960000] >8 NAKS: pipetype 3 len 12288 act 0 [ 476.210000] >8 NAKS: pipetype 3 len 12288 act 0 [ 476.470000] >8 NAKS: pipetype 3 len 12288 act 0 [ 476.730000] >8 NAKS: pipetype 3 len 12288 act 0 [ 476.990000] >8 NAKS: pipetype 3 len 12288 act 0 [ 477.250000] >8 NAKS: pipetype 3 len 12288 act 0 [ 477.510000] >8 NAKS: pipetype 3 len 12288 act 0 [ 477.770000] >8 NAKS: pipetype 3 len 12288 act 0 [ 478.030000] >8 NAKS: pipetype 3 len 12288 act 0 [ 478.290000] >8 NAKS: pipetype 3 len 12288 act 0 [ 478.550000] >8 NAKS: pipetype 3 len 12288 act 0 [ 478.810000] >8 NAKS: pipetype 3 len 12288 act 0 [ 479.070000] >8 NAKS: pipetype 3 len 12288 act 0 [ 479.320000] >8 NAKS: pipetype 3 len 12288 act 0 [ 479.590000] >8 NAKS: pipetype 3 len 12288 act 0 [ 479.790000] max3421_handle_irqs: fnum 1672 urb types 0 0 0 10 errcnt 1474 0 0 0 4563 0 0 0 0 0 0 0 0 0 0 0 [ 479.850000] >8 NAKS: pipetype 3 len 12288 act 0 [ 480.110000] >8 NAKS: pipetype 3 len 12288 act 0 [ 480.370000] >8 NAKS: pipetype 3 len 12288 act 0 [ 480.630000] >8 NAKS: pipetype 3 len 12288 act 0 [ 480.890000] >8 NAKS: pipetype 3 len 12288 act 0 [ 481.150000] >8 NAKS: pipetype 3 len 12288 act 0 [ 481.410000] >8 NAKS: pipetype 3 len 12288 act 0 [ 481.670000] >8 NAKS: pipetype 3 len 12288 act 0 [ 481.930000] >8 NAKS: pipetype 3 len 12288 act 0 [ 482.190000] >8 NAKS: pipetype 3 len 12288 act 0 [ 482.450000] >8 NAKS: pipetype 3 len 12288 act 0 [ 482.710000] >8 NAKS: pipetype 3 len 12288 act 0 [ 482.970000] >8 NAKS: pipetype 3 len 12288 act 0 [ 483.230000] >8 NAKS: pipetype 3 len 12288 act 0 [ 483.490000] >8 NAKS: pipetype 3 len 12288 act 0 [ 483.750000] >8 NAKS: pipetype 3 len 12288 act 0 [ 484.010000] >8 NAKS: pipetype 3 len 12288 act 0 [ 484.270000] >8 NAKS: pipetype 3 len 12288 act 0 [ 484.530000] >8 NAKS: pipetype 3 len 12288 act 0 [ 484.790000] >8 NAKS: pipetype 3 len 12288 act 0 [ 484.810000] max3421_handle_irqs: fnum 467 urb types 0 0 0 0 errcnt 0 0 0 0 4939 0 0 0 0 0 0 0 0 0 0 0 [ 485.050000] >8 NAKS: pipetype 3 len 12288 act 0 [ 485.310000] >8 NAKS: pipetype 3 len 12288 act 0 [ 485.570000] >8 NAKS: pipetype 3 len 12288 act 0 [ 485.830000] >8 NAKS: pipetype 3 len 12288 act 0 [ 486.090000] >8 NAKS: pipetype 3 len 12288 act 0 [ 486.350000] >8 NAKS: pipetype 3 len 12288 act 0 [ 486.610000] >8 NAKS: pipetype 3 len 12288 act 0 [ 486.870000] >8 NAKS: pipetype 3 len 12288 act 0 [ 487.130000] >8 NAKS: pipetype 3 len 12288 act 0 [ 487.390000] >8 NAKS: pipetype 3 len 12288 act 0 [ 487.650000] >8 NAKS: pipetype 3 len 12288 act 0 [ 487.920000] >8 NAKS: pipetype 3 len 12288 act 0 [ 488.180000] >8 NAKS: pipetype 3 len 12288 act 0 [ 488.440000] >8 NAKS: pipetype 3 len 12288 act 0 [ 488.710000] >8 NAKS: pipetype 3 len 12288 act 0 [ 488.970000] >8 NAKS: pipetype 3 len 12288 act 0 [ 489.230000] >8 NAKS: pipetype 3 len 12288 act 0 [ 489.490000] >8 NAKS: pipetype 3 len 12288 act 0 [ 489.750000] >8 NAKS: pipetype 3 len 12288 act 0 [ 489.830000] max3421_handle_irqs: fnum 1296 urb types 0 0 0 0 errcnt 0 0 0 0 4924 0 0 0 0 0 0 0 0 0 0 0 [ 490.010000] >8 NAKS: pipetype 3 len 12288 act 0 [ 490.270000] >8 NAKS: pipetype 3 len 12288 act 0 [ 490.530000] >8 NAKS: pipetype 3 len 12288 act 0 [ 490.790000] >8 NAKS: pipetype 3 len 12288 act 0 [ 491.050000] >8 NAKS: pipetype 3 len 12288 act 0 [ 491.310000] >8 NAKS: pipetype 3 len 12288 act 0 [ 491.570000] >8 NAKS: pipetype 3 len 12288 act 0 [ 491.830000] >8 NAKS: pipetype 3 len 12288 act 0 [ 492.090000] >8 NAKS: pipetype 3 len 12288 act 0 [ 492.350000] >8 NAKS: pipetype 3 len 12288 act 0 [ 492.610000] >8 NAKS: pipetype 3 len 12288 act 0 [ 492.870000] >8 NAKS: pipetype 3 len 12288 act 0 [ 493.130000] >8 NAKS: pipetype 3 len 12288 act 0 [ 493.390000] >8 NAKS: pipetype 3 len 12288 act 0 [ 493.640000] >8 NAKS: pipetype 3 len 12288 act 0 [ 493.910000] >8 NAKS: pipetype 3 len 12288 act 0 [ 494.170000] >8 NAKS: pipetype 3 len 12288 act 0 [ 494.430000] >8 NAKS: pipetype 3 len 12288 act 0 [ 494.700000] >8 NAKS: pipetype 3 len 12288 act 0 [ 494.850000] max3421_handle_irqs: fnum 79 urb types 0 0 0 0 errcnt 0 0 0 0 4927 0 0 0 0 0 0 0 0 0 0 0 [ 494.980000] >8 NAKS: pipetype 3 len 12288 act 0 [ 495.240000] >8 NAKS: pipetype 3 len 12288 act 0 [ 495.500000] >8 NAKS: pipetype 3 len 12288 act 0 [ 495.770000] >8 NAKS: pipetype 3 len 12288 act 0 [ 496.030000] >8 NAKS: pipetype 3 len 12288 act 0 [ 496.340000] >8 NAKS: pipetype 3 len 12288 act 0 [ 496.350000] max3421_remove()
Attachment:
usbmon.out.gz
Description: GNU Zip compressed data
