>>> I need tracepoints to see what's going on, please collect tracepoints. >> >> See attached. Search for "length 16384/16384" to the USB request using >> sg list. And the transfer stalls at a request with "length 512/512". > > which gadget driver is this btw? Let's look at what happened leading up to this problem: I'm using the upstream kernel with some Android patches from Google. Comparing to pure upstream, there is no change in drivers/usb/dwc3/. There are a few Android patches on top of drivers/usb/gadget, but those don't seem to have anything to do with this case as the patches are changing things like f_accessory/f_audio/f_midi. >> <...>-3107 [001] d..1 164.184431: dwc3_alloc_request: ep1out: req 0000000066963d3c length 0/0 zsI ==> 0 > > Allocated a new request > >> <...>-3107 [001] d..2 164.184432: dwc3_ep_queue: ep1out: req 0000000066963d3c length 0/16384 zsI ==> -115 > > queued it for a 16kiB transfer (split into 3 sglist entries) > >> <...>-3107 [001] d..2 164.184433: dwc3_prepare_trb: ep1out: trb 0000000011fb30b4 buf 0000000077caf000 size 4096 ctrl 0000001d (HlCS:sc:normal) > > first one, 4kiB. Note the capital 'C', this one is chained. > >> <...>-3107 [001] d..2 164.184433: dwc3_prepare_trb: ep1out: trb 00000000bc197bc2 buf 0000000077cb0000 size 8192 ctrl 0000001d (HlCS:sc:normal) > >second one, 8kiB. Also chained. > >> <...>-3107 [001] d..2 164.184433: dwc3_prepare_trb: ep1out: trb 00000000ae5c00ad buf 0000000077cb2000 size 4096 ctrl 00000819 (HlcS:sC:normal) > > last one, 4kiB. NOT CHAINED! > >> <...>-3107 [001] d..2 164.184438: dwc3_gadget_ep_cmd: ep1out: cmd 'Update Transfer' [20007] params 00000000 00000000 00000000 --> status: Successful > > issue update transfer > >> <...>-3107 [001] d..1 164.184444: dwc3_alloc_request: ep1out: req 00000000fe2c6e9d length 0/0 zsI ==> 0 > > now gadget driver allocates a NEW request > >> <...>-3107 [001] d..2 164.184444: dwc3_ep_queue: ep1out: req 00000000fe2c6e9d length 0/512 zsI ==> -115 > > ... and queues it for zero bytes. Why? Why didn't gadget driver set the ZERO flag in the original request? I don't see any difference between this request and the one above for 16Kbyte (except the length). Why are you expecting "Z" to be set? The 0 is request.actual, which is correct at this point of time. >> <...>-3107 [001] d..2 164.184445: dwc3_prepare_trb: ep1out: trb 0000000055827a46 buf 0000000077cb3000 size 512 ctrl 00000819 (HlcS:sC:normal) > > a single TRB is prepared correctly. > >> <...>-3107 [001] d..2 164.184449: dwc3_gadget_ep_cmd: ep1out: cmd 'Update Transfer' [20007] params 00000000 00000000 00000000 --> status: Successful > > Update transfer is issued. > >> <...>-3165 [001] d..1 164.192315: dwc3_event: event (00004084): ep1out: Transfer In Progress [0] (sIm) >> <...>-3165 [001] d..1 164.192316: dwc3_complete_trb: ep1out: trb 0000000017050f80 buf 0000000077c63000 size 0 ctrl 0000001c (hlCS:sc:normal) >> <...>-3165 [001] d..1 164.192325: dwc3_gadget_giveback: ep1out: req 00000000af8aa80e length 16384/16384 zsI ==> 0 >> kworker/u8:5-1165 [001] .... 164.192353: dwc3_free_request: ep1out: req 00000000af8aa80e length 16384/16384 zsI ==> 0 >> <...>-3165 [001] d..1 164.192849: dwc3_event: event (00004084): ep1out: Transfer In Progress [0] (sIm) >> <...>-3165 [001] d..1 164.192851: dwc3_complete_trb: ep1out: trb 00000000c1f0fd23 buf 0000000077c64000 size 0 ctrl 0000001c (hlCS:sc:normal) >> <...>-3165 [001] d..1 164.192860: dwc3_gadget_giveback: ep1out: req 0000000066963d3c length 16384/16384 zsI ==> 0 > > here we giveback the request to the gadget driver. Note that the TRB addresses that were completed do NOT match the TRB addresses of the prepared TRBs. > Again, which gadget driver is this? Where is the source code for this gadget driver? Also note that we requested for event upon completion of the final TRB only > but we get events for each and every TRB. I don't know how to interpret this trace log, but it didn't help me find the problem until I added my own log in the prepare_trb() and completed_trb() [ 86.817218] ffs_epfile_io:READ:SG: buf=00000000fcc78b10 sg=00000000952c5428 length=16384 num_sgs=4 [ 86.827242] __dwc3_prepare_one_trb: size=4096 bp=000000007780d000 ctrl=0000001d enq=b3 [ 86.836172] __dwc3_prepare_one_trb: size=4096 bp=000000007780e000 ctrl=0000001d enq=b4 [ 86.845100] __dwc3_prepare_one_trb: size=4096 bp=000000007780f000 ctrl=0000001d enq=b5 [ 86.854028] __dwc3_prepare_one_trb: size=4096 bp=0000000077810000 ctrl=00000819 enq=b6 [ 86.862959] __dwc3_gadget_kick_transfer: updating buf=00000000be7c4a4c sg=00000000952c5428 length=16384 pending_sgs=4 remaining=0 [ 86.876146] ffs_epfile_io:READ:SG: buf=000000008b573d0c sg=00000000d7992341 length=16384 num_sgs=4 [ 86.886159] __dwc3_prepare_one_trb: size=4096 bp=0000000077811000 ctrl=0000001d enq=b7 [ 86.895091] __dwc3_prepare_one_trb: size=4096 bp=0000000077812000 ctrl=0000001d enq=b8 [ 86.904023] __dwc3_prepare_one_trb: size=4096 bp=0000000077813000 ctrl=0000001d enq=b9 [ 86.912955] __dwc3_prepare_one_trb: size=4096 bp=0000000077814000 ctrl=00000819 enq=ba [ 86.921890] __dwc3_gadget_kick_transfer: updating buf=00000000be7c4a4c sg=00000000952c5428 length=16384 pending_sgs=4 remaining=0 [ 86.934979] dwc3_gadget_ep_reclaim_completed_trb(1): buf=00000000be7c4a4c sg=00000000952c5428 status=0 ctrl=0000001c length=16384 pending_sgs=3 trb_size=0 evstatus=00000004 [ 86.936025] ffs_epfile_io:READ:SG: buf=000000006cee33d6 sg=00000000244e9645 length=16384 num_sgs=4 [ 86.952253] dwc3_gadget_ep_reclaim_completed_trb(1): buf=00000000be7c4a4c sg=00000000d7992341 status=0 ctrl=0000001c length=16384 pending_sgs=3 trb_size=0 evstatus=00000004 >From this log, you can clearly see each sg list gets only one reclaim_completed_trb() call, and the trb reclaimed is not the last one (ctrl=0000001c, the last one should have ctrl=00000818). The trb addresses is continuous as indicated by bp=000000007780d000 to bp=0000000077814000 with 4K increment in between. Also you can see that event->status has IOC bit set (evstatus=00000004), so the for-loop to reclaim all trb in the sg list breaks out right after the first trb is reclaimed.
