DWC3 Isoc Gadget Missed Interrupts on Start Transfer

DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Michael Grzeschik]

[-- Attachment #1: Type: text/plain, Size: 24766 bytes --]

Hi Thinh!

I am currently debugging a strange error with transferring isoc requests with
the current mainline driver.

When the pending and started list is empty the complete interrupt handler is
sending an End Transfer to the controller. This End Transfer will then get
successfully completed.

     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd: ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 --> status: Successful
     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event (080b01d6): ep5in: Endpoint Command Complete
     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)


After this the Transfer needs to start again. But unfortunately this sometimes
does not succeed. You see in the following trace that the Start of the just
prepared trbs did complete with an -18.

    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb: ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size 1x 12 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb: ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691313: dwc3_gadget_ep_cmd: ep5in: cmd 'Start Transfer' [49140406] params 0000ffff ffff3e80 00000000 --> status: Bus Expiry
    kworker/u5:2-347     [001] d..2.   166.691327: dwc3_gadget_ep_cmd: ep5in: cmd 'Start Transfer' [49150406] params 0000ffff ffff3e80 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691351: dwc3_prepare_trb: ep5in: trb 00000000207832b0 (E235:D232) buf 0000ffffffb202e8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691356: dwc3_prepare_trb: ep5in: trb 000000007a081501 (E236:D232) buf 0000ffffffb21bf4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691362: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691384: dwc3_prepare_trb: ep5in: trb 0000000072f4be38 (E237:D232) buf 0000ffffffb24168 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691389: dwc3_prepare_trb: ep5in: trb 00000000596ad302 (E238:D232) buf 0000ffffffb257ec size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691394: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691419: dwc3_prepare_trb: ep5in: trb 00000000b313a087 (E239:D232) buf 0000ffffffb284e8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691423: dwc3_prepare_trb: ep5in: trb 000000000667492d (E240:D232) buf 0000ffffffb293e4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691429: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691451: dwc3_prepare_trb: ep5in: trb 00000000459ec17b (E241:D232) buf 0000ffffffb305a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691455: dwc3_prepare_trb: ep5in: trb 00000000f5ca2c22 (E242:D232) buf 0000ffffffb31fdc size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691461: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691483: dwc3_prepare_trb: ep5in: trb 0000000074be44bd (E243:D232) buf 0000ffffffb34b28 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691487: dwc3_prepare_trb: ep5in: trb 000000009b1475ad (E244:D232) buf 0000ffffffb35bd4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691492: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
     irq/50-dwc3-305     [000] d..1.   166.691502: dwc3_complete_trb: ep5in: trb 000000007ff95a12 (E244:D233) buf 0000ffffffb1c2a8 size 1x 0 ctrl 12454464:00004915 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.691505: dwc3_complete_trb: ep5in: trb 00000000f9cd175e (E244:D234) buf 0000ffffffb1d000 size 1x 7168 ctrl 12454470:00004915 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.691515: dwc3_gadget_giveback: ep5in: req 0000000090943319 length 0/7168 zsi ==> -18
    kworker/u5:2-347     [001] d..2.   166.691525: dwc3_prepare_trb: ep5in: trb 0000000008992ded (E245:D234) buf 0000ffffffe00d68 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691530: dwc3_prepare_trb: ep5in: trb 0000000099db8537 (E246:D234) buf 0000ffffffe017cc size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691535: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691560: dwc3_prepare_trb: ep5in: trb 000000009a32f3df (E247:D234) buf 0000ffffffdfc8e8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691564: dwc3_prepare_trb: ep5in: trb 0000000099e18287 (E248:D234) buf 0000ffffffdfd3c4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691570: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691593: dwc3_prepare_trb: ep5in: trb 0000000069755327 (E249:D234) buf 0000ffffffdf8e28 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691597: dwc3_prepare_trb: ep5in: trb 00000000b4ea3844 (E250:D234) buf 0000ffffffdf9fbc size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691603: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691626: dwc3_prepare_trb: ep5in: trb 000000004356a51c (E251:D234) buf 0000ffffffdf4f68 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691630: dwc3_prepare_trb: ep5in: trb 0000000005790196 (E252:D234) buf 0000ffffffdf5bb4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691636: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691657: dwc3_prepare_trb: ep5in: trb 00000000eabf4b9c (E253:D234) buf 0000ffffffdf0ce8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691661: dwc3_prepare_trb: ep5in: trb 00000000e5b7688c (E254:D234) buf 0000ffffffdf17ac size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691667: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691688: dwc3_prepare_trb: ep5in: trb 000000007a2518a4 (E0:D234) buf 0000ffffffdec8a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691693: dwc3_prepare_trb: ep5in: trb 000000005d8805e7 (E1:D234) buf 0000ffffffded3a4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691698: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691720: dwc3_prepare_trb: ep5in: trb 00000000b2243432 (E2:D234) buf 0000ffffffde8568 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691724: dwc3_prepare_trb: ep5in: trb 000000009d420079 (E3:D234) buf 0000ffffffde9f9c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691730: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691751: dwc3_prepare_trb: ep5in: trb 00000000649fe5d6 (E4:D234) buf 0000ffffff9c8c28 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691756: dwc3_prepare_trb: ep5in: trb 000000006d01d4b7 (E5:D234) buf 0000ffffff9c9b94 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691761: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691783: dwc3_prepare_trb: ep5in: trb 00000000a7d5ae23 (E6:D234) buf 0000ffffffbcc368 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691788: dwc3_prepare_trb: ep5in: trb 00000000f63c85d3 (E7:D234) buf 0000ffffffbcd78c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691793: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691816: dwc3_prepare_trb: ep5in: trb 00000000893379d8 (E8:D234) buf 0000ffffffbd09a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691820: dwc3_prepare_trb: ep5in: trb 0000000010adff65 (E9:D234) buf 0000ffffffbd1384 size 1x 7160 ctrl 00000c71:00000000 (Hlcs:SC:isoc)
    kworker/u5:2-347     [001] d..2.   166.691826: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691848: dwc3_prepare_trb: ep5in: trb 000000003c91f4e3 (E10:D234) buf 0000ffffffbd47e8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691852: dwc3_prepare_trb: ep5in: trb 000000001eb9a46d (E11:D234) buf 0000ffffffbd5f7c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691858: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691880: dwc3_prepare_trb: ep5in: trb 000000008039b4f5 (E12:D234) buf 0000ffffffbd80a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691884: dwc3_prepare_trb: ep5in: trb 000000003acd9b86 (E13:D234) buf 0000ffffffbd9b74 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691890: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691912: dwc3_prepare_trb: ep5in: trb 0000000016625d76 (E14:D234) buf 0000ffffffbbcc68 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691916: dwc3_prepare_trb: ep5in: trb 000000005060be63 (E15:D234) buf 0000ffffffbbd76c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691922: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691943: dwc3_prepare_trb: ep5in: trb 000000006c7ec562 (E16:D234) buf 0000ffffffbc0768 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691948: dwc3_prepare_trb: ep5in: trb 00000000153e7b58 (E17:D234) buf 0000ffffffbc1364 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691953: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.691975: dwc3_prepare_trb: ep5in: trb 00000000d79e8ccd (E18:D234) buf 0000ffffffbc4f28 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.691979: dwc3_prepare_trb: ep5in: trb 000000002ebdf5db (E19:D234) buf 0000ffffffbc5f5c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.691985: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.692008: dwc3_prepare_trb: ep5in: trb 0000000036246e8f (E20:D234) buf 0000ffffffbc8aa8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.692012: dwc3_prepare_trb: ep5in: trb 000000000f75f134 (E21:D234) buf 0000ffffffbc9b54 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.692018: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.692040: dwc3_prepare_trb: ep5in: trb 00000000ca9d0693 (E22:D234) buf 0000ffffff9c4528 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.692044: dwc3_prepare_trb: ep5in: trb 000000008587c7c2 (E23:D234) buf 0000ffffff9c574c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.692050: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.692072: dwc3_prepare_trb: ep5in: trb 0000000003ad0d16 (E24:D234) buf 0000ffffff9c07a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.692076: dwc3_prepare_trb: ep5in: trb 0000000054e33de9 (E25:D234) buf 0000ffffff9c1344 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.692081: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.692103: dwc3_prepare_trb: ep5in: trb 000000006598a295 (E26:D234) buf 0000ffffff9a0668 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.692108: dwc3_prepare_trb: ep5in: trb 0000000015487935 (E27:D234) buf 0000ffffff9a1f3c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.692114: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.692136: dwc3_prepare_trb: ep5in: trb 00000000ef2871fc (E28:D234) buf 0000ffffff978ea8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.692140: dwc3_prepare_trb: ep5in: trb 0000000013e0668f (E29:D234) buf 0000ffffff979b34 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.692146: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.692167: dwc3_prepare_trb: ep5in: trb 0000000092e94032 (E30:D234) buf 0000ffffff94c428 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.692172: dwc3_prepare_trb: ep5in: trb 0000000002970903 (E31:D234) buf 0000ffffff94d72c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:2-347     [001] d..2.   166.692177: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:2-347     [001] d..2.   166.692200: dwc3_prepare_trb: ep5in: trb 00000000b3249549 (E32:D234) buf 0000ffffff8bc068 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:2-347     [001] d..2.   166.692205: dwc3_prepare_trb: ep5in: trb 00000000ec88603f (E33:D234) buf 0000ffffff8bd324 size 1x 1221 ctrl 00000c71:00000000 (Hlcs:SC:isoc)
    kworker/u5:2-347     [001] d..2.   166.692211: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
     irq/50-dwc3-305     [000] d..1.   166.698763: dwc3_complete_trb: ep5in: trb 00000000207832b0 (E33:D235) buf 0000ffffffb202e8 size 1x 0 ctrl 12458464:00004916 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.698766: dwc3_complete_trb: ep5in: trb 000000007a081501 (E33:D236) buf 0000ffffffb21bf4 size 1x 7168 ctrl 12458470:00004916 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.698773: dwc3_gadget_giveback: ep5in: req 00000000a3af67aa length 0/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.705998: dwc3_complete_trb: ep5in: trb 0000000072f4be38 (E33:D237) buf 0000ffffffb24168 size 1x 0 ctrl 1245c464:00004917 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.706002: dwc3_complete_trb: ep5in: trb 00000000596ad302 (E33:D238) buf 0000ffffffb257ec size 1x 0 ctrl 1245c470:00004917 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.706008: dwc3_gadget_giveback: ep5in: req 00000000efe24442 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.713228: dwc3_complete_trb: ep5in: trb 00000000b313a087 (E33:D239) buf 0000ffffffb284e8 size 1x 0 ctrl 12460464:00004918 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.713231: dwc3_complete_trb: ep5in: trb 000000000667492d (E33:D240) buf 0000ffffffb293e4 size 1x 0 ctrl 12460470:00004918 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.713238: dwc3_gadget_giveback: ep5in: req 00000000be20abd7 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.720459: dwc3_complete_trb: ep5in: trb 00000000459ec17b (E33:D241) buf 0000ffffffb305a8 size 1x 0 ctrl 12464464:00004919 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.720462: dwc3_complete_trb: ep5in: trb 00000000f5ca2c22 (E33:D242) buf 0000ffffffb31fdc size 1x 0 ctrl 12464470:00004919 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.720469: dwc3_gadget_giveback: ep5in: req 00000000c7d419e1 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.727689: dwc3_complete_trb: ep5in: trb 0000000074be44bd (E33:D243) buf 0000ffffffb34b28 size 1x 0 ctrl 12468464:0000491a (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.727693: dwc3_complete_trb: ep5in: trb 000000009b1475ad (E33:D244) buf 0000ffffffb35bd4 size 1x 0 ctrl 12468470:0000491a (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.727699: dwc3_gadget_giveback: ep5in: req 000000002b31980b length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.734920: dwc3_complete_trb: ep5in: trb 0000000008992ded (E33:D245) buf 0000ffffffe00d68 size 1x 0 ctrl 1246c464:0000491b (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.734923: dwc3_complete_trb: ep5in: trb 0000000099db8537 (E33:D246) buf 0000ffffffe017cc size 1x 0 ctrl 1246c470:0000491b (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.734930: dwc3_gadget_giveback: ep5in: req 00000000e62a3292 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.742150: dwc3_complete_trb: ep5in: trb 000000009a32f3df (E33:D247) buf 0000ffffffdfc8e8 size 1x 0 ctrl 12470464:0000491c (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.742153: dwc3_complete_trb: ep5in: trb 0000000099e18287 (E33:D248) buf 0000ffffffdfd3c4 size 1x 0 ctrl 12470470:0000491c (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.742161: dwc3_gadget_giveback: ep5in: req 00000000ebfe68aa length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.749381: dwc3_complete_trb: ep5in: trb 0000000069755327 (E33:D249) buf 0000ffffffdf8e28 size 1x 0 ctrl 12474464:0000491d (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.749384: dwc3_complete_trb: ep5in: trb 00000000b4ea3844 (E33:D250) buf 0000ffffffdf9fbc size 1x 0 ctrl 12474470:0000491d (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.749390: dwc3_gadget_giveback: ep5in: req 0000000048685fa4 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.756611: dwc3_complete_trb: ep5in: trb 000000004356a51c (E33:D251) buf 0000ffffffdf4f68 size 1x 0 ctrl 12478464:0000491e (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.756614: dwc3_complete_trb: ep5in: trb 0000000005790196 (E33:D252) buf 0000ffffffdf5bb4 size 1x 0 ctrl 12478470:0000491e (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.756621: dwc3_gadget_giveback: ep5in: req 0000000053b4813f length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.763842: dwc3_complete_trb: ep5in: trb 00000000eabf4b9c (E33:D253) buf 0000ffffffdf0ce8 size 1x 0 ctrl 1247c464:0000491f (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.763845: dwc3_complete_trb: ep5in: trb 00000000e5b7688c (E33:D254) buf 0000ffffffdf17ac size 1x 0 ctrl 1247c470:0000491f (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.763851: dwc3_gadget_giveback: ep5in: req 000000009ccc1e16 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.771072: dwc3_complete_trb: ep5in: trb 000000007a2518a4 (E33:D0) buf 0000ffffffdec8a8 size 1x 0 ctrl 12480464:00004920 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.771075: dwc3_complete_trb: ep5in: trb 000000005d8805e7 (E33:D1) buf 0000ffffffded3a4 size 1x 0 ctrl 12480470:00004920 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.771081: dwc3_gadget_giveback: ep5in: req 000000001170551f length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.778302: dwc3_complete_trb: ep5in: trb 00000000b2243432 (E33:D2) buf 0000ffffffde8568 size 1x 0 ctrl 12484464:00004921 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.778306: dwc3_complete_trb: ep5in: trb 000000009d420079 (E33:D3) buf 0000ffffffde9f9c size 1x 0 ctrl 12484470:00004921 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.778312: dwc3_gadget_giveback: ep5in: req 00000000a9695599 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.785533: dwc3_complete_trb: ep5in: trb 00000000649fe5d6 (E33:D4) buf 0000ffffff9c8c28 size 1x 0 ctrl 12488464:00004922 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.785536: dwc3_complete_trb: ep5in: trb 000000006d01d4b7 (E33:D5) buf 0000ffffff9c9b94 size 1x 0 ctrl 12488470:00004922 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.785545: dwc3_gadget_giveback: ep5in: req 0000000073dd58a7 length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.792772: dwc3_complete_trb: ep5in: trb 00000000a7d5ae23 (E33:D6) buf 0000ffffffbcc368 size 1x 0 ctrl 1248c464:00004923 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.792775: dwc3_complete_trb: ep5in: trb 00000000f63c85d3 (E33:D7) buf 0000ffffffbcd78c size 1x 0 ctrl 1248c470:00004923 (hlcs:Sc:isoc)
     irq/50-dwc3-305     [000] d..1.   166.792782: dwc3_gadget_giveback: ep5in: req 0000000075b98f5a length 7168/7168 zsi ==> -18
     irq/50-dwc3-305     [000] d..1.   166.800002: dwc3_complete_trb: ep5in: trb 00000000893379d8 (E33:D8) buf 0000ffffffbd09a8 size 1x 0 ctrl 12490464:00004924 (hlCs:Sc:isoc-first)
     irq/50-dwc3-305     [000] d..1.   166.800006: dwc3_complete_trb: ep5in: trb 0000000010adff65 (E33:D9) buf 0000ffffffbd1384 size 1x 0 ctrl 12490c70:00004924 (hlcs:SC:isoc)
     irq/50-dwc3-305     [000] d..1.   166.800012: dwc3_gadget_giveback: ep5in: req 00000000cd0ff97f length 7168/7168 zsI ==> -18
     irq/50-dwc3-305     [000] d..1.   166.807238: dwc3_event: event (49168096): ep5in: Transfer In Progress [00004916] (siM)
     irq/50-dwc3-305     [000] d..1.   166.807256: dwc3_gadget_ep_cmd: ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 --> status: Successful

The intermediate Bus Expiry is not always present in that case, but also completely acceptable as we loop
over the Start Transfer until this succeeds.

Do you have any Idea why this succeeded Start Streaming does come back with an
Missed Transfer on the first trb?

Regards,
Michael

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Thinh Nguyen]

Michael Grzeschik wrote:
> Hi Thinh!
> 
> I am currently debugging a strange error with transferring isoc requests
> with
> the current mainline driver.
> 
> When the pending and started list is empty the complete interrupt
> handler is
> sending an End Transfer to the controller. This End Transfer will then get
> successfully completed.
> 
>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 -->
> status: Successful
>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
> (080b01d6): ep5in: Endpoint Command Complete
>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
> 
> 
> After this the Transfer needs to start again. But unfortunately this
> sometimes
> does not succeed. You see in the following trace that the Start of the just
> prepared trbs did complete with an -18.
> 
>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size 1x 12
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691313: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Start Transfer' [49140406] params 0000ffff ffff3e80 00000000
> --> status: Bus Expiry
>    kworker/u5:2-347     [001] d..2.   166.691327: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Start Transfer' [49150406] params 0000ffff ffff3e80 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691351: dwc3_prepare_trb:
> ep5in: trb 00000000207832b0 (E235:D232) buf 0000ffffffb202e8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691356: dwc3_prepare_trb:
> ep5in: trb 000000007a081501 (E236:D232) buf 0000ffffffb21bf4 size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691362: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691384: dwc3_prepare_trb:
> ep5in: trb 0000000072f4be38 (E237:D232) buf 0000ffffffb24168 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691389: dwc3_prepare_trb:
> ep5in: trb 00000000596ad302 (E238:D232) buf 0000ffffffb257ec size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691394: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691419: dwc3_prepare_trb:
> ep5in: trb 00000000b313a087 (E239:D232) buf 0000ffffffb284e8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691423: dwc3_prepare_trb:
> ep5in: trb 000000000667492d (E240:D232) buf 0000ffffffb293e4 size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691429: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691451: dwc3_prepare_trb:
> ep5in: trb 00000000459ec17b (E241:D232) buf 0000ffffffb305a8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691455: dwc3_prepare_trb:
> ep5in: trb 00000000f5ca2c22 (E242:D232) buf 0000ffffffb31fdc size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691461: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691483: dwc3_prepare_trb:
> ep5in: trb 0000000074be44bd (E243:D232) buf 0000ffffffb34b28 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691487: dwc3_prepare_trb:
> ep5in: trb 000000009b1475ad (E244:D232) buf 0000ffffffb35bd4 size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691492: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>     irq/50-dwc3-305     [000] d..1.   166.691502: dwc3_complete_trb:
> ep5in: trb 000000007ff95a12 (E244:D233) buf 0000ffffffb1c2a8 size 1x 0
> ctrl 12454464:00004915 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.691505: dwc3_complete_trb:
> ep5in: trb 00000000f9cd175e (E244:D234) buf 0000ffffffb1d000 size 1x
> 7168 ctrl 12454470:00004915 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.691515: dwc3_gadget_giveback:
> ep5in: req 0000000090943319 length 0/7168 zsi ==> -18
>    kworker/u5:2-347     [001] d..2.   166.691525: dwc3_prepare_trb:
> ep5in: trb 0000000008992ded (E245:D234) buf 0000ffffffe00d68 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691530: dwc3_prepare_trb:
> ep5in: trb 0000000099db8537 (E246:D234) buf 0000ffffffe017cc size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691535: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691560: dwc3_prepare_trb:
> ep5in: trb 000000009a32f3df (E247:D234) buf 0000ffffffdfc8e8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691564: dwc3_prepare_trb:
> ep5in: trb 0000000099e18287 (E248:D234) buf 0000ffffffdfd3c4 size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691570: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691593: dwc3_prepare_trb:
> ep5in: trb 0000000069755327 (E249:D234) buf 0000ffffffdf8e28 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691597: dwc3_prepare_trb:
> ep5in: trb 00000000b4ea3844 (E250:D234) buf 0000ffffffdf9fbc size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691603: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691626: dwc3_prepare_trb:
> ep5in: trb 000000004356a51c (E251:D234) buf 0000ffffffdf4f68 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691630: dwc3_prepare_trb:
> ep5in: trb 0000000005790196 (E252:D234) buf 0000ffffffdf5bb4 size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691636: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691657: dwc3_prepare_trb:
> ep5in: trb 00000000eabf4b9c (E253:D234) buf 0000ffffffdf0ce8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691661: dwc3_prepare_trb:
> ep5in: trb 00000000e5b7688c (E254:D234) buf 0000ffffffdf17ac size 1x
> 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691667: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691688: dwc3_prepare_trb:
> ep5in: trb 000000007a2518a4 (E0:D234) buf 0000ffffffdec8a8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691693: dwc3_prepare_trb:
> ep5in: trb 000000005d8805e7 (E1:D234) buf 0000ffffffded3a4 size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691698: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691720: dwc3_prepare_trb:
> ep5in: trb 00000000b2243432 (E2:D234) buf 0000ffffffde8568 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691724: dwc3_prepare_trb:
> ep5in: trb 000000009d420079 (E3:D234) buf 0000ffffffde9f9c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691730: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691751: dwc3_prepare_trb:
> ep5in: trb 00000000649fe5d6 (E4:D234) buf 0000ffffff9c8c28 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691756: dwc3_prepare_trb:
> ep5in: trb 000000006d01d4b7 (E5:D234) buf 0000ffffff9c9b94 size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691761: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691783: dwc3_prepare_trb:
> ep5in: trb 00000000a7d5ae23 (E6:D234) buf 0000ffffffbcc368 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691788: dwc3_prepare_trb:
> ep5in: trb 00000000f63c85d3 (E7:D234) buf 0000ffffffbcd78c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691793: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691816: dwc3_prepare_trb:
> ep5in: trb 00000000893379d8 (E8:D234) buf 0000ffffffbd09a8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691820: dwc3_prepare_trb:
> ep5in: trb 0000000010adff65 (E9:D234) buf 0000ffffffbd1384 size 1x 7160
> ctrl 00000c71:00000000 (Hlcs:SC:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691826: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691848: dwc3_prepare_trb:
> ep5in: trb 000000003c91f4e3 (E10:D234) buf 0000ffffffbd47e8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691852: dwc3_prepare_trb:
> ep5in: trb 000000001eb9a46d (E11:D234) buf 0000ffffffbd5f7c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691858: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691880: dwc3_prepare_trb:
> ep5in: trb 000000008039b4f5 (E12:D234) buf 0000ffffffbd80a8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691884: dwc3_prepare_trb:
> ep5in: trb 000000003acd9b86 (E13:D234) buf 0000ffffffbd9b74 size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691890: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691912: dwc3_prepare_trb:
> ep5in: trb 0000000016625d76 (E14:D234) buf 0000ffffffbbcc68 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691916: dwc3_prepare_trb:
> ep5in: trb 000000005060be63 (E15:D234) buf 0000ffffffbbd76c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691922: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691943: dwc3_prepare_trb:
> ep5in: trb 000000006c7ec562 (E16:D234) buf 0000ffffffbc0768 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691948: dwc3_prepare_trb:
> ep5in: trb 00000000153e7b58 (E17:D234) buf 0000ffffffbc1364 size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691953: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.691975: dwc3_prepare_trb:
> ep5in: trb 00000000d79e8ccd (E18:D234) buf 0000ffffffbc4f28 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.691979: dwc3_prepare_trb:
> ep5in: trb 000000002ebdf5db (E19:D234) buf 0000ffffffbc5f5c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.691985: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.692008: dwc3_prepare_trb:
> ep5in: trb 0000000036246e8f (E20:D234) buf 0000ffffffbc8aa8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.692012: dwc3_prepare_trb:
> ep5in: trb 000000000f75f134 (E21:D234) buf 0000ffffffbc9b54 size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.692018: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.692040: dwc3_prepare_trb:
> ep5in: trb 00000000ca9d0693 (E22:D234) buf 0000ffffff9c4528 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.692044: dwc3_prepare_trb:
> ep5in: trb 000000008587c7c2 (E23:D234) buf 0000ffffff9c574c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.692050: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.692072: dwc3_prepare_trb:
> ep5in: trb 0000000003ad0d16 (E24:D234) buf 0000ffffff9c07a8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.692076: dwc3_prepare_trb:
> ep5in: trb 0000000054e33de9 (E25:D234) buf 0000ffffff9c1344 size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.692081: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.692103: dwc3_prepare_trb:
> ep5in: trb 000000006598a295 (E26:D234) buf 0000ffffff9a0668 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.692108: dwc3_prepare_trb:
> ep5in: trb 0000000015487935 (E27:D234) buf 0000ffffff9a1f3c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.692114: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.692136: dwc3_prepare_trb:
> ep5in: trb 00000000ef2871fc (E28:D234) buf 0000ffffff978ea8 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.692140: dwc3_prepare_trb:
> ep5in: trb 0000000013e0668f (E29:D234) buf 0000ffffff979b34 size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.692146: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.692167: dwc3_prepare_trb:
> ep5in: trb 0000000092e94032 (E30:D234) buf 0000ffffff94c428 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.692172: dwc3_prepare_trb:
> ep5in: trb 0000000002970903 (E31:D234) buf 0000ffffff94d72c size 1x 7160
> ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>    kworker/u5:2-347     [001] d..2.   166.692177: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>    kworker/u5:2-347     [001] d..2.   166.692200: dwc3_prepare_trb:
> ep5in: trb 00000000b3249549 (E32:D234) buf 0000ffffff8bc068 size 1x 8
> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>    kworker/u5:2-347     [001] d..2.   166.692205: dwc3_prepare_trb:
> ep5in: trb 00000000ec88603f (E33:D234) buf 0000ffffff8bd324 size 1x 1221
> ctrl 00000c71:00000000 (Hlcs:SC:isoc)
>    kworker/u5:2-347     [001] d..2.   166.692211: dwc3_gadget_ep_cmd:
> ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000
> --> status: Successful
>     irq/50-dwc3-305     [000] d..1.   166.698763: dwc3_complete_trb:
> ep5in: trb 00000000207832b0 (E33:D235) buf 0000ffffffb202e8 size 1x 0
> ctrl 12458464:00004916 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.698766: dwc3_complete_trb:
> ep5in: trb 000000007a081501 (E33:D236) buf 0000ffffffb21bf4 size 1x 7168
> ctrl 12458470:00004916 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.698773: dwc3_gadget_giveback:
> ep5in: req 00000000a3af67aa length 0/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.705998: dwc3_complete_trb:
> ep5in: trb 0000000072f4be38 (E33:D237) buf 0000ffffffb24168 size 1x 0
> ctrl 1245c464:00004917 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.706002: dwc3_complete_trb:
> ep5in: trb 00000000596ad302 (E33:D238) buf 0000ffffffb257ec size 1x 0
> ctrl 1245c470:00004917 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.706008: dwc3_gadget_giveback:
> ep5in: req 00000000efe24442 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.713228: dwc3_complete_trb:
> ep5in: trb 00000000b313a087 (E33:D239) buf 0000ffffffb284e8 size 1x 0
> ctrl 12460464:00004918 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.713231: dwc3_complete_trb:
> ep5in: trb 000000000667492d (E33:D240) buf 0000ffffffb293e4 size 1x 0
> ctrl 12460470:00004918 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.713238: dwc3_gadget_giveback:
> ep5in: req 00000000be20abd7 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.720459: dwc3_complete_trb:
> ep5in: trb 00000000459ec17b (E33:D241) buf 0000ffffffb305a8 size 1x 0
> ctrl 12464464:00004919 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.720462: dwc3_complete_trb:
> ep5in: trb 00000000f5ca2c22 (E33:D242) buf 0000ffffffb31fdc size 1x 0
> ctrl 12464470:00004919 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.720469: dwc3_gadget_giveback:
> ep5in: req 00000000c7d419e1 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.727689: dwc3_complete_trb:
> ep5in: trb 0000000074be44bd (E33:D243) buf 0000ffffffb34b28 size 1x 0
> ctrl 12468464:0000491a (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.727693: dwc3_complete_trb:
> ep5in: trb 000000009b1475ad (E33:D244) buf 0000ffffffb35bd4 size 1x 0
> ctrl 12468470:0000491a (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.727699: dwc3_gadget_giveback:
> ep5in: req 000000002b31980b length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.734920: dwc3_complete_trb:
> ep5in: trb 0000000008992ded (E33:D245) buf 0000ffffffe00d68 size 1x 0
> ctrl 1246c464:0000491b (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.734923: dwc3_complete_trb:
> ep5in: trb 0000000099db8537 (E33:D246) buf 0000ffffffe017cc size 1x 0
> ctrl 1246c470:0000491b (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.734930: dwc3_gadget_giveback:
> ep5in: req 00000000e62a3292 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.742150: dwc3_complete_trb:
> ep5in: trb 000000009a32f3df (E33:D247) buf 0000ffffffdfc8e8 size 1x 0
> ctrl 12470464:0000491c (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.742153: dwc3_complete_trb:
> ep5in: trb 0000000099e18287 (E33:D248) buf 0000ffffffdfd3c4 size 1x 0
> ctrl 12470470:0000491c (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.742161: dwc3_gadget_giveback:
> ep5in: req 00000000ebfe68aa length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.749381: dwc3_complete_trb:
> ep5in: trb 0000000069755327 (E33:D249) buf 0000ffffffdf8e28 size 1x 0
> ctrl 12474464:0000491d (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.749384: dwc3_complete_trb:
> ep5in: trb 00000000b4ea3844 (E33:D250) buf 0000ffffffdf9fbc size 1x 0
> ctrl 12474470:0000491d (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.749390: dwc3_gadget_giveback:
> ep5in: req 0000000048685fa4 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.756611: dwc3_complete_trb:
> ep5in: trb 000000004356a51c (E33:D251) buf 0000ffffffdf4f68 size 1x 0
> ctrl 12478464:0000491e (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.756614: dwc3_complete_trb:
> ep5in: trb 0000000005790196 (E33:D252) buf 0000ffffffdf5bb4 size 1x 0
> ctrl 12478470:0000491e (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.756621: dwc3_gadget_giveback:
> ep5in: req 0000000053b4813f length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.763842: dwc3_complete_trb:
> ep5in: trb 00000000eabf4b9c (E33:D253) buf 0000ffffffdf0ce8 size 1x 0
> ctrl 1247c464:0000491f (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.763845: dwc3_complete_trb:
> ep5in: trb 00000000e5b7688c (E33:D254) buf 0000ffffffdf17ac size 1x 0
> ctrl 1247c470:0000491f (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.763851: dwc3_gadget_giveback:
> ep5in: req 000000009ccc1e16 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.771072: dwc3_complete_trb:
> ep5in: trb 000000007a2518a4 (E33:D0) buf 0000ffffffdec8a8 size 1x 0 ctrl
> 12480464:00004920 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.771075: dwc3_complete_trb:
> ep5in: trb 000000005d8805e7 (E33:D1) buf 0000ffffffded3a4 size 1x 0 ctrl
> 12480470:00004920 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.771081: dwc3_gadget_giveback:
> ep5in: req 000000001170551f length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.778302: dwc3_complete_trb:
> ep5in: trb 00000000b2243432 (E33:D2) buf 0000ffffffde8568 size 1x 0 ctrl
> 12484464:00004921 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.778306: dwc3_complete_trb:
> ep5in: trb 000000009d420079 (E33:D3) buf 0000ffffffde9f9c size 1x 0 ctrl
> 12484470:00004921 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.778312: dwc3_gadget_giveback:
> ep5in: req 00000000a9695599 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.785533: dwc3_complete_trb:
> ep5in: trb 00000000649fe5d6 (E33:D4) buf 0000ffffff9c8c28 size 1x 0 ctrl
> 12488464:00004922 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.785536: dwc3_complete_trb:
> ep5in: trb 000000006d01d4b7 (E33:D5) buf 0000ffffff9c9b94 size 1x 0 ctrl
> 12488470:00004922 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.785545: dwc3_gadget_giveback:
> ep5in: req 0000000073dd58a7 length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.792772: dwc3_complete_trb:
> ep5in: trb 00000000a7d5ae23 (E33:D6) buf 0000ffffffbcc368 size 1x 0 ctrl
> 1248c464:00004923 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.792775: dwc3_complete_trb:
> ep5in: trb 00000000f63c85d3 (E33:D7) buf 0000ffffffbcd78c size 1x 0 ctrl
> 1248c470:00004923 (hlcs:Sc:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.792782: dwc3_gadget_giveback:
> ep5in: req 0000000075b98f5a length 7168/7168 zsi ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.800002: dwc3_complete_trb:
> ep5in: trb 00000000893379d8 (E33:D8) buf 0000ffffffbd09a8 size 1x 0 ctrl
> 12490464:00004924 (hlCs:Sc:isoc-first)
>     irq/50-dwc3-305     [000] d..1.   166.800006: dwc3_complete_trb:
> ep5in: trb 0000000010adff65 (E33:D9) buf 0000ffffffbd1384 size 1x 0 ctrl
> 12490c70:00004924 (hlcs:SC:isoc)
>     irq/50-dwc3-305     [000] d..1.   166.800012: dwc3_gadget_giveback:
> ep5in: req 00000000cd0ff97f length 7168/7168 zsI ==> -18
>     irq/50-dwc3-305     [000] d..1.   166.807238: dwc3_event: event
> (49168096): ep5in: Transfer In Progress [00004916] (siM)
>     irq/50-dwc3-305     [000] d..1.   166.807256: dwc3_gadget_ep_cmd:
> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 -->
> status: Successful
> 
> The intermediate Bus Expiry is not always present in that case, but also
> completely acceptable as we loop
> over the Start Transfer until this succeeds.
> 
> Do you have any Idea why this succeeded Start Streaming does come back
> with an
> Missed Transfer on the first trb?
> 

Hi Michael,

When sending the trace, please leave it unfiltered. It's missing some
trace events that I want to check.

Please check if the host is actually polling for data at that uframe.
Each TRB is scheduled for a particular interval. If the host doesn't
request for data at that particular interval, then it's a missed isoc
also (err -18). So, if you have a usb traffic analyzer, please verify
this. Also, maybe try with a different host vendor to see if the
behavior is the same.

BR,
Thinh

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Michael Grzeschik]

[-- Attachment #1: Type: text/plain, Size: 47199 bytes --]

On Wed, Mar 02, 2022 at 10:22:55PM +0000, Thinh Nguyen wrote:
>Michael Grzeschik wrote:
>> I am currently debugging a strange error with transferring isoc requests
>> with
>> the current mainline driver.
>>
>> When the pending and started list is empty the complete interrupt
>> handler is
>> sending an End Transfer to the controller. This End Transfer will then get
>> successfully completed.
>>
>>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
>> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 -->
>> status: Successful
>>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
>> (080b01d6): ep5in: Endpoint Command Complete
>>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
>> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
>>
>>
>> After this the Transfer needs to start again. But unfortunately this
>> sometimes
>> does not succeed. You see in the following trace that the Start of the just
>> prepared trbs did complete with an -18.
>>
>>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
>> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size 1x 12
>> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
>> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
>> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)

[snip]

>>
>> The intermediate Bus Expiry is not always present in that case, but also
>> completely acceptable as we loop
>> over the Start Transfer until this succeeds.
>>
>> Do you have any Idea why this succeeded Start Streaming does come back
>> with an
>> Missed Transfer on the first trb?
>>
>
>Hi Michael,
>
>When sending the trace, please leave it unfiltered. It's missing some
>trace events that I want to check.

Right, it was a mix of trace_event:dwc3:* and ftrace_filter=dwc*. So I
kind of felt filtering out the interesting part would help.

Anyway. Here is the same situation in another trace, with all
trace_events from dwc3:

     ...
     irq/50-dwc3-317     [000] d..1.   303.270329: dwc3_complete_trb: ep5in: trb 000000002b7860b1 (E110:D109) buf 0000ffffff8b07a8 size 1x 0 ctrl 3a660464:0000e998 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.270331: dwc3_complete_trb: ep5in: trb 000000007bd5c03d (E110:D110) buf 0000ffffff8b1b34 size 1x 0 ctrl 3a660c70:0000e998 (hlcs:SC:isoc)
     irq/50-dwc3-317     [000] d..1.   303.270336: dwc3_gadget_giveback: ep5in: req 000000005332cdd2 length 1146/1146 zsI ==> 0
     irq/50-dwc3-317     [000] d..1.   303.270349: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
     irq/50-dwc3-317     [000] d..1.   303.270350: dwc3_writel: addr 00000000980f66dc offset 0008 value 00000000
     irq/50-dwc3-317     [000] d..1.   303.270351: dwc3_writel: addr 00000000e5d226be offset 0004 value 00000000
     irq/50-dwc3-317     [000] d..1.   303.270352: dwc3_writel: addr 00000000cd12f6fc offset 0000 value 00000000
     irq/50-dwc3-317     [000] d..1.   303.270353: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0d08
     irq/50-dwc3-317     [000] d..1.   303.270354: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0908
     irq/50-dwc3-317     [000] d..1.   303.270355: dwc3_gadget_ep_cmd: ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 --> status: Successful
     irq/50-dwc3-317     [000] d..1.   303.270357: dwc3_writel: addr 0000000077945c0a offset c408 value 00001000
     irq/50-dwc3-317     [000] d.h1.   303.270369: dwc3_readl: addr 0000000073cc91b4 offset c40c value 00000004
     irq/50-dwc3-317     [000] d.h1.   303.270370: dwc3_writel: addr 0000000077945c0a offset c408 value 80001000
     irq/50-dwc3-317     [000] d.h1.   303.270371: dwc3_writel: addr 0000000073cc91b4 offset c40c value 00000004
     irq/50-dwc3-317     [000] d..1.   303.270384: dwc3_event: event (080b01d6): ep5in: Endpoint Command Complete
     irq/50-dwc3-317     [000] d..1.   303.270386: dwc3_writel: addr 0000000077945c0a offset c408 value 00001000
          <idle>-0       [000] d.h1.   303.270434: dwc3_readl: addr 0000000073cc91b4 offset c40c value 00000004
          <idle>-0       [000] d.h1.   303.270436: dwc3_writel: addr 0000000077945c0a offset c408 value 80001000
          <idle>-0       [000] d.h1.   303.270437: dwc3_writel: addr 0000000073cc91b4 offset c40c value 00000004
     irq/50-dwc3-317     [000] d..1.   303.270453: dwc3_event: event (e99a10d6): ep5in: Transfer Not Ready [0000e99a] (Not Active)
     irq/50-dwc3-317     [000] d..1.   303.270454: dwc3_writel: addr 0000000077945c0a offset c408 value 00001000
    kworker/u5:0-103     [001] d..1.   303.300147: dwc3_readl: addr 0000000068f703d8 offset c70c value 0083543c
    kworker/u5:0-103     [001] d..2.   303.300153: dwc3_ep_queue: ep5in: req 00000000ebdd96ce length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300156: dwc3_readl: addr 0000000068f703d8 offset c70c value 0083543c
    kworker/u5:0-103     [001] d..2.   303.300167: dwc3_prepare_trb: ep5in: trb 00000000dfee81a1 (E111:D110) buf 0000ffffffb1ca28 size 1x 12 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300169: dwc3_prepare_trb: ep5in: trb 00000000985156de (E112:D110) buf 0000ffffffb1d000 size 1x 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300172: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300173: dwc3_readl: addr 0000000068f703d8 offset c70c value 0083543c
    kworker/u5:0-103     [001] d..2.   303.300174: dwc3_writel: addr 00000000980f66dc offset 0008 value 0000ffff
    kworker/u5:0-103     [001] d..2.   303.300175: dwc3_writel: addr 00000000e5d226be offset 0004 value ffff36e0
    kworker/u5:0-103     [001] d..2.   303.300176: dwc3_writel: addr 00000000cd12f6fc offset 0000 value 00000000
    kworker/u5:0-103     [001] d..2.   303.300177: dwc3_writel: addr 000000005a3de08f offset 000c value ea880c06
    kworker/u5:0-103     [001] d..2.   303.300178: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0806
    kworker/u5:0-103     [001] d..2.   303.300181: dwc3_gadget_ep_cmd: ep5in: cmd 'Start Transfer' [ea880c06] params 0000ffff ffff36e0 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..2.   303.300182: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0806
    kworker/u5:0-103     [001] d..1.   303.300190: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035444
    kworker/u5:0-103     [001] d..2.   303.300192: dwc3_ep_queue: ep5in: req 0000000051b03a63 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300199: dwc3_prepare_trb: ep5in: trb 0000000030bedaf0 (E113:D110) buf 0000ffffffb18d28 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300201: dwc3_prepare_trb: ep5in: trb 000000009cea9eeb (E114:D110) buf 0000ffffffb19bf4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300202: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300203: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300205: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300205: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300212: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035444
    kworker/u5:0-103     [001] d..2.   303.300214: dwc3_ep_queue: ep5in: req 00000000b5e8c200 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300220: dwc3_prepare_trb: ep5in: trb 0000000067df777d (E115:D110) buf 0000ffffffa6c968 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300222: dwc3_prepare_trb: ep5in: trb 0000000027dc06f7 (E116:D110) buf 0000ffffffa6d7ec size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300224: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300225: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300226: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300227: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300234: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035444
    kworker/u5:0-103     [001] d..2.   303.300236: dwc3_ep_queue: ep5in: req 000000008ba09979 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300242: dwc3_prepare_trb: ep5in: trb 00000000e92e3cbd (E117:D110) buf 0000ffffffb58568 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300244: dwc3_prepare_trb: ep5in: trb 0000000008efb276 (E118:D110) buf 0000ffffffb593e4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300245: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300246: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300248: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300248: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300256: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035444
    kworker/u5:0-103     [001] d..2.   303.300258: dwc3_ep_queue: ep5in: req 00000000fc26cabb length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300264: dwc3_prepare_trb: ep5in: trb 00000000634dffa2 (E119:D110) buf 0000ffffffb745a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300266: dwc3_prepare_trb: ep5in: trb 00000000544b5d11 (E120:D110) buf 0000ffffffb75fdc size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300268: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300269: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300270: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300271: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300278: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035444
    kworker/u5:0-103     [001] d..2.   303.300280: dwc3_ep_queue: ep5in: req 000000004e112f8f length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300285: dwc3_prepare_trb: ep5in: trb 0000000055a06d19 (E121:D110) buf 0000ffffffb782e8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300287: dwc3_prepare_trb: ep5in: trb 00000000221e87a1 (E122:D110) buf 0000ffffffb79bd4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300289: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300293: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300294: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300295: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300302: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035444
    kworker/u5:0-103     [001] d..2.   303.300304: dwc3_ep_queue: ep5in: req 00000000a77632f8 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300309: dwc3_prepare_trb: ep5in: trb 00000000b0827538 (E123:D110) buf 0000ffffffb7ca68 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    pipewire:src-350     [000] d.h..   303.300310: dwc3_readl: addr 0000000073cc91b4 offset c40c value 00000008
    kworker/u5:0-103     [001] d..2.   303.300312: dwc3_prepare_trb: ep5in: trb 0000000007c04114 (E124:D110) buf 0000ffffffb7d7cc size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    pipewire:src-350     [000] d.h..   303.300312: dwc3_writel: addr 0000000077945c0a offset c408 value 80001000
    kworker/u5:0-103     [001] d..2.   303.300313: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    pipewire:src-350     [000] d.h..   303.300314: dwc3_writel: addr 0000000073cc91b4 offset c40c value 00000008
    kworker/u5:0-103     [001] d..2.   303.300314: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300315: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300316: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300323: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003544c
    kworker/u5:0-103     [001] d..2.   303.300325: dwc3_ep_queue: ep5in: req 000000009d99afac length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300331: dwc3_prepare_trb: ep5in: trb 000000005394448b (E125:D110) buf 0000ffffffb80ba8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300333: dwc3_prepare_trb: ep5in: trb 000000004361b6ec (E126:D110) buf 0000ffffffb813c4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300335: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300336: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300337: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300338: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
     irq/50-dwc3-317     [000] d..1.   303.300340: dwc3_event: event (ea888096): ep5in: Transfer In Progress [0000ea88] (siM)
     irq/50-dwc3-317     [000] d..1.   303.300343: dwc3_complete_trb: ep5in: trb 00000000dfee81a1 (E126:D111) buf 0000ffffffb1ca28 size 1x 0 ctrl 3aa20464:0000ea88 (hlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..1.   303.300345: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003544c
     irq/50-dwc3-317     [000] d..1.   303.300345: dwc3_complete_trb: ep5in: trb 00000000985156de (E126:D112) buf 0000ffffffb1d000 size 1x 7168 ctrl 3aa20470:0000ea88 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.300354: dwc3_gadget_giveback: ep5in: req 00000000ebdd96ce length 0/7168 zsi ==> -18
    kworker/u5:0-103     [001] d..2.   303.300356: dwc3_ep_queue: ep5in: req 00000000b27ec36b length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300362: dwc3_prepare_trb: ep5in: trb 000000000fc782b8 (E127:D112) buf 0000ffffffb84828 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300364: dwc3_prepare_trb: ep5in: trb 00000000f594423f (E128:D112) buf 0000ffffffb85fbc size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300365: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300366: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300367: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300368: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300375: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003544c
    kworker/u5:0-103     [001] d..2.   303.300378: dwc3_ep_queue: ep5in: req 000000007b6ed6f3 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300383: dwc3_prepare_trb: ep5in: trb 00000000391b49ab (E129:D112) buf 0000ffffffb889a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300386: dwc3_prepare_trb: ep5in: trb 00000000979d3c23 (E130:D112) buf 0000ffffffb89bb4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300388: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300389: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300390: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300391: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300398: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003544c
    kworker/u5:0-103     [001] d..2.   303.300401: dwc3_ep_queue: ep5in: req 00000000bc2b6c4d length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300408: dwc3_prepare_trb: ep5in: trb 000000007ab7715a (E131:D112) buf 0000ffffffb8c0a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300410: dwc3_prepare_trb: ep5in: trb 00000000217c7be7 (E132:D112) buf 0000ffffffb8d7ac size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300412: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300413: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300414: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300415: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300422: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003544c
    kworker/u5:0-103     [001] d..2.   303.300424: dwc3_ep_queue: ep5in: req 00000000f8f3eb0d length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300430: dwc3_prepare_trb: ep5in: trb 00000000907e85e1 (E133:D112) buf 0000ffffffb90928 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300432: dwc3_prepare_trb: ep5in: trb 00000000bb860433 (E134:D112) buf 0000ffffffb913a4 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300434: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300435: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300436: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300437: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300444: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035454
    kworker/u5:0-103     [001] d..2.   303.300446: dwc3_ep_queue: ep5in: req 00000000ab8d9880 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300451: dwc3_prepare_trb: ep5in: trb 00000000c0003d17 (E135:D112) buf 0000ffffffb94528 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300453: dwc3_prepare_trb: ep5in: trb 00000000b03c9834 (E136:D112) buf 0000ffffffb95f9c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300455: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300456: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300457: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300458: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300465: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035454
    kworker/u5:0-103     [001] d..2.   303.300467: dwc3_ep_queue: ep5in: req 00000000d4dc2a9c length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300473: dwc3_prepare_trb: ep5in: trb 00000000c55d236b (E137:D112) buf 0000ffffffb98ca8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300475: dwc3_prepare_trb: ep5in: trb 0000000079a7319b (E138:D112) buf 0000ffffffb99b94 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300477: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300478: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300479: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300480: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300487: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035454
    kworker/u5:0-103     [001] d..2.   303.300489: dwc3_ep_queue: ep5in: req 000000002268e4db length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300494: dwc3_prepare_trb: ep5in: trb 0000000066932860 (E139:D112) buf 0000ffffffae88a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300496: dwc3_prepare_trb: ep5in: trb 0000000062d70129 (E140:D112) buf 0000ffffffae978c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300498: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300499: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300501: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300501: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300508: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035454
    kworker/u5:0-103     [001] d..2.   303.300510: dwc3_ep_queue: ep5in: req 00000000e5c4f08a length 0/7168 zsI ==> -115
    kworker/u5:0-103     [001] d..2.   303.300516: dwc3_prepare_trb: ep5in: trb 00000000c7f30d08 (E141:D112) buf 0000ffffffb20da8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300518: dwc3_prepare_trb: ep5in: trb 000000009ee7250a (E142:D112) buf 0000ffffffb21384 size 1x 7160 ctrl 00000c71:00000000 (Hlcs:SC:isoc)
    kworker/u5:0-103     [001] d..2.   303.300520: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300521: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300522: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300523: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300529: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035454
    kworker/u5:0-103     [001] d..2.   303.300531: dwc3_ep_queue: ep5in: req 00000000d325210d length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300537: dwc3_prepare_trb: ep5in: trb 0000000092da83c7 (E143:D112) buf 0000ffffffb24768 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300539: dwc3_prepare_trb: ep5in: trb 00000000edd8fc2d (E144:D112) buf 0000ffffffb25f7c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300541: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300542: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300543: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300544: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300550: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035454
    kworker/u5:0-103     [001] d..2.   303.300553: dwc3_ep_queue: ep5in: req 00000000cb1d250d length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300559: dwc3_prepare_trb: ep5in: trb 00000000d3571109 (E145:D112) buf 0000ffffffb28ae8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300561: dwc3_prepare_trb: ep5in: trb 000000007e3b29d0 (E146:D112) buf 0000ffffffb29b74 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300563: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300564: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300565: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300566: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300573: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003545c
    kworker/u5:0-103     [001] d..2.   303.300575: dwc3_ep_queue: ep5in: req 0000000039270917 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300581: dwc3_prepare_trb: ep5in: trb 00000000abc803fb (E147:D112) buf 0000ffffffb2cea8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300583: dwc3_prepare_trb: ep5in: trb 00000000f4e4afdb (E148:D112) buf 0000ffffffb2d76c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300585: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300586: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300587: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300588: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300594: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003545c
    kworker/u5:0-103     [001] d..2.   303.300596: dwc3_ep_queue: ep5in: req 00000000803068b1 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300602: dwc3_prepare_trb: ep5in: trb 0000000062759476 (E149:D112) buf 0000ffffffb306e8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300604: dwc3_prepare_trb: ep5in: trb 0000000076d1e318 (E150:D112) buf 0000ffffffb31364 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300606: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300607: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300608: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300609: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300616: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003545c
    kworker/u5:0-103     [001] d..2.   303.300618: dwc3_ep_queue: ep5in: req 000000009b7e08f9 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300624: dwc3_prepare_trb: ep5in: trb 000000007eb5d983 (E151:D112) buf 0000ffffffb34e28 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300626: dwc3_prepare_trb: ep5in: trb 00000000dfcddf34 (E152:D112) buf 0000ffffffb35f5c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300627: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300628: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300629: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300630: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300637: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003545c
    kworker/u5:0-103     [001] d..2.   303.300640: dwc3_ep_queue: ep5in: req 000000001a38dcac length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300645: dwc3_prepare_trb: ep5in: trb 00000000a4de6c46 (E153:D112) buf 0000ffffffb403a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300647: dwc3_prepare_trb: ep5in: trb 00000000a232b4ca (E154:D112) buf 0000ffffffb41b54 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300649: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300650: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300651: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300652: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300659: dwc3_readl: addr 0000000068f703d8 offset c70c value 0003545c
    kworker/u5:0-103     [001] d..2.   303.300661: dwc3_ep_queue: ep5in: req 00000000be265ac6 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300667: dwc3_prepare_trb: ep5in: trb 00000000a2be3f51 (E155:D112) buf 0000ffffffb3cd68 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300669: dwc3_prepare_trb: ep5in: trb 00000000f8c7bb97 (E156:D112) buf 0000ffffffb3d74c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300671: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300672: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300673: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300674: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300680: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035464
    kworker/u5:0-103     [001] d..2.   303.300682: dwc3_ep_queue: ep5in: req 000000008c3acb19 length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300688: dwc3_prepare_trb: ep5in: trb 000000000058d163 (E157:D112) buf 0000ffffffb384a8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300690: dwc3_prepare_trb: ep5in: trb 00000000d28a0b36 (E158:D112) buf 0000ffffffb39344 size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300692: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300693: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300694: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300695: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300702: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035464
    kworker/u5:0-103     [001] d..2.   303.300704: dwc3_ep_queue: ep5in: req 000000003b45383a length 0/7168 zsi ==> -115
    kworker/u5:0-103     [001] d..2.   303.300710: dwc3_prepare_trb: ep5in: trb 000000000da4d0e7 (E159:D112) buf 0000ffffffaf0ce8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300712: dwc3_prepare_trb: ep5in: trb 00000000a397b469 (E160:D112) buf 0000ffffffaf1f3c size 1x 7160 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
    kworker/u5:0-103     [001] d..2.   303.300714: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300715: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300716: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300717: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
    kworker/u5:0-103     [001] d..1.   303.300724: dwc3_readl: addr 0000000068f703d8 offset c70c value 00035464
    kworker/u5:0-103     [001] d..2.   303.300726: dwc3_ep_queue: ep5in: req 000000005af62967 length 0/1180 zsI ==> -115
    kworker/u5:0-103     [001] d..2.   303.300731: dwc3_prepare_trb: ep5in: trb 000000000f40be5d (E161:D112) buf 0000ffffff8aefa8 size 1x 8 ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
    kworker/u5:0-103     [001] d..2.   303.300733: dwc3_prepare_trb: ep5in: trb 00000000d536f1d5 (E162:D112) buf 0000ffffff8afb34 size 1x 1172 ctrl 00000c71:00000000 (Hlcs:SC:isoc)
    kworker/u5:0-103     [001] d..2.   303.300735: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
    kworker/u5:0-103     [001] d..2.   303.300736: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0407
    kworker/u5:0-103     [001] d..2.   303.300737: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0007
    kworker/u5:0-103     [001] d..2.   303.300738: dwc3_gadget_ep_cmd: ep5in: cmd 'Update Transfer' [b0407] params 00000000 00000000 00000000 --> status: Successful
     irq/50-dwc3-317     [000] d..1.   303.307600: dwc3_complete_trb: ep5in: trb 0000000030bedaf0 (E162:D113) buf 0000ffffffb18d28 size 1x 0 ctrl 3aa24464:0000ea89 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.307602: dwc3_complete_trb: ep5in: trb 000000009cea9eeb (E162:D114) buf 0000ffffffb19bf4 size 1x 7168 ctrl 3aa24470:0000ea89 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.307608: dwc3_gadget_giveback: ep5in: req 0000000051b03a63 length 0/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.314827: dwc3_complete_trb: ep5in: trb 0000000067df777d (E162:D115) buf 0000ffffffa6c968 size 1x 0 ctrl 3aa28464:0000ea8a (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.314829: dwc3_complete_trb: ep5in: trb 0000000027dc06f7 (E162:D116) buf 0000ffffffa6d7ec size 1x 0 ctrl 3aa28470:0000ea8a (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.314835: dwc3_gadget_giveback: ep5in: req 00000000b5e8c200 length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.322057: dwc3_complete_trb: ep5in: trb 00000000e92e3cbd (E162:D117) buf 0000ffffffb58568 size 1x 0 ctrl 3aa2c464:0000ea8b (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.322059: dwc3_complete_trb: ep5in: trb 0000000008efb276 (E162:D118) buf 0000ffffffb593e4 size 1x 0 ctrl 3aa2c470:0000ea8b (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.322065: dwc3_gadget_giveback: ep5in: req 000000008ba09979 length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.329287: dwc3_complete_trb: ep5in: trb 00000000634dffa2 (E162:D119) buf 0000ffffffb745a8 size 1x 0 ctrl 3aa30464:0000ea8c (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.329290: dwc3_complete_trb: ep5in: trb 00000000544b5d11 (E162:D120) buf 0000ffffffb75fdc size 1x 0 ctrl 3aa30470:0000ea8c (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.329295: dwc3_gadget_giveback: ep5in: req 00000000fc26cabb length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.336518: dwc3_complete_trb: ep5in: trb 0000000055a06d19 (E162:D121) buf 0000ffffffb782e8 size 1x 0 ctrl 3aa34464:0000ea8d (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.336520: dwc3_complete_trb: ep5in: trb 00000000221e87a1 (E162:D122) buf 0000ffffffb79bd4 size 1x 0 ctrl 3aa34470:0000ea8d (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.336526: dwc3_gadget_giveback: ep5in: req 000000004e112f8f length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.343748: dwc3_complete_trb: ep5in: trb 00000000b0827538 (E162:D123) buf 0000ffffffb7ca68 size 1x 0 ctrl 3aa38464:0000ea8e (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.343751: dwc3_complete_trb: ep5in: trb 0000000007c04114 (E162:D124) buf 0000ffffffb7d7cc size 1x 0 ctrl 3aa38470:0000ea8e (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.343756: dwc3_gadget_giveback: ep5in: req 00000000a77632f8 length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.350979: dwc3_complete_trb: ep5in: trb 000000005394448b (E162:D125) buf 0000ffffffb80ba8 size 1x 0 ctrl 3aa3c464:0000ea8f (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.350981: dwc3_complete_trb: ep5in: trb 000000004361b6ec (E162:D126) buf 0000ffffffb813c4 size 1x 0 ctrl 3aa3c470:0000ea8f (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.350986: dwc3_gadget_giveback: ep5in: req 000000009d99afac length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.358209: dwc3_complete_trb: ep5in: trb 000000000fc782b8 (E162:D127) buf 0000ffffffb84828 size 1x 0 ctrl 3aa40464:0000ea90 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.358212: dwc3_complete_trb: ep5in: trb 00000000f594423f (E162:D128) buf 0000ffffffb85fbc size 1x 0 ctrl 3aa40470:0000ea90 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.358217: dwc3_gadget_giveback: ep5in: req 00000000b27ec36b length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.365440: dwc3_complete_trb: ep5in: trb 00000000391b49ab (E162:D129) buf 0000ffffffb889a8 size 1x 0 ctrl 3aa44464:0000ea91 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.365442: dwc3_complete_trb: ep5in: trb 00000000979d3c23 (E162:D130) buf 0000ffffffb89bb4 size 1x 0 ctrl 3aa44470:0000ea91 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.365448: dwc3_gadget_giveback: ep5in: req 000000007b6ed6f3 length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.372670: dwc3_complete_trb: ep5in: trb 000000007ab7715a (E162:D131) buf 0000ffffffb8c0a8 size 1x 0 ctrl 3aa48464:0000ea92 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.372672: dwc3_complete_trb: ep5in: trb 00000000217c7be7 (E162:D132) buf 0000ffffffb8d7ac size 1x 0 ctrl 3aa48470:0000ea92 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.372678: dwc3_gadget_giveback: ep5in: req 00000000bc2b6c4d length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.379900: dwc3_complete_trb: ep5in: trb 00000000907e85e1 (E162:D133) buf 0000ffffffb90928 size 1x 0 ctrl 3aa4c464:0000ea93 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.379904: dwc3_complete_trb: ep5in: trb 00000000bb860433 (E162:D134) buf 0000ffffffb913a4 size 1x 0 ctrl 3aa4c470:0000ea93 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.379909: dwc3_gadget_giveback: ep5in: req 00000000f8f3eb0d length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.387131: dwc3_complete_trb: ep5in: trb 00000000c0003d17 (E162:D135) buf 0000ffffffb94528 size 1x 0 ctrl 3aa50464:0000ea94 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.387133: dwc3_complete_trb: ep5in: trb 00000000b03c9834 (E162:D136) buf 0000ffffffb95f9c size 1x 0 ctrl 3aa50470:0000ea94 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.387139: dwc3_gadget_giveback: ep5in: req 00000000ab8d9880 length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.394361: dwc3_complete_trb: ep5in: trb 00000000c55d236b (E162:D137) buf 0000ffffffb98ca8 size 1x 0 ctrl 3aa54464:0000ea95 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.394363: dwc3_complete_trb: ep5in: trb 0000000079a7319b (E162:D138) buf 0000ffffffb99b94 size 1x 0 ctrl 3aa54470:0000ea95 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.394369: dwc3_gadget_giveback: ep5in: req 00000000d4dc2a9c length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.401592: dwc3_complete_trb: ep5in: trb 0000000066932860 (E162:D139) buf 0000ffffffae88a8 size 1x 0 ctrl 3aa58464:0000ea96 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.401594: dwc3_complete_trb: ep5in: trb 0000000062d70129 (E162:D140) buf 0000ffffffae978c size 1x 0 ctrl 3aa58470:0000ea96 (hlcs:Sc:isoc)
     irq/50-dwc3-317     [000] d..1.   303.401600: dwc3_gadget_giveback: ep5in: req 000000002268e4db length 7168/7168 zsi ==> -18
     irq/50-dwc3-317     [000] d..1.   303.408822: dwc3_complete_trb: ep5in: trb 00000000c7f30d08 (E162:D141) buf 0000ffffffb20da8 size 1x 0 ctrl 3aa5c464:0000ea97 (hlCs:Sc:isoc-first)
     irq/50-dwc3-317     [000] d..1.   303.408825: dwc3_complete_trb: ep5in: trb 000000009ee7250a (E162:D142) buf 0000ffffffb21384 size 1x 0 ctrl 3aa5cc70:0000ea97 (hlcs:SC:isoc)
     irq/50-dwc3-317     [000] d..1.   303.408830: dwc3_gadget_giveback: ep5in: req 00000000e5c4f08a length 7168/7168 zsI ==> -18
     irq/50-dwc3-317     [000] d..1.   303.416054: dwc3_event: event (ea898096): ep5in: Transfer In Progress [0000ea89] (siM)
     irq/50-dwc3-317     [000] d..1.   303.416056: dwc3_readl: addr 0000000043b43362 offset c2c0 value 010c8002
     irq/50-dwc3-317     [000] d..1.   303.416057: dwc3_writel: addr 00000000980f66dc offset 0008 value 00000000
     irq/50-dwc3-317     [000] d..1.   303.416058: dwc3_writel: addr 00000000e5d226be offset 0004 value 00000000
     irq/50-dwc3-317     [000] d..1.   303.416059: dwc3_writel: addr 00000000cd12f6fc offset 0000 value 00000000
     irq/50-dwc3-317     [000] d..1.   303.416060: dwc3_writel: addr 000000005a3de08f offset 000c value 000b0d08
     irq/50-dwc3-317     [000] d..1.   303.416061: dwc3_readl: addr 000000005a3de08f offset 000c value 000b0908
     irq/50-dwc3-317     [000] d..1.   303.416062: dwc3_gadget_ep_cmd: ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 --> status: Successful
     irq/50-dwc3-317     [000] d..1.   303.416063: dwc3_writel: addr 0000000077945c0a offset c408 value 00001000
     irq/50-dwc3-317     [000] d.h1.   303.416159: dwc3_readl: addr 0000000073cc91b4 offset c40c value 00000010
     irq/50-dwc3-317     [000] d.h1.   303.416161: dwc3_writel: addr 0000000077945c0a offset c408 value 80001000
     irq/50-dwc3-317     [000] d.h1.   303.416162: dwc3_writel: addr 0000000073cc91b4 offset c40c value 00000010
     irq/50-dwc3-317     [000] d..1.   303.416232: dwc3_event: event (ea974096): ep5in: Transfer In Progress [0000ea97] (sIm)
     irq/50-dwc3-317     [000] d..1.   303.416234: dwc3_event: event (eaa14096): ep5in: Transfer In Progress [0000eaa1] (sIm)
     irq/50-dwc3-317     [000] d..1.   303.416235: dwc3_event: event (080b01d6): ep5in: Endpoint Command Complete
     irq/50-dwc3-317     [000] d..1.   303.416244: dwc3_gadget_giveback: ep5in: req 00000000d325210d length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.423562: dwc3_gadget_giveback: ep5in: req 00000000cb1d250d length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.430874: dwc3_gadget_giveback: ep5in: req 0000000039270917 length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.438182: dwc3_gadget_giveback: ep5in: req 00000000803068b1 length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.445490: dwc3_gadget_giveback: ep5in: req 000000009b7e08f9 length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.452799: dwc3_gadget_giveback: ep5in: req 000000001a38dcac length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.460107: dwc3_gadget_giveback: ep5in: req 00000000be265ac6 length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.467415: dwc3_gadget_giveback: ep5in: req 000000008c3acb19 length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.474724: dwc3_gadget_giveback: ep5in: req 000000003b45383a length 0/7168 zsi ==> -104
     irq/50-dwc3-317     [000] d..1.   303.482033: dwc3_gadget_giveback: ep5in: req 000000005af62967 length 0/1180 zsI ==> -104
     irq/50-dwc3-317     [000] d..1.   303.489347: dwc3_event: event (ee2710d6): ep5in: Transfer Not Ready [0000ee27] (Not Active)
     ...


>Please check if the host is actually polling for data at that uframe.
>Each TRB is scheduled for a particular interval. If the host doesn't
>request for data at that particular interval, then it's a missed isoc
>also (err -18). So, if you have a usb traffic analyzer, please verify
>this. Also, maybe try with a different host vendor to see if the
>behavior is the same.

The behavior seems to differ if I attach different hosts. I have no
traffic analyzer. Would usbmon under linux host work for that? How would
I synchronize the gadget request and host urbs to know which frame
interval would have been the one that was missed in my logs?

Is there any way the gadget driver could see if for that interval the
host did not poll for data? OR are there bits to get this behaviour
predictable and the driver to react on?

Otherwise, why should on an ongoing stream the host not poll
for data in any interval. What would be the constraints to
ignore one interval.

Regards,
Michael

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Thinh Nguyen]

Michael Grzeschik wrote:
> On Wed, Mar 02, 2022 at 10:22:55PM +0000, Thinh Nguyen wrote:
>> Michael Grzeschik wrote:
>>> I am currently debugging a strange error with transferring isoc requests
>>> with
>>> the current mainline driver.
>>>
>>> When the pending and started list is empty the complete interrupt
>>> handler is
>>> sending an End Transfer to the controller. This End Transfer will
>>> then get
>>> successfully completed.
>>>
>>>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
>>> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 -->
>>> status: Successful
>>>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
>>> (080b01d6): ep5in: Endpoint Command Complete
>>>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
>>> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
>>>
>>>
>>> After this the Transfer needs to start again. But unfortunately this
>>> sometimes
>>> does not succeed. You see in the following trace that the Start of
>>> the just
>>> prepared trbs did complete with an -18.
>>>
>>>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
>>> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size 1x 12
>>> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>>>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
>>> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
>>> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
> 
> [snip]
> 
>>>
>>> The intermediate Bus Expiry is not always present in that case, but also
>>> completely acceptable as we loop
>>> over the Start Transfer until this succeeds.
>>>
>>> Do you have any Idea why this succeeded Start Streaming does come back
>>> with an
>>> Missed Transfer on the first trb?
>>>
>>
>> Hi Michael,
>>
>> When sending the trace, please leave it unfiltered. It's missing some
>> trace events that I want to check.
> 
> Right, it was a mix of trace_event:dwc3:* and ftrace_filter=dwc*. So I
> kind of felt filtering out the interesting part would help.
> 
> Anyway. Here is the same situation in another trace, with all
> trace_events from dwc3:
> 

<snip>

> 
>> Please check if the host is actually polling for data at that uframe.
>> Each TRB is scheduled for a particular interval. If the host doesn't
>> request for data at that particular interval, then it's a missed isoc
>> also (err -18). So, if you have a usb traffic analyzer, please verify
>> this. Also, maybe try with a different host vendor to see if the
>> behavior is the same.
> 
> The behavior seems to differ if I attach different hosts. I have no
> traffic analyzer. Would usbmon under linux host work for that? How would

usbmon doesn't see usb packet level. So no, usbmon doesn't work.

> I synchronize the gadget request and host urbs to know which frame
> interval would have been the one that was missed in my logs?

It will be difficult. You'd have to check the expected interval the urb
was scheduled for from xhci driver, and you may have to check the
MFINDEX. You'd also need to determine a point of reference that the data
received from device is for a particular interval. Even if you have all
this info, you'd have to assume everything the host controller reported
is accurate and not missing anything.

> 
> Is there any way the gadget driver could see if for that interval the
> host did not poll for data? OR are there bits to get this behaviour
> predictable and the driver to react on?
> 

You can check if there any "missed service error" from host, it may give
some clues, but not the whole picture.

> Otherwise, why should on an ongoing stream the host not poll
> for data in any interval. What would be the constraints to
> ignore one interval.

The host driver may not intentionally does it. There are many reasons
where the host controller not poll for data, and I've seen it often. It
can be because of the driver handling interrupt latency/delay that
prevents the driver from feeding isoc TD/TRBs to the controller in time,
causing underflow and starve the controller. Some other time it's the
controller that decided the bandwidth is not sufficient for isoc
transfer or phy signal instability and cause a missed service error etc.

Anyway, in this particular case, from my experience, I don't think it's
the host that's missing a poll. It's probably because the device
scheduling it too aggressively early. Can you try to schedule on the 2nd
interval instead and see if it helps in your case.

diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
index 3e75eaa13abc..b9ec7626b080 100644
--- a/drivers/usb/dwc3/gadget.c
+++ b/drivers/usb/dwc3/gadget.c
@@ -2104,7 +2104,7 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep
*dep)
        }

        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
-               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
+               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 2);

                ret = __dwc3_gadget_kick_transfer(dep);
                if (ret != -EAGAIN)



Also, there's another issue in the dwc3 driver. Currently it checks the
event status and reported it to all the requests. I notice that you (or
the device UVC) don't set interrupt for every request but about every
10th request? Not all of the completed requests failed with missed isoc,
but the interrupt event status incorrectly set -18 for all of them. The
dwc3 driver should check the TRB status for each individual TRB and
return the proper status to the associated request.

Thanks,
Thinh

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Michael Grzeschik]

[-- Attachment #1: Type: text/plain, Size: 7933 bytes --]

On Fri, Mar 04, 2022 at 01:43:00AM +0000, Thinh Nguyen wrote:
>Michael Grzeschik wrote:
>> On Wed, Mar 02, 2022 at 10:22:55PM +0000, Thinh Nguyen wrote:
>>> Michael Grzeschik wrote:
>>>> I am currently debugging a strange error with transferring isoc requests
>>>> with
>>>> the current mainline driver.
>>>>
>>>> When the pending and started list is empty the complete interrupt
>>>> handler is
>>>> sending an End Transfer to the controller. This End Transfer will
>>>> then get
>>>> successfully completed.
>>>>
>>>>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
>>>> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 -->
>>>> status: Successful
>>>>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
>>>> (080b01d6): ep5in: Endpoint Command Complete
>>>>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
>>>> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
>>>>
>>>>
>>>> After this the Transfer needs to start again. But unfortunately this
>>>> sometimes
>>>> does not succeed. You see in the following trace that the Start of
>>>> the just
>>>> prepared trbs did complete with an -18.
>>>>
>>>>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
>>>> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size 1x 12
>>>> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>>>>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
>>>> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
>>>> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>>
>> [snip]
>>
>>>>
>>>> The intermediate Bus Expiry is not always present in that case, but also
>>>> completely acceptable as we loop
>>>> over the Start Transfer until this succeeds.
>>>>
>>>> Do you have any Idea why this succeeded Start Streaming does come back
>>>> with an
>>>> Missed Transfer on the first trb?
>>>>
>>>
>>> Hi Michael,
>>>
>>> When sending the trace, please leave it unfiltered. It's missing some
>>> trace events that I want to check.
>>
>> Right, it was a mix of trace_event:dwc3:* and ftrace_filter=dwc*. So I
>> kind of felt filtering out the interesting part would help.
>>
>> Anyway. Here is the same situation in another trace, with all
>> trace_events from dwc3:
>>
>
><snip>
>
>>
>>> Please check if the host is actually polling for data at that uframe.
>>> Each TRB is scheduled for a particular interval. If the host doesn't
>>> request for data at that particular interval, then it's a missed isoc
>>> also (err -18). So, if you have a usb traffic analyzer, please verify
>>> this. Also, maybe try with a different host vendor to see if the
>>> behavior is the same.
>>
>> The behavior seems to differ if I attach different hosts. I have no
>> traffic analyzer. Would usbmon under linux host work for that? How would
>
>usbmon doesn't see usb packet level. So no, usbmon doesn't work.
>
>> I synchronize the gadget request and host urbs to know which frame
>> interval would have been the one that was missed in my logs?
>
>It will be difficult. You'd have to check the expected interval the urb
>was scheduled for from xhci driver, and you may have to check the
>MFINDEX. You'd also need to determine a point of reference that the data
>received from device is for a particular interval. Even if you have all
>this info, you'd have to assume everything the host controller reported
>is accurate and not missing anything.

Right. But as I have no analyzer, this option is out of scope for now.
And as you further describe the likelihood for the host being the cause
is also very low.

I also was looking into another direction and was suspecting the
frame_length not being properly configured.

In my system the ref_clk is 100MHz so the period is 10ns. That is
also what is configured in dts with snps,ref-clock-period-ns = <10>;

The default for xilinx is <50> so 25MHz. It seemed that changing this
had completely no effect on the transfers. I had expected that this
would change at least the stability.

The fladj is also 0 in all cases. Do I miss something here?

>> Is there any way the gadget driver could see if for that interval the
>> host did not poll for data? OR are there bits to get this behaviour
>> predictable and the driver to react on?
>>
>
>You can check if there any "missed service error" from host, it may give
>some clues, but not the whole picture.

Alright, I will check for that option.

>> Otherwise, why should on an ongoing stream the host not poll
>> for data in any interval. What would be the constraints to
>> ignore one interval.
>
>The host driver may not intentionally does it. There are many reasons
>where the host controller not poll for data, and I've seen it often. It
>can be because of the driver handling interrupt latency/delay that
>prevents the driver from feeding isoc TD/TRBs to the controller in time,
>causing underflow and starve the controller. Some other time it's the
>controller that decided the bandwidth is not sufficient for isoc
>transfer or phy signal instability and cause a missed service error etc.

I also think latency is the point here. I had a patch laying around that
was counting the queued requests but only kicked the start transfer
after one defined threshold was reached. This seemed to help with the
missed interrupts. But unfortunately this approach introduced other
issues. For being absolute save I had to put this threshold very high.
But when in rare cases the Frame that was ment to be enqueued was very
small the full amount of data could reach under that threshold and
stall the whole pipeline, since this frame was then never kicked. I
could sprinkle some timeout handling around it. To ensure that after a
minimum time the last queue will definitely start. But this seemed to be
a very hacky approach.

>Anyway, in this particular case, from my experience, I don't think it's
>the host that's missing a poll. It's probably because the device
>scheduling it too aggressively early. Can you try to schedule on the 2nd
>interval instead and see if it helps in your case.
>
>diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>index 3e75eaa13abc..b9ec7626b080 100644
>--- a/drivers/usb/dwc3/gadget.c
>+++ b/drivers/usb/dwc3/gadget.c
>@@ -2104,7 +2104,7 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep
>*dep)
>        }
>
>        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
>-               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
>+               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 2);
>
>                ret = __dwc3_gadget_kick_transfer(dep);
>                if (ret != -EAGAIN)

I also had this patch applied. I just tested it jet with + 3 instead
and it did stop showing the missed interrupts. Is this a valid patch
for mainline? I had my doubts, so missed to send it yet.

>Also, there's another issue in the dwc3 driver. Currently it checks the
>event status and reported it to all the requests. I notice that you (or
>the device UVC) don't set interrupt for every request but about every
>10th request? Not all of the completed requests failed with missed isoc,
>but the interrupt event status incorrectly set -18 for all of them. The
>dwc3 driver should check the TRB status for each individual TRB and
>return the proper status to the associated request.

Oh! This is where the multiple -18 are coming from. I did not have time
to look for that. But it totally makes sense.

Thanks,
Michael

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Thinh Nguyen]

Michael Grzeschik wrote:
> On Fri, Mar 04, 2022 at 01:43:00AM +0000, Thinh Nguyen wrote:
>> Michael Grzeschik wrote:
>>> On Wed, Mar 02, 2022 at 10:22:55PM +0000, Thinh Nguyen wrote:
>>>> Michael Grzeschik wrote:
>>>>> I am currently debugging a strange error with transferring isoc
>>>>> requests
>>>>> with
>>>>> the current mainline driver.
>>>>>
>>>>> When the pending and started list is empty the complete interrupt
>>>>> handler is
>>>>> sending an End Transfer to the controller. This End Transfer will
>>>>> then get
>>>>> successfully completed.
>>>>>
>>>>>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
>>>>> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000
>>>>> -->
>>>>> status: Successful
>>>>>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
>>>>> (080b01d6): ep5in: Endpoint Command Complete
>>>>>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
>>>>> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
>>>>>
>>>>>
>>>>> After this the Transfer needs to start again. But unfortunately this
>>>>> sometimes
>>>>> does not succeed. You see in the following trace that the Start of
>>>>> the just
>>>>> prepared trbs did complete with an -18.
>>>>>
>>>>>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
>>>>> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size
>>>>> 1x 12
>>>>> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>>>>>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
>>>>> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
>>>>> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>>>
>>> [snip]
>>>
>>>>>
>>>>> The intermediate Bus Expiry is not always present in that case, but
>>>>> also
>>>>> completely acceptable as we loop
>>>>> over the Start Transfer until this succeeds.
>>>>>
>>>>> Do you have any Idea why this succeeded Start Streaming does come back
>>>>> with an
>>>>> Missed Transfer on the first trb?
>>>>>
>>>>
>>>> Hi Michael,
>>>>
>>>> When sending the trace, please leave it unfiltered. It's missing some
>>>> trace events that I want to check.
>>>
>>> Right, it was a mix of trace_event:dwc3:* and ftrace_filter=dwc*. So I
>>> kind of felt filtering out the interesting part would help.
>>>
>>> Anyway. Here is the same situation in another trace, with all
>>> trace_events from dwc3:
>>>
>>
>> <snip>
>>
>>>
>>>> Please check if the host is actually polling for data at that uframe.
>>>> Each TRB is scheduled for a particular interval. If the host doesn't
>>>> request for data at that particular interval, then it's a missed isoc
>>>> also (err -18). So, if you have a usb traffic analyzer, please verify
>>>> this. Also, maybe try with a different host vendor to see if the
>>>> behavior is the same.
>>>
>>> The behavior seems to differ if I attach different hosts. I have no
>>> traffic analyzer. Would usbmon under linux host work for that? How would
>>
>> usbmon doesn't see usb packet level. So no, usbmon doesn't work.
>>
>>> I synchronize the gadget request and host urbs to know which frame
>>> interval would have been the one that was missed in my logs?
>>
>> It will be difficult. You'd have to check the expected interval the urb
>> was scheduled for from xhci driver, and you may have to check the
>> MFINDEX. You'd also need to determine a point of reference that the data
>> received from device is for a particular interval. Even if you have all
>> this info, you'd have to assume everything the host controller reported
>> is accurate and not missing anything.
> 
> Right. But as I have no analyzer, this option is out of scope for now.
> And as you further describe the likelihood for the host being the cause
> is also very low.
> 
> I also was looking into another direction and was suspecting the
> frame_length not being properly configured.
> 
> In my system the ref_clk is 100MHz so the period is 10ns. That is
> also what is configured in dts with snps,ref-clock-period-ns = <10>;
> 
> The default for xilinx is <50> so 25MHz. It seemed that changing this
> had completely no effect on the transfers. I had expected that this
> would change at least the stability.
> 
> The fladj is also 0 in all cases. Do I miss something here?

The controller turns off some clocks and uses ref_clk to track the current
uframe when it's in low power. If the device is not in low power, then there's
no need for it to use the ref_clk to track uframe. The UVC is running isoc at
1 uframe interval, the device definitely won't go in low power at this rate.

Also, I'm not sure if your setup is configured to take advantage of that feature
either.

> 
>>> Is there any way the gadget driver could see if for that interval the
>>> host did not poll for data? OR are there bits to get this behaviour
>>> predictable and the driver to react on?
>>>
>>
>> You can check if there any "missed service error" from host, it may give
>> some clues, but not the whole picture.
> 
> Alright, I will check for that option.
> 
>>> Otherwise, why should on an ongoing stream the host not poll
>>> for data in any interval. What would be the constraints to
>>> ignore one interval.
>>
>> The host driver may not intentionally does it. There are many reasons
>> where the host controller not poll for data, and I've seen it often. It
>> can be because of the driver handling interrupt latency/delay that
>> prevents the driver from feeding isoc TD/TRBs to the controller in time,
>> causing underflow and starve the controller. Some other time it's the
>> controller that decided the bandwidth is not sufficient for isoc
>> transfer or phy signal instability and cause a missed service error etc.
> 
> I also think latency is the point here. I had a patch laying around that
> was counting the queued requests but only kicked the start transfer
> after one defined threshold was reached. This seemed to help with the
> missed interrupts. But unfortunately this approach introduced other
> issues. For being absolute save I had to put this threshold very high.
> But when in rare cases the Frame that was ment to be enqueued was very
> small the full amount of data could reach under that threshold and
> stall the whole pipeline, since this frame was then never kicked. I
> could sprinkle some timeout handling around it. To ensure that after a
> minimum time the last queue will definitely start. But this seemed to be
> a very hacky approach.

Yeah, that doesn't sound right.

> 
>> Anyway, in this particular case, from my experience, I don't think it's
>> the host that's missing a poll. It's probably because the device
>> scheduling it too aggressively early. Can you try to schedule on the 2nd
>> interval instead and see if it helps in your case.
>>
>> diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>> index 3e75eaa13abc..b9ec7626b080 100644
>> --- a/drivers/usb/dwc3/gadget.c
>> +++ b/drivers/usb/dwc3/gadget.c
>> @@ -2104,7 +2104,7 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep
>> *dep)
>>        }
>>
>>        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
>> -               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
>> +               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 2);
>>
>>                ret = __dwc3_gadget_kick_transfer(dep);
>>                if (ret != -EAGAIN)
> 
> I also had this patch applied. I just tested it jet with + 3 instead
> and it did stop showing the missed interrupts. Is this a valid patch
> for mainline? I had my doubts, so missed to send it yet.
> 

Not by itself like this. I just wanted to test this and confirm my
suspicion, which it did.

For a real patch, it should look something like this:

diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
index 3e75eaa13abc..fb070a3237a8 100644
--- a/drivers/usb/dwc3/gadget.c
+++ b/drivers/usb/dwc3/gadget.c
@@ -2104,7 +2104,13 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep *dep)
        }
 
        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
-               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
+               int future_interval = i + 1;
+
+               /* Give the controller at least 500us to schedule transfer */
+               if (desc->bInterval < 3)
+                       future_interval += 3 - desc->bInterval;
+
+               dep->frame_number = DWC3_ALIGN_FRAME(dep, future_interval);
 
                ret = __dwc3_gadget_kick_transfer(dep);
                if (ret != -EAGAIN)


>> Also, there's another issue in the dwc3 driver. Currently it checks the
>> event status and reported it to all the requests. I notice that you (or
>> the device UVC) don't set interrupt for every request but about every
>> 10th request? Not all of the completed requests failed with missed isoc,
>> but the interrupt event status incorrectly set -18 for all of them. The
>> dwc3 driver should check the TRB status for each individual TRB and
>> return the proper status to the associated request.
> 
> Oh! This is where the multiple -18 are coming from. I did not have time
> to look for that. But it totally makes sense.
> 

If you're up to creating a patch to fix it, I'll be glad to review it.
If not, it'll be on my to-do list (which may take awhile).

Thanks,
Thinh

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Michael Grzeschik]

[-- Attachment #1: Type: text/plain, Size: 10216 bytes --]

On Fri, Mar 04, 2022 at 11:48:20PM +0000, Thinh Nguyen wrote:
>Michael Grzeschik wrote:
>> On Fri, Mar 04, 2022 at 01:43:00AM +0000, Thinh Nguyen wrote:
>>> Michael Grzeschik wrote:
>>>> On Wed, Mar 02, 2022 at 10:22:55PM +0000, Thinh Nguyen wrote:
>>>>> Michael Grzeschik wrote:
>>>>>> I am currently debugging a strange error with transferring isoc
>>>>>> requests
>>>>>> with
>>>>>> the current mainline driver.
>>>>>>
>>>>>> When the pending and started list is empty the complete interrupt
>>>>>> handler is
>>>>>> sending an End Transfer to the controller. This End Transfer will
>>>>>> then get
>>>>>> successfully completed.
>>>>>>
>>>>>>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
>>>>>> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000
>>>>>> -->
>>>>>> status: Successful
>>>>>>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
>>>>>> (080b01d6): ep5in: Endpoint Command Complete
>>>>>>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
>>>>>> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
>>>>>>
>>>>>>
>>>>>> After this the Transfer needs to start again. But unfortunately this
>>>>>> sometimes
>>>>>> does not succeed. You see in the following trace that the Start of
>>>>>> the just
>>>>>> prepared trbs did complete with an -18.
>>>>>>
>>>>>>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
>>>>>> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size
>>>>>> 1x 12
>>>>>> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>>>>>>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
>>>>>> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
>>>>>> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>>>>
>>>> [snip]
>>>>
>>>>>>
>>>>>> The intermediate Bus Expiry is not always present in that case, but
>>>>>> also
>>>>>> completely acceptable as we loop
>>>>>> over the Start Transfer until this succeeds.
>>>>>>
>>>>>> Do you have any Idea why this succeeded Start Streaming does come back
>>>>>> with an
>>>>>> Missed Transfer on the first trb?
>>>>>>
>>>>>
>>>>> Hi Michael,
>>>>>
>>>>> When sending the trace, please leave it unfiltered. It's missing some
>>>>> trace events that I want to check.
>>>>
>>>> Right, it was a mix of trace_event:dwc3:* and ftrace_filter=dwc*. So I
>>>> kind of felt filtering out the interesting part would help.
>>>>
>>>> Anyway. Here is the same situation in another trace, with all
>>>> trace_events from dwc3:
>>>>
>>>
>>> <snip>
>>>
>>>>
>>>>> Please check if the host is actually polling for data at that uframe.
>>>>> Each TRB is scheduled for a particular interval. If the host doesn't
>>>>> request for data at that particular interval, then it's a missed isoc
>>>>> also (err -18). So, if you have a usb traffic analyzer, please verify
>>>>> this. Also, maybe try with a different host vendor to see if the
>>>>> behavior is the same.
>>>>
>>>> The behavior seems to differ if I attach different hosts. I have no
>>>> traffic analyzer. Would usbmon under linux host work for that? How would
>>>
>>> usbmon doesn't see usb packet level. So no, usbmon doesn't work.
>>>
>>>> I synchronize the gadget request and host urbs to know which frame
>>>> interval would have been the one that was missed in my logs?
>>>
>>> It will be difficult. You'd have to check the expected interval the urb
>>> was scheduled for from xhci driver, and you may have to check the
>>> MFINDEX. You'd also need to determine a point of reference that the data
>>> received from device is for a particular interval. Even if you have all
>>> this info, you'd have to assume everything the host controller reported
>>> is accurate and not missing anything.
>>
>> Right. But as I have no analyzer, this option is out of scope for now.
>> And as you further describe the likelihood for the host being the cause
>> is also very low.
>>
>> I also was looking into another direction and was suspecting the
>> frame_length not being properly configured.
>>
>> In my system the ref_clk is 100MHz so the period is 10ns. That is
>> also what is configured in dts with snps,ref-clock-period-ns = <10>;
>>
>> The default for xilinx is <50> so 25MHz. It seemed that changing this
>> had completely no effect on the transfers. I had expected that this
>> would change at least the stability.
>>
>> The fladj is also 0 in all cases. Do I miss something here?
>
>The controller turns off some clocks and uses ref_clk to track the current
>uframe when it's in low power. If the device is not in low power, then there's
>no need for it to use the ref_clk to track uframe. The UVC is running isoc at
>1 uframe interval, the device definitely won't go in low power at this rate.
>
>Also, I'm not sure if your setup is configured to take advantage of that feature
>either.
>

I see.

>>
>>>> Is there any way the gadget driver could see if for that interval the
>>>> host did not poll for data? OR are there bits to get this behaviour
>>>> predictable and the driver to react on?
>>>>
>>>
>>> You can check if there any "missed service error" from host, it may give
>>> some clues, but not the whole picture.
>>
>> Alright, I will check for that option.
>>
>>>> Otherwise, why should on an ongoing stream the host not poll
>>>> for data in any interval. What would be the constraints to
>>>> ignore one interval.
>>>
>>> The host driver may not intentionally does it. There are many reasons
>>> where the host controller not poll for data, and I've seen it often. It
>>> can be because of the driver handling interrupt latency/delay that
>>> prevents the driver from feeding isoc TD/TRBs to the controller in time,
>>> causing underflow and starve the controller. Some other time it's the
>>> controller that decided the bandwidth is not sufficient for isoc
>>> transfer or phy signal instability and cause a missed service error etc.
>>
>> I also think latency is the point here. I had a patch laying around that
>> was counting the queued requests but only kicked the start transfer
>> after one defined threshold was reached. This seemed to help with the
>> missed interrupts. But unfortunately this approach introduced other
>> issues. For being absolute save I had to put this threshold very high.
>> But when in rare cases the Frame that was ment to be enqueued was very
>> small the full amount of data could reach under that threshold and
>> stall the whole pipeline, since this frame was then never kicked. I
>> could sprinkle some timeout handling around it. To ensure that after a
>> minimum time the last queue will definitely start. But this seemed to be
>> a very hacky approach.
>
>Yeah, that doesn't sound right.
>
>>
>>> Anyway, in this particular case, from my experience, I don't think it's
>>> the host that's missing a poll. It's probably because the device
>>> scheduling it too aggressively early. Can you try to schedule on the 2nd
>>> interval instead and see if it helps in your case.
>>>
>>> diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>>> index 3e75eaa13abc..b9ec7626b080 100644
>>> --- a/drivers/usb/dwc3/gadget.c
>>> +++ b/drivers/usb/dwc3/gadget.c
>>> @@ -2104,7 +2104,7 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep
>>> *dep)
>>>        }
>>>
>>>        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
>>> -               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
>>> +               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 2);
>>>
>>>                ret = __dwc3_gadget_kick_transfer(dep);
>>>                if (ret != -EAGAIN)
>>
>> I also had this patch applied. I just tested it jet with + 3 instead
>> and it did stop showing the missed interrupts. Is this a valid patch
>> for mainline? I had my doubts, so missed to send it yet.
>>
>
>Not by itself like this. I just wanted to test this and confirm my
>suspicion, which it did.
>
>For a real patch, it should look something like this:
>
>diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>index 3e75eaa13abc..fb070a3237a8 100644
>--- a/drivers/usb/dwc3/gadget.c
>+++ b/drivers/usb/dwc3/gadget.c
>@@ -2104,7 +2104,13 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep *dep)
>        }
>
>        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
>-               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
>+               int future_interval = i + 1;
>+
>+               /* Give the controller at least 500us to schedule transfer */
>+               if (desc->bInterval < 3)
>+                       future_interval += 3 - desc->bInterval;
>+
>+               dep->frame_number = DWC3_ALIGN_FRAME(dep, future_interval);
>
>                ret = __dwc3_gadget_kick_transfer(dep);
>                if (ret != -EAGAIN)


That looks much better! Will you send this?

>>> Also, there's another issue in the dwc3 driver. Currently it checks the
>>> event status and reported it to all the requests. I notice that you (or
>>> the device UVC) don't set interrupt for every request but about every
>>> 10th request? Not all of the completed requests failed with missed isoc,
>>> but the interrupt event status incorrectly set -18 for all of them. The
>>> dwc3 driver should check the TRB status for each individual TRB and
>>> return the proper status to the associated request.
>>
>> Oh! This is where the multiple -18 are coming from. I did not have time
>> to look for that. But it totally makes sense.
>>
>
>If you're up to creating a patch to fix it, I'll be glad to review it.
>If not, it'll be on my to-do list (which may take awhile).

Just did that:

https://lore.kernel.org/linux-usb/20220307214639.4164547-1-m.grzeschik@pengutronix.de/T/#u

Thanks,
Michael

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Michael Grzeschik]

[-- Attachment #1: Type: text/plain, Size: 7224 bytes --]

On Fri, Mar 04, 2022 at 01:43:00AM +0000, Thinh Nguyen wrote:
>Michael Grzeschik wrote:
>> On Wed, Mar 02, 2022 at 10:22:55PM +0000, Thinh Nguyen wrote:
>>> Michael Grzeschik wrote:
>>>> I am currently debugging a strange error with transferring isoc requests
>>>> with
>>>> the current mainline driver.
>>>>
>>>> When the pending and started list is empty the complete interrupt
>>>> handler is
>>>> sending an End Transfer to the controller. This End Transfer will
>>>> then get
>>>> successfully completed.
>>>>
>>>>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
>>>> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000 -->
>>>> status: Successful
>>>>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
>>>> (080b01d6): ep5in: Endpoint Command Complete
>>>>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
>>>> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
>>>>
>>>>
>>>> After this the Transfer needs to start again. But unfortunately this
>>>> sometimes
>>>> does not succeed. You see in the following trace that the Start of
>>>> the just
>>>> prepared trbs did complete with an -18.
>>>>
>>>>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
>>>> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size 1x 12
>>>> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>>>>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
>>>> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
>>>> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>>
>> [snip]
>>
>>>>
>>>> The intermediate Bus Expiry is not always present in that case, but also
>>>> completely acceptable as we loop
>>>> over the Start Transfer until this succeeds.
>>>>
>>>> Do you have any Idea why this succeeded Start Streaming does come back
>>>> with an
>>>> Missed Transfer on the first trb?
>>>>
>>>
>>> Hi Michael,
>>>
>>> When sending the trace, please leave it unfiltered. It's missing some
>>> trace events that I want to check.
>>
>> Right, it was a mix of trace_event:dwc3:* and ftrace_filter=dwc*. So I
>> kind of felt filtering out the interesting part would help.
>>
>> Anyway. Here is the same situation in another trace, with all
>> trace_events from dwc3:
>>
>
><snip>
>
>>
>>> Please check if the host is actually polling for data at that uframe.
>>> Each TRB is scheduled for a particular interval. If the host doesn't
>>> request for data at that particular interval, then it's a missed isoc
>>> also (err -18). So, if you have a usb traffic analyzer, please verify
>>> this. Also, maybe try with a different host vendor to see if the
>>> behavior is the same.
>>
>> The behavior seems to differ if I attach different hosts. I have no
>> traffic analyzer. Would usbmon under linux host work for that? How would
>
>usbmon doesn't see usb packet level. So no, usbmon doesn't work.
>
>> I synchronize the gadget request and host urbs to know which frame
>> interval would have been the one that was missed in my logs?
>
>It will be difficult. You'd have to check the expected interval the urb
>was scheduled for from xhci driver, and you may have to check the
>MFINDEX. You'd also need to determine a point of reference that the data
>received from device is for a particular interval. Even if you have all
>this info, you'd have to assume everything the host controller reported
>is accurate and not missing anything.
>
>>
>> Is there any way the gadget driver could see if for that interval the
>> host did not poll for data? OR are there bits to get this behaviour
>> predictable and the driver to react on?
>>
>
>You can check if there any "missed service error" from host, it may give
>some clues, but not the whole picture.
>
>> Otherwise, why should on an ongoing stream the host not poll
>> for data in any interval. What would be the constraints to
>> ignore one interval.
>
>The host driver may not intentionally does it. There are many reasons
>where the host controller not poll for data, and I've seen it often. It
>can be because of the driver handling interrupt latency/delay that
>prevents the driver from feeding isoc TD/TRBs to the controller in time,
>causing underflow and starve the controller. Some other time it's the
>controller that decided the bandwidth is not sufficient for isoc
>transfer or phy signal instability and cause a missed service error etc.
>
>Anyway, in this particular case, from my experience, I don't think it's
>the host that's missing a poll. It's probably because the device
>scheduling it too aggressively early. Can you try to schedule on the 2nd
>interval instead and see if it helps in your case.
>
>diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>index 3e75eaa13abc..b9ec7626b080 100644
>--- a/drivers/usb/dwc3/gadget.c
>+++ b/drivers/usb/dwc3/gadget.c
>@@ -2104,7 +2104,7 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep
>*dep)
>        }
>
>        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
>-               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
>+               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 2);
>
>                ret = __dwc3_gadget_kick_transfer(dep);
>                if (ret != -EAGAIN)
>
>

I think I found the case:

From my datasheet:

<quote>
  After a transfer has been started, the hardware will perform the following functions for
  IN endpoints:

  1. Fetch TX data as early as one interval prior to the beginning of the interval (call it A)
     if the HWO bit is set to one in the TRB.
  2. Decrement the buffer size of each TRB as packets are transmitted.
  3. Retire TRBs when their buffer size has reached 0, issuing an XferInProgress event if
     the IOC bit is set.
  4. If the next interval (B) starts before all the packets have been transmitted for interval A:
     a. Flush the TXFIFO.
     b. Retire the Buffer Descriptor of interval A with a "Missed Isochronous" status.
     c. Retire the Buffer Descriptor of interval B with a "Missed Isochronous" status.
     d. See Checking interval status for a description of how software can determine that
        an interval ended unexpectedly.
     e. Go to step 1 to prepare for interval C
  5. Otherwise, if all the TRBs of interval A are completed, the hardware will prepare for
     interval B.
</quote>

Could it be that in the observed case we just run directly into case 4
after issueing Stream Start. Since the frame interval we programm
is so close to the current running frame interval.

So actually applying the below patch would totally make sense. We could even
increase that to an higher number, just to make sure that we would not run into
an partially started frame interval when issueing the Start Transfer.


Thanks,
Michael

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: DWC3 Isoc Gadget Missed Interrupts on Start Transfer

[Thinh Nguyen]

Michael Grzeschik wrote:
> On Fri, Mar 04, 2022 at 01:43:00AM +0000, Thinh Nguyen wrote:
>> Michael Grzeschik wrote:
>>> On Wed, Mar 02, 2022 at 10:22:55PM +0000, Thinh Nguyen wrote:
>>>> Michael Grzeschik wrote:
>>>>> I am currently debugging a strange error with transferring isoc
>>>>> requests
>>>>> with
>>>>> the current mainline driver.
>>>>>
>>>>> When the pending and started list is empty the complete interrupt
>>>>> handler is
>>>>> sending an End Transfer to the controller. This End Transfer will
>>>>> then get
>>>>> successfully completed.
>>>>>
>>>>>     irq/50-dwc3-305     [000] d..1.   166.661845: dwc3_gadget_ep_cmd:
>>>>> ep5in: cmd 'End Transfer' [b0d08] params 00000000 00000000 00000000
>>>>> -->
>>>>> status: Successful
>>>>>     irq/50-dwc3-305     [000] d..1.   166.661877: dwc3_event: event
>>>>> (080b01d6): ep5in: Endpoint Command Complete
>>>>>     irq/50-dwc3-305     [000] d..1.   166.661979: dwc3_event: event
>>>>> (482a10d6): ep5in: Transfer Not Ready [0000482a] (Not Active)
>>>>>
>>>>>
>>>>> After this the Transfer needs to start again. But unfortunately this
>>>>> sometimes
>>>>> does not succeed. You see in the following trace that the Start of
>>>>> the just
>>>>> prepared trbs did complete with an -18.
>>>>>
>>>>>    kworker/u5:2-347     [001] d..2.   166.691288: dwc3_prepare_trb:
>>>>> ep5in: trb 000000007ff95a12 (E233:D232) buf 0000ffffffb1c2a8 size
>>>>> 1x 12
>>>>> ctrl 00000465:00000000 (HlCs:Sc:isoc-first)
>>>>>    kworker/u5:2-347     [001] d..2.   166.691293: dwc3_prepare_trb:
>>>>> ep5in: trb 00000000f9cd175e (E234:D232) buf 0000ffffffb1d000 size 1x
>>>>> 7156 ctrl 00000471:00000000 (Hlcs:Sc:isoc)
>>>
>>> [snip]
>>>
>>>>>
>>>>> The intermediate Bus Expiry is not always present in that case, but
>>>>> also
>>>>> completely acceptable as we loop
>>>>> over the Start Transfer until this succeeds.
>>>>>
>>>>> Do you have any Idea why this succeeded Start Streaming does come back
>>>>> with an
>>>>> Missed Transfer on the first trb?
>>>>>
>>>>
>>>> Hi Michael,
>>>>
>>>> When sending the trace, please leave it unfiltered. It's missing some
>>>> trace events that I want to check.
>>>
>>> Right, it was a mix of trace_event:dwc3:* and ftrace_filter=dwc*. So I
>>> kind of felt filtering out the interesting part would help.
>>>
>>> Anyway. Here is the same situation in another trace, with all
>>> trace_events from dwc3:
>>>
>>
>> <snip>
>>
>>>
>>>> Please check if the host is actually polling for data at that uframe.
>>>> Each TRB is scheduled for a particular interval. If the host doesn't
>>>> request for data at that particular interval, then it's a missed isoc
>>>> also (err -18). So, if you have a usb traffic analyzer, please verify
>>>> this. Also, maybe try with a different host vendor to see if the
>>>> behavior is the same.
>>>
>>> The behavior seems to differ if I attach different hosts. I have no
>>> traffic analyzer. Would usbmon under linux host work for that? How would
>>
>> usbmon doesn't see usb packet level. So no, usbmon doesn't work.
>>
>>> I synchronize the gadget request and host urbs to know which frame
>>> interval would have been the one that was missed in my logs?
>>
>> It will be difficult. You'd have to check the expected interval the urb
>> was scheduled for from xhci driver, and you may have to check the
>> MFINDEX. You'd also need to determine a point of reference that the data
>> received from device is for a particular interval. Even if you have all
>> this info, you'd have to assume everything the host controller reported
>> is accurate and not missing anything.
>>
>>>
>>> Is there any way the gadget driver could see if for that interval the
>>> host did not poll for data? OR are there bits to get this behaviour
>>> predictable and the driver to react on?
>>>
>>
>> You can check if there any "missed service error" from host, it may give
>> some clues, but not the whole picture.
>>
>>> Otherwise, why should on an ongoing stream the host not poll
>>> for data in any interval. What would be the constraints to
>>> ignore one interval.
>>
>> The host driver may not intentionally does it. There are many reasons
>> where the host controller not poll for data, and I've seen it often. It
>> can be because of the driver handling interrupt latency/delay that
>> prevents the driver from feeding isoc TD/TRBs to the controller in time,
>> causing underflow and starve the controller. Some other time it's the
>> controller that decided the bandwidth is not sufficient for isoc
>> transfer or phy signal instability and cause a missed service error etc.
>>
>> Anyway, in this particular case, from my experience, I don't think it's
>> the host that's missing a poll. It's probably because the device
>> scheduling it too aggressively early. Can you try to schedule on the 2nd
>> interval instead and see if it helps in your case.
>>
>> diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>> index 3e75eaa13abc..b9ec7626b080 100644
>> --- a/drivers/usb/dwc3/gadget.c
>> +++ b/drivers/usb/dwc3/gadget.c
>> @@ -2104,7 +2104,7 @@ static int __dwc3_gadget_start_isoc(struct dwc3_ep
>> *dep)
>>        }
>>
>>        for (i = 0; i < DWC3_ISOC_MAX_RETRIES; i++) {
>> -               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 1);
>> +               dep->frame_number = DWC3_ALIGN_FRAME(dep, i + 2);
>>
>>                ret = __dwc3_gadget_kick_transfer(dep);
>>                if (ret != -EAGAIN)
>>
>>
> 
> I think I found the case:
> 
> From my datasheet:
> 
> <quote>
>  After a transfer has been started, the hardware will perform the
> following functions for
>  IN endpoints:
> 
>  1. Fetch TX data as early as one interval prior to the beginning of the
> interval (call it A)
>     if the HWO bit is set to one in the TRB.
>  2. Decrement the buffer size of each TRB as packets are transmitted.
>  3. Retire TRBs when their buffer size has reached 0, issuing an
> XferInProgress event if
>     the IOC bit is set.
>  4. If the next interval (B) starts before all the packets have been
> transmitted for interval A:
>     a. Flush the TXFIFO.
>     b. Retire the Buffer Descriptor of interval A with a "Missed
> Isochronous" status.
>     c. Retire the Buffer Descriptor of interval B with a "Missed
> Isochronous" status.
>     d. See Checking interval status for a description of how software
> can determine that
>        an interval ended unexpectedly.
>     e. Go to step 1 to prepare for interval C
>  5. Otherwise, if all the TRBs of interval A are completed, the hardware
> will prepare for
>     interval B.
> </quote>
> 
> Could it be that in the observed case we just run directly into case 4
> after issueing Stream Start. Since the frame interval we programm
> is so close to the current running frame interval.

Yes, that's what the code snippet I sent to confirm the case was for.
Typically, the Start Transfer command status "bus expiry" will tell the
driver of this case, but that may not be enough.

> 
> So actually applying the below patch would totally make sense. We could
> even
> increase that to an higher number, just to make sure that we would not
> run into
> an partially started frame interval when issueing the Start Transfer.
> 

See my other email to make a patch.

Thanks,
Thinh