Wesley Cheng wrote: > Hi Thinh, > > On 2/24/2022 5:26 PM, Thinh Nguyen wrote: >> Hi Wesley, >> >> Wesley Cheng wrote: >>> Hi Thinh, >>> >>> On 2/22/2022 6:59 PM, Thinh Nguyen wrote: >>>> Hi Wesley, >>>> >> >> <snip> >> >>>> >>>> Can you provide a full trace? >>>> >>> Sorry for doing this, but we didn't have a way to share the file >>> directly, so I have to paste the trace below. :/ >>> >>>> Btw, when you experiment with increasing the timeout to 10 seconds, did >>>> you use the mdelay() in each loop? The delta time for End Transfer >>>> timeout here seems very small. >>>> >>> This particular run did not modify the timeout for the cmd status polling. >>> >>> Is that something that you want to try? Not pertaining to this dequeue >>> situation, during the pullup disable path debug, I noticed that as long >>> as there was a pending EP0 SETUP packet (not data/status) cached in the >>> controller, it would also have endxfer timeouts on non-control EPs. We >>> were able to capture a bus sniffer log + ftrace, and it showed that at >>> the point of the error, the lecroy/bus log saw a SETUP token ACK'ed, >>> while on the ftrace, there were endxfer timeouts for all non-control EPs >>> (due to the dwc3_gadget_stop_active_transfers() call) >>> >>> Thanks >>> Wesley >>> >>> TRACE >>> --------------------------------------------------------------------- >>> >> >> <snip> >> >>> [ 1023.912550050 0x4af666fd2] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep4in) >>> [ 1023.912934738 0x4af668cab] dbg_send_ep_cmd: ep0out: cmd 'Set >>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful >>> [ 1023.913361561 0x4af66acae] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1024.336480573 0x4afe2a29b] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep5in) >>> [ 1024.336855573 0x4afe2bebc] dbg_send_ep_cmd: ep5in: cmd 'Clear >>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful >>> [ 1024.337264531 0x4afe2dd68] dbg_send_ep_cmd: ep0in: cmd 'Start >>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful >>> [ 1024.351910156 0x4afe727d4] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1024.363139896 0x4afea720f] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep4in) >>> [ 1024.363898281 0x4afeaaaf0] dbg_send_ep_cmd: ep0out: cmd 'Set >>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful >>> [ 1024.364734010 0x4afeae99e] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1024.776173803 0x4b063739a] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep5in) >>> [ 1024.776907188 0x4b063aa9b] dbg_send_ep_cmd: ep5in: cmd 'Clear >>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful >>> [ 1024.777646147 0x4b063e208] dbg_send_ep_cmd: ep0in: cmd 'Start >>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful >>> [ 1024.788641980 0x4b0671ab8] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1024.799682397 0x4b06a56bf] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep4in) >>> [ 1024.800442605 0x4b06a8fc3] dbg_send_ep_cmd: ep0out: cmd 'Set >>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful >>> [ 1024.801184584 0x4b06ac769] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1025.222173752 0x4b0e61d99] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep5in) >>> [ 1025.222991669 0x4b0e65af1] dbg_send_ep_cmd: ep5in: cmd 'Clear >>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful >>> [ 1025.223850731 0x4b0e69b5f] dbg_send_ep_cmd: ep0in: cmd 'Start >>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful >>> [ 1025.239023492 0x4b0eb0d54] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1025.248963179 0x4b0edf6ce] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep4in) >>> [ 1025.249709846 0x4b0ee2ecd] dbg_send_ep_cmd: ep0out: cmd 'Set >>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful >>> [ 1025.250533440 0x4b0ee6c93] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1025.667084535 0x4b16875e7] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep5in) >>> [ 1025.667827764 0x4b168ada6] dbg_send_ep_cmd: ep5in: cmd 'Clear >>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful >>> [ 1025.668635993 0x4b168ea44] dbg_send_ep_cmd: ep0in: cmd 'Start >>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful >>> [ 1025.674777764 0x4b16ab6e7] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1025.684733597 0x4b16da197] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep4in) >>> [ 1025.685336150 0x4b16dcec7] dbg_send_ep_cmd: ep0out: cmd 'Set >>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful >>> [ 1025.686112608 0x4b16e0904] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: >>> Successful >>> [ 1025.698842347 0x4b171c3bf] dbg_send_ep_cmd: ep0out: cmd 'Set >>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful >>> [ 1026.444051569 0x4b24c1670] dbg_send_ep_cmd: ep0out: cmd >>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: No >>> Resource >> >> Why did this fail with No Resource? Was it sent before the control TRB >> completion? >> >>> [ 1027.225705425 0x4b3311678] dbg_trace_log_ctrl: Clear Endpoint >>> Feature(Halt ep5in) >>> [ 1027.225820165 0x4b3311f14] dbg_send_ep_cmd: ep5in: cmd 'Clear >>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful >>> [ 1027.225931467 0x4b331276c] dbg_send_ep_cmd: ep0in: cmd 'Start >>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful >>> [ 1027.234311467 0x4b3339bed] dbg_ep_dequeue: ep7in: req >>> ffffff87f99b8f00 length 0/61696 zsI ==> -115 >>> [ 1027.247409123 0x4b337723f] dbg_send_ep_cmd: ep7in: cmd 'End >>> Transfer' [f0d08] params 00000000 00000000 00000000 --> status: Timed Out >>> >> >> If the Start Transfer for ep0 failed and the Setup packet can't be >> DMA'ed out, the End Transfer may not go through. >> >> Can you leave the log unfiltered and is it possible to send as >> attachment? It's missing some important info in this log. >> > Are there any specific logs you were looking for? > trace_dwc3_event > trace_dwc3_prepare_trb > > Part of reproducing this issue will not allow me to enable tracing, so I > have to make changes in our driver to reroute the logs elsewhere. So > far I've added changes to do: > trace_dwc3_ctrl_req > trace_dwc3_ep_queue > trace_dwc3_ep_dequeue > trace_dwc3_gadget_giveback > trace_dwc3_gadget_ep_cmd > > I can add the above 2 tracepoints as well, but wondering if you needed > anything else. > If possible, please have these in addition to the above. trace_dwc3_event trace_dwc3_complete_trb Thanks, Thinh
