Alan Stern wrote: > On Fri, 25 Mar 2011, Arvid Brodin wrote: > >> Sorry about my sloppy language. :) I'm not exactly sure what happens, but the >> symptoms is the cp (or sync) never returns and cannot be terminated by ctrl-c. >> The usb analyzer shows one NAKed IN transfer every 9 micro-seconds, or >> thereabouts. I also get this: >> >> INFO: task scsi_eh_0:491 blocked for more than 120 seconds. >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. >> scsi_eh_0 D 9028ba06 0 491 2 0x00000000 >> Stack: (0x93ed7eb8 to 0x93ed8000) >> 7ea0: 93ed6000 9028bd3c >> 7ec0: 90025178 9028bd3c 93ed7f1c 93df9630 93df962c 7fffffff 00000002 ffffe000 >> ... >> Call trace: >> [<9028bd3c>] schedule_timeout+0x14/0x170 >> [<9028bc12>] wait_for_common+0xaa/0x10c >> [<9028bcec>] wait_for_completion+0xc/0x14 >> [<901b674e>] command_abort+0x7a/0xa0 >> [<9018a4aa>] scsi_try_to_abort_cmd+0x1e/0x22 >> [<9018b976>] scsi_error_handler+0xda/0x29c >> [<9003d612>] kthread+0x5c/0x76 >> [<9002d894>] do_exit+0x0/0x524 >> >> no locks held by scsi_eh_0/491. > > That's normal for a hung system. Of course, the real question is why > is it hanging? Probably a bug in the isp176x driver. > You were right; I did not unlink active packets correctly. After fixing, I now get a device reset after 30 s just like you said I should! However I still have the problem of the device STALLing for 30 s a few times per megabyte or so. Any clues from the following info? >From the USB bus analyser: ... OUT 003:2 ACK 512 bytes OUT 003:2 ACK 512 bytes OUT 003:2 ACK 512 bytes OUT 003:2 NYET 511 bytes IN 003:1 ACK 13 bytes OUT 003:2 ACK 30 bytes OUT 003:2 STALL 512 bytes Device Request: Clear Feature Endpoint Halt (003:0 OK) <30 s of IN NAKs> Device Reset I guess this matches the "-32 line" and the line above that in the corresponding usbmon dump (taken on 2.6.27): ... 93996200 659495767 S Bi:1:003:1 -115 13 < 93996200 659496030 C Bi:1:003:1 0 13 = 55534253 0000006f 00000000 00 93996200 659497681 S Bo:1:003:2 -115 31 = 55534243 00000070 00e00100 00000a2a 00000ca7 e80000f0 00000000 000000 93996200 659497852 C Bo:1:003:2 0 31 > 93996800 659497990 S Bo:1:003:2 -115 32768 = 403f518d 337a68f1 c7f651ed 0889d5ed a213cd76 73811e68 b6bd4746 2080c422 93996880 659498651 S Bo:1:003:2 -115 65536 = f4084289 f573422f c620b17f 9743a720 da104d27 699e0810 0ab2ba9a 443d3489 93996900 659499000 S Bo:1:003:2 -115 24576 = 04713170 e4093fd4 feba8615 2ce94705 84dab6a5 64e355bc 54b7293c 3b168ade 93996800 659506453 C Bo:1:003:2 0 32768 > 93996880 659522453 C Bo:1:003:2 0 65536 > 93996900 659529452 C Bo:1:003:2 0 24576 > 93996200 659529774 S Bi:1:003:1 -115 13 < 93996200 659529948 C Bi:1:003:1 0 13 = 55534253 00000070 00000000 00 93996200 659531264 S Bo:1:003:2 -115 31 = 55534243 00000071 00e00100 00000a2a 00000ca8 d80000f0 00000000 000000 93996200 659531463 C Bo:1:003:2 0 31 > 93996800 659531660 S Bo:1:003:2 -115 40960 = 8dfc378f ecc64464 f3f5a0f9 593a6c07 d52f13ae 4ce0f396 ad80a868 be88f9b9 93996800 659532401 C Bo:1:003:2 -32 0 <STALL above (-32)> Is it normal that usbmon thinks that the urb above the stalling one have 31 bytes, while the USB analyser says 30 bytes? Seems weird to me... (the earlier 13/31 byte transfers are reported as such by the analyser). The continued dump, complete until the next STALL: 93996200 659532770 S Co:1:003:0 s 02 01 0000 0002 0000 0 93996200 659533441 C Co:1:003:0 0 0 93996200 659533735 S Bi:1:003:1 -115 13 < 93996200 689531155 C Bi:1:003:1 -104 0 93996800 689535041 S Co:1:002:0 s 23 03 0004 0002 0000 0 93996800 689538799 C Co:1:002:0 0 0 93996800 689553248 S Ci:1:002:0 s a3 00 0000 0002 0004 4 < 93996800 689557669 C Ci:1:002:0 0 4 = 03051000 93949300 689559565 C Ii:1:002:1 0:2048 1 = 04 93949300 689559768 S Ii:1:002:1 -115:2048 1 < 93949300 689591604 C Ii:1:002:1 0:2048 1 = 04 93949300 689591803 S Ii:1:002:1 -115:2048 1 < 93996800 689613193 S Co:1:002:0 s 23 01 0014 0002 0000 0 93996800 689615737 C Co:1:002:0 0 0 93996800 689623081 S Ci:1:000:0 s 80 06 0100 0000 0040 64 < 93996800 689628651 C Ci:1:000:0 0 18 = 12010002 00000040 a61a0102 00100102 0301 93996800 689633910 S Co:1:002:0 s 23 03 0004 0002 0000 0 93996800 689634650 C Co:1:002:0 0 0 93996800 689649227 S Ci:1:002:0 s a3 00 0000 0002 0004 4 < 93996800 689650679 C Ci:1:002:0 0 4 = 03051000 93949300 689655599 C Ii:1:002:1 0:2048 1 = 04 93949300 689655801 S Ii:1:002:1 -115:2048 1 < 93949300 689687596 C Ii:1:002:1 0:2048 1 = 04 93949300 689687794 S Ii:1:002:1 -115:2048 1 < 93996800 689705571 S Co:1:002:0 s 23 01 0014 0002 0000 0 93996800 689706764 C Co:1:002:0 0 0 93996800 689707310 S Co:1:000:0 s 00 05 0003 0000 0000 0 93996800 689707664 C Co:1:000:0 0 0 93996800 689721157 S Ci:1:003:0 s 80 06 0100 0000 0012 18 < 93996800 689725691 C Ci:1:003:0 0 18 = 12010002 00000040 a61a0102 00100102 0301 93996800 689726232 S Ci:1:003:0 s 80 06 0200 0000 0020 32 < 93996800 689728663 C Ci:1:003:0 0 32 = 09022000 01010080 32090400 00020806 50000705 81020002 ff070502 020002ff 93996800 689729205 S Ci:1:003:0 s 80 06 0303 0409 00ff 255 < 93996800 689731670 C Ci:1:003:0 0 30 = 1e033000 34003200 33003000 38003300 39003500 34003200 33003900 3200 93996800 689732175 S Co:1:003:0 s 00 09 0001 0000 0000 0 93996800 689732624 C Co:1:003:0 0 0 93996800 689733312 S Co:1:003:0 s 01 0b 0000 0000 0000 0 93996800 689733664 C Co:1:003:0 0 0 93996200 689737410 S Bo:1:003:2 -115 31 = 55534243 00000072 00000000 00000600 00000000 00000000 00000000 000000 93996200 689737709 C Bo:1:003:2 0 31 > 93996200 689741157 S Bi:1:003:1 -115 13 < 93996200 689741491 C Bi:1:003:1 0 13 = 55534253 00000072 00000000 00 93996200 689743301 S Bo:1:003:2 -115 31 = 55534243 00000073 00000000 0000061e 00000001 00000000 00000000 000000 93996200 689743571 C Bo:1:003:2 0 31 > 93996200 689743743 S Bi:1:003:1 -115 13 < 93996200 689743956 C Bi:1:003:1 0 13 = 55534253 00000073 00000000 00 93996200 689747585 S Bo:1:003:2 -115 31 = 55534243 00000074 00e00100 00000a2a 00000ca8 d80000f0 00000000 000000 93996200 689747925 C Bo:1:003:2 0 31 > 93996800 689748173 S Bo:1:003:2 -115 40960 = 8dfc378f ecc64464 f3f5a0f9 593a6c07 d52f13ae 4ce0f396 ad80a868 be88f9b9 93996880 689749223 S Bo:1:003:2 -115 65536 = 53e47a1a 8c6b3aca 9d4c765c 974b5ae0 e33c2227 a4f6d0cd b61e5050 3312a7fb 93996900 689749691 S Bo:1:003:2 -115 16384 = 6ea7ff8b 26283d1e 6f828066 1ce0820d 3fe032ab 1a6e88bf be5551a7 3fc1eace 93996800 689789704 C Bo:1:003:2 0 40960 > 93996880 689805703 C Bo:1:003:2 0 65536 > 93996900 689809684 C Bo:1:003:2 0 16384 > 93996200 689810632 S Bi:1:003:1 -115 13 < 93996200 689810973 C Bi:1:003:1 0 13 = 55534253 00000074 00000000 00 93996200 689814734 S Bo:1:003:2 -115 31 = 55534243 00000075 00e00100 00000a2a 00000ca9 c80000f0 00000000 000000 93996200 689815080 C Bo:1:003:2 0 31 > 93996800 689815338 S Bo:1:003:2 -115 49152 = 909856e0 71ec3f0d 031b52d9 2f953dc0 6d633909 bbe7bae3 8b0efb72 3eb2a8d1 93996800 689816228 C Bo:1:003:2 -32 0 <STALL above (-32)> Thanks, Arvid Brodin Enea Services Stockholm AB -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
