Hi, (adding linux-usb which I forgot when I sent the original email, sorry) Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> writes: > On Thu, 1 Sep 2016, Felipe Balbi wrote: > >> Hi Alan, Michal, >> >> I think I have emailed the list about this at some point, but I have >> much stronger evidence that g_mass_storage is not enqueueing requests >> when it should. >> >> Here's a snippet of dwc3's tracepoints: >> >> > irq/17-dwc3-3520 [001] d..1 73.736147: dwc3_gadget_giveback: ep1out: req ffff88002898bd80 length 31/1024 zsI ==> 0 >> > irq/17-dwc3-3520 [001] d... 73.736147: usb_gadget_giveback_request: ep1out: length 31/1024 sgs 0/0 stream 0 zsI status 0 --> 0 >> >> We received CBW. >> >> > file-storage-3519 [002] d..1 73.736157: dwc3_ep_queue: ep1in: req ffff88002898b180 length 0/16384 zsI ==> -115 >> >> g_mass_storage queues first 16kiB (enqueue 1) >> >> > file-storage-3519 [002] d..1 73.736165: dwc3_gadget: ep1in: req ffff88002898b180 dma 28654000 length 16384 >> > file-storage-3519 [002] d..1 73.736166: dwc3_prepare_trb: ep1in: 1/255 trb ffff8800874134c0 buf 0000000028654000 size 16384 ctrl 00000c19 (HlcS:SC:normal) >> > file-storage-3519 [002] d..1 73.736173: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful >> > file-storage-3519 [002] .... 73.736174: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 >> >> which is started to HW >> >> > file-storage-3519 [002] d..1 73.736178: dwc3_ep_queue: ep1in: req ffff88002898bcc0 length 0/16384 zsI ==> -115 >> > file-storage-3519 [002] d..1 73.736183: dwc3_gadget: ep1in: req ffff88002898bcc0 dma 28658000 length 16384 >> > file-storage-3519 [002] d..1 73.736184: dwc3_prepare_trb: ep1in: 2/255 trb ffff8800874134d0 buf 0000000028658000 size 16384 ctrl 00000c19 (HlcS:SC:normal) >> > file-storage-3519 [002] d..1 73.736187: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful >> > file-storage-3519 [002] .... 73.736188: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 >> >> enqueue 2 > > ... > >> > file-storage-3519 [002] d..1 73.736260: dwc3_ep_queue: ep1in: req ffff88002898c840 length 0/13 zsI ==> -115 >> > file-storage-3519 [002] d..1 73.736264: dwc3_gadget: ep1in: req ffff88002898c840 dma 28674000 length 13 >> > file-storage-3519 [002] d..1 73.736265: dwc3_prepare_trb: ep1in: 9/255 trb ffff880087413540 buf 0000000028674000 size 13 ctrl 00000c19 (HlcS:SC:normal) >> > file-storage-3519 [002] d..1 73.736267: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful >> > file-storage-3519 [002] .... 73.736267: usb_ep_queue: ep1in: length 0/13 sgs 0/0 stream 0 zsI status -115 --> 0 >> >> enqueue 9 (this is CSW) >> >> > file-storage-3519 [002] d..1 73.736267: dwc3_ep_queue: ep1out: req ffff88002898c240 length 0/1024 zsI ==> -115 >> > file-storage-3519 [002] d..1 73.736271: dwc3_gadget: ep1out: req ffff88002898c240 dma 28678000 length 1024 >> > file-storage-3519 [002] d..1 73.736272: dwc3_prepare_trb: ep1out: 1/255 trb ffff8800874040b0 buf 0000000028678000 size 1024 ctrl 00000c19 (HlcS:SC:normal) >> > file-storage-3519 [002] d..1 73.736274: dwc3_gadget_ep_cmd: ep1out: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> status: Successful >> > file-storage-3519 [002] .... 73.736274: usb_ep_queue: ep1out: length 0/1024 sgs 0/0 stream 0 zsI status -115 --> 0 >> >> enqueue 10 (another CBW) >> >> > irq/17-dwc3-3520 [001] d..1 73.736280: dwc3_event: event (00004086): ep1in: Transfer In-Progress >> > irq/17-dwc3-3520 [001] d..1 73.736280: dwc3_complete_trb: ep1in: 8/255 trb ffff8800874134c0 buf 0000000028654000 size 0 ctrl 00000c18 (hlcS:SC:normal) >> > irq/17-dwc3-3520 [001] d..1 73.736281: dwc3_gadget_giveback: ep1in: req ffff88002898b180 length 16384/16384 zsI ==> 0 >> > irq/17-dwc3-3520 [001] d... 73.736281: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 >> >> complete 1 > > ... > >> complete 9 (CSW) >> >> > irq/17-dwc3-3520 [001] d..1 73.736697: dwc3_event: event (00006084): ep1in: Transfer In-Progress >> >> this is actually ep1out: Transfer In-Progress, have already patched this >> error on trace output (see [1]). Basically this is telling me our CBW >> completed, we received it. >> >> > irq/17-dwc3-3520 [001] d..1 73.736698: dwc3_complete_trb: ep1out: 0/255 trb ffff8800874040b0 buf 0000000028678000 size 993 ctrl 00000c18 (hlcS:SC:normal) >> >> we can confirm it here. 1024 - 31 = 993 (complete 10) >> >> > irq/17-dwc3-3520 [001] d..1 73.736699: dwc3_gadget_giveback: ep1out: req ffff88002898c240 length 31/1024 zsI ==> 0 >> > irq/17-dwc3-3520 [001] d... 73.736699: usb_gadget_giveback_request: ep1out: length 31/1024 sgs 0/0 stream 0 zsI status 0 --> 0 >> >> give it back to gadget driver and... nothing happens. I can see the same >> thing on sniffer (see screenshot at [2]). Why would mass storage avoid >> queueing requests like that? >> >> If you want details about the contents of that last CBW, here you go: >> >> 55 53 42 43 17 01 00 00 00 00 02 00 80 00 0A 28 >> 00 00 00 CD 00 00 01 00 00 00 00 00 00 00 00 >> >> Basically, this is a READ(10) of 256 blocks (512 bsize * 256 blocks = 128 kiB) >> >> Any ideas on how to debug this would be apreciated. > > You can start by enabling verbose debugging in f_mass_storage.c. > Uncomment the two lines that say: > > /* #define VERBOSE_DEBUG */ > /* #define DUMP_MSGS */ > > You'll probably also have to enable dynamic debugging for the > g_mass_storage module. right, I'll do that tomorrow. I'll probably need some rather larger kernel logbuf too. Hopefully some 8MiB is enough. > Alan Stern > >> [1] https://marc.info/?l=linux-usb&m=147211066411575&w=2 >> [2] http://imgur.com/kAqqnpp > -- balbi -- 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
