Date:   Tue, 20 Apr 2021 10:19:01 +0200
From:   Pavel Hofman <pavel.hofman@...tera.com>
To:     Minas Harutyunyan <Minas.Harutyunyan@...opsys.com>,
        Ruslan Bilovol <ruslan.bilovol@...il.com>,
        Linux USB <linux-usb@...r.kernel.org>
Cc:     "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>
Subject: Re: RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP +
 DATA OUT transaction


Dne 19. 04. 21 v 18:30 Minas Harutyunyan napsal(a):
> Hi Pavel,
> 
> On 4/19/2021 5:22 PM, Pavel Hofman wrote:
>>
>> Dne 11. 02. 21 v 12:21 Minas Harutyunyan napsal(a):
>>> Hi Ruslan,
>>>
>>> On 2/1/2021 3:44 AM, Ruslan Bilovol wrote:
>>>> Hi Minas and other USB experts,
>>>>
>>>> I'm currently developing new features for UAC1/UAC2 audio gadgets
>>>> like Volume/Mute controls which use Control SETUP + DATA OUT
>>>> transactions through ep0.
>>>>
>>>> While it works fine on BeagleBone black board with MUSB UDC,
>>>> on Raspberry Pi 4 with DWC2 UDC there is an issue.
>>>>
>>>> I found that when DWC2 receives ep0 SETUP + DATA OUT transaction,
>>>> it doesn't copy data transferred from the host to EP0 in DATA OUT stage
>>>> to the usb_request->buf buffer. This buffer contains unchanged data from
>>>> previous transactions.
>>>>
>>>
>>> Could you please send debug log with issue and usb trace.
>>>
>>
>> Hi Minas,
>>
>> I confirm this problem with DWC2 gadget on RPi4. I rebased Julian's
>> multiple audio clocks patch
>> https://urldefense.com/v3/__https://lore.kernel.org/patchwork/patch/803422/__;!!A4F2R9G_pg!J3zujH0Tzsp0DBsJm6EPTzG0vdr9plGNx7jmoik8JvN4NqODulvND5RXZiLE8d70RkUod4ZZ$  on top of Ruslan's
>> implicit feedback patches
>> https://urldefense.com/v3/__https://patchwork.kernel.org/project/linux-usb/list/?series=&submitter=121671&state=&q=&archive=&delegate=__;!!A4F2R9G_pg!J3zujH0Tzsp0DBsJm6EPTzG0vdr9plGNx7jmoik8JvN4NqODulvND5RXZiLE8d70Rtv_duVh$
>> on branch rpi-5.12.y
>> https://urldefense.com/v3/__https://github.com/raspberrypi/linux/tree/rpi-5.12.y__;!!A4F2R9G_pg!J3zujH0Tzsp0DBsJm6EPTzG0vdr9plGNx7jmoik8JvN4NqODulvND5RXZiLE8d70Rkqjb2Qb$  and compiled for arm64.
>>
>> When USB host switches audio playback to non-default samplerate (from
>> 96000 to 192000 in my case), usb_request->buf contains the previous
>> default value of 96000, instead of the new value sent by the host - see
>> the captured USB packet below:
>>
>> ===============
>> Frame 9: 68 bytes on wire (544 bits), 68 bytes captured (544 bits) on
>> interface usbmon1, id 0
>>      Interface id: 0 (usbmon1)
>>          Interface name: usbmon1
>>      Encapsulation type: USB packets with Linux header and padding (115)
>>      Arrival Time: Apr 19, 2021 13:41:25.146650000 CEST
>>      [Time shift for this packet: 0.000000000 seconds]
>>      Epoch Time: 1618832485.146650000 seconds
>>      [Time delta from previous captured frame: 0.000050000 seconds]
>>      [Time delta from previous displayed frame: 0.000050000 seconds]
>>      [Time since reference or first frame: 6.013518000 seconds]
>>      Frame Number: 9
>>      Frame Length: 68 bytes (544 bits)
>>      Capture Length: 68 bytes (544 bits)
>>      [Frame is marked: False]
>>      [Frame is ignored: False]
>>      [Protocols in frame: usb]
>> USB URB
>>      [Source: host]
>>      [Destination: 1.14.0]
>>      URB id: 0xffff8c37444f2480
>>      URB type: URB_SUBMIT ('S')
>>      URB transfer type: URB_CONTROL (0x02)
>>      Endpoint: 0x00, Direction: OUT
>>          0... .... = Direction: OUT (0)
>>          .... 0000 = Endpoint number: 0
>>      Device: 14
>>      URB bus id: 1
>>      Device setup request: relevant (0)
>>      Data: present (0)
>>      URB sec: 1618832485
>>      URB usec: 146650
>>      URB status: Operation now in progress (-EINPROGRESS) (-115)
>>      URB length [bytes]: 4
>>      Data length [bytes]: 4
>>      [Response in: 10]
>>      Interval: 0
>>      Start frame: 0
>>      Copy of Transfer Flags: 0x00000000
>>          .... .... .... .... .... .... .... ...0 = Short not OK: False
>>          .... .... .... .... .... .... .... ..0. = ISO ASAP: False
>>          .... .... .... .... .... .... .... .0.. = No transfer DMA map: False
>>          .... .... .... .... .... .... ..0. .... = No FSBR: False
>>          .... .... .... .... .... .... .0.. .... = Zero Packet: False
>>          .... .... .... .... .... .... 0... .... = No Interrupt: False
>>          .... .... .... .... .... ...0 .... .... = Free Buffer: False
>>          .... .... .... .... .... ..0. .... .... = Dir IN: False
>>          .... .... .... ...0 .... .... .... .... = DMA Map Single: False
>>          .... .... .... ..0. .... .... .... .... = DMA Map Page: False
>>          .... .... .... .0.. .... .... .... .... = DMA Map SG: False
>>          .... .... .... 0... .... .... .... .... = Map Local: False
>>          .... .... ...0 .... .... .... .... .... = Setup Map Single: False
>>          .... .... ..0. .... .... .... .... .... = Setup Map Local: False
>>          .... .... .0.. .... .... .... .... .... = DMA S-G Combined: False
>>          .... .... 0... .... .... .... .... .... = Aligned Temp Buffer: False
>>      Number of ISO descriptors: 0
>>      [bInterfaceClass: Unknown (0xffff)]
>> Setup Data
>>      bmRequestType: 0x21
>>          0... .... = Direction: Host-to-device
>>          .01. .... = Type: Class (0x1)
>>          ...0 0001 = Recipient: Interface (0x01)
>>      bRequest: 1
>>      wValue: 0x0100
>>      wIndex: 1792 (0x0700)
>>      wLength: 4
>>      Data Fragment: 00ee0200      <------------------------------
>> ===============
>>
>>
Hi Minas,


> Some clarifications required:
> 1. gadget works in scatter/gather DMA mode (g_dma_desc is true)?

I guess not, this is /sys/kernel/debug/usb/fe980000.usb/params:

otg_cap                       : 0
dma_desc_enable               : 0
dma_desc_fs_enable            : 0
speed                         : 0
enable_dynamic_fifo           : 1
en_multiple_tx_fifo           : 1
host_rx_fifo_size             : 774
host_nperio_tx_fifo_size      : 256
host_perio_tx_fifo_size       : 512
max_transfer_size             : 65535
max_packet_count              : 511
host_channels                 : 8
phy_type                      : 1
phy_utmi_width                : 8
phy_ulpi_ddr                  : 0
phy_ulpi_ext_vbus             : 0
i2c_enable                    : 0
ipg_isoc_en                   : 0
ulpi_fs_ls                    : 0
host_support_fs_ls_low_power  : 0
host_ls_low_power_phy_clk     : 0
ts_dline                      : 0
reload_ctl                    : 0
ahbcfg                        : 0x10
uframe_sched                  : 1
external_id_pin_ctl           : 0
power_down                    : 0
lpm                           : 0
lpm_clock_gating              : 0
besl                          : 0
hird_threshold_en             : 0
hird_threshold                : 0
service_interval              : 0
host_dma                      : 1
g_dma                         : 1
g_dma_desc                    : 0
g_rx_fifo_size                : 558
g_np_tx_fifo_size             : 32
g_tx_fifo_size[0]             : 0
g_tx_fifo_size[1]             : 512
g_tx_fifo_size[2]             : 512
g_tx_fifo_size[3]             : 512
g_tx_fifo_size[4]             : 512
g_tx_fifo_size[5]             : 512
g_tx_fifo_size[6]             : 256
g_tx_fifo_size[7]             : 256
g_tx_fifo_size[8]             : 0
g_tx_fifo_size[9]             : 0
g_tx_fifo_size[10]            : 0
g_tx_fifo_size[11]            : 0
g_tx_fifo_size[12]            : 0
g_tx_fifo_size[13]            : 0
g_tx_fifo_size[14]            : 0
g_tx_fifo_size[15]            : 0



Also /sys/kernel/debug/usb/fe980000.usb/regdump attached.


> 2. Above captured Host side USB packet corresponds in dmesg to line#39907:
> 
> [ 1261.789552] dwc2 fe980000.usb: ctrl Type=21, Req=01, V=0100, I=0700, 
> L=0004
> 
> Correct?


I think more likely from line #2319 - the value 96000 should be 192000
instead.

[ 1260.277683] dwc2 fe980000.usb: dwc2_hsotg_start_req:
DxEPCTL=0x00028000, ep 0, dir out
[ 1260.277690] dwc2 fe980000.usb: ureq->length:8 ureq->actual:0
[ 1260.277696] dwc2 fe980000.usb: dwc2_hsotg_start_req: 1@8/8,
0x00080008 => 0x00000b10
[ 1260.277702] dwc2 fe980000.usb: dwc2_hsotg_start_req:
0x00000000fb0ca000 => 0x00000b14
[ 1260.277707] dwc2 fe980000.usb: ep0 state:0
[ 1260.277711] dwc2 fe980000.usb: dwc2_hsotg_start_req: DxEPCTL=0x80028000
[ 1260.277718] dwc2 fe980000.usb: dwc2_hsotg_start_req: DXEPCTL=0x80028000
[ 1260.277806] dwc2 fe980000.usb: dwc2_hsotg_irq: 040c8028 000c0000
(d0bc3cc4) retry 8
[ 1260.277813] dwc2 fe980000.usb: dwc2_hsotg_irq: daint=00010001
[ 1260.277818] dwc2 fe980000.usb: dwc2_hsotg_epint: ep0(out)
DxEPINT=0x00000008
[ 1260.277823] dwc2 fe980000.usb: dwc2_hsotg_epint: Setup/Timeout
[ 1260.277831] dwc2 fe980000.usb: complete: ep 0000000018e5b31a ep0, req
00000000432c9718, 0 => 000000002d523fc0
[ 1260.277839] dwc2 fe980000.usb: ctrl Type=a1, Req=01, V=0100, I=0700,
L=0004
[ 1260.277846] g_audio gadget: ac_rq_in(): 1
[ 1260.277850] g_audio gadget: in_rq_cur(): 96000
[ 1260.277857] dwc2 fe980000.usb: ep0: req 00000000cf0a7502:
4@...000000e574c90, noi=0, zero=0, snok=0
[ 1260.277865] dwc2 fe980000.usb: dwc2_hsotg_start_req:
DxEPCTL=0x00028000, ep 0, dir in
[ 1260.277870] dwc2 fe980000.usb: ureq->length:4 ureq->actual:0
[ 1260.277886] dwc2 fe980000.usb: ep0 state:1
[ 1260.277913] dwc2 fe980000.usb: req->length:4 req->actual:4 req->zero:0
[ 1260.277944] dwc2 fe980000.usb: zlp packet received
[ 1260.277948] dwc2 fe980000.usb: complete: ep 0000000018e5b31a ep0, req
00000000cf0a7502, 0 => 0000000023e79ed8
[ 1260.277984] dwc2 fe980000.usb: ureq->length:8 ureq->actual:0
[ 1260.278078] dwc2 fe980000.usb: dwc2_hsotg_epint: ep0(out)
DxEPINT=0x00000018
[ 1260.278104] dwc2 fe980000.usb: ep0: req 00000000cf0a7502:
4@...000000e574c90, noi=0, zero=0, snok=0
[ 1260.278128] dwc2 fe980000.usb: dwc2_hsotg_start_req:
0x00000000fb0cb800 => 0x00000b14
[ 1260.278163] dwc2 fe980000.usb: dwc2_hsotg_epint: XferCompl:
DxEPCTL=0x00028000, DXEPTSIZ=00000000
[ 1260.278182] g_audio gadget: Calling uac2_cs_control_sam_freq 2.
[ 1260.278186] g_audio gadget: uac2_cs_control_sam_freq val: 96000.
[ 1260.278190] g_audio gadget: Calling uac2_cs_control_sam_freq OUT.

> 
> 3. You assume that issue seen in below printk's (lines##39923-39927):

Maybe this part later in the dmesg dump is switching back to the default
96000 after playback stops, I am sorry for my lack of USB protocol
knowledge.

But lines starting at #2319 correspond to the SETUP packet with 192000
value.
> 
> [ 1261.789640] g_audio gadget: Calling uac2_cs_control_sam_freq 1.
> [ 1261.789652] g_audio gadget: Calling uac2_cs_control_sam_freq 2.
> [ 1261.789655] g_audio gadget: uac2_cs_control_sam_freq val: 96000.
> [ 1261.789659] g_audio gadget: Calling uac2_cs_control_sam_freq OUT.
> [ 1261.789665] Calling u_audio_set_capture_srate with srate 96000
> 
> Instead both 96000 should be 192000? Could you please provide me 
> messages sequence for correct behaviour for 192000.

I am afraid I do not know how to do that. The host sends 192000 but the
gadget function receives 96000. When stopping playback and starting at
96000, again 96000 is received. When going back to 192000, again 96000
is received.

> 
> 4. Below dmesg fragment not corresponds to observed issue, it's just for 
> show added printk's in g_audio. Correct?

It's the same sequence I listed in point 1 of this message. It shows the
observed issue.

My wireshark packet was captured in an earlier run, therefore some
possible packet IDs (if any exist) would not fit with the dump. But it
is the same observed situation - the packet carries 192000, yet f_uac2
->u_audio receive 96000.

I pushed my current source code with all the rebased patches to
https://github.com/pavhofman/linux-rpi/tree/fb5afcec549a998cafe9e0d11534400f508d8be3
for reference.

The function receiving incorrect value is
https://github.com/pavhofman/linux-rpi/blob/fb5afcec549a998cafe9e0d11534400f508d8be3/drivers/usb/gadget/function/f_uac2.c#L1476
, registered in req->complete callback in
https://github.com/pavhofman/linux-rpi/blob/fb5afcec549a998cafe9e0d11534400f508d8be3/drivers/usb/gadget/function/f_uac2.c#L1573

Thanks a lot!

Pavel.

> 
> Thanks,
> Minas
> 
> 
>> The value sent 00ee0200 corresponds to 192000, but the gadget received
>> the original 96000 (I added some printks to g_audio):
>>
>> ==========
>> [ 1260.277857] dwc2 fe980000.usb: ep0: req 00000000cf0a7502:
>> 4@...000000e574c90, noi=0, zero=0, snok=0
>> [ 1260.277865] dwc2 fe980000.usb: dwc2_hsotg_start_req:
>> DxEPCTL=0x00028000, ep 0, dir in
>> [ 1260.277870] dwc2 fe980000.usb: ureq->length:4 ureq->actual:0
>> [ 1260.277886] dwc2 fe980000.usb: ep0 state:1
>> [ 1260.277913] dwc2 fe980000.usb: req->length:4 req->actual:4 req->zero:0
>> [ 1260.277944] dwc2 fe980000.usb: zlp packet received
>> [ 1260.277948] dwc2 fe980000.usb: complete: ep 0000000018e5b31a ep0, req
>> 00000000cf0a7502, 0 => 0000000023e79ed8
>> [ 1260.277984] dwc2 fe980000.usb: ureq->length:8 ureq->actual:0
>> [ 1260.278078] dwc2 fe980000.usb: dwc2_hsotg_epint: ep0(out)
>> DxEPINT=0x00000018
>> [ 1260.278104] dwc2 fe980000.usb: ep0: req 00000000cf0a7502:
>> 4@...000000e574c90, noi=0, zero=0, snok=0
>> [ 1260.278128] dwc2 fe980000.usb: dwc2_hsotg_start_req:
>> 0x00000000fb0cb800 => 0x00000b14
>> [ 1260.278163] dwc2 fe980000.usb: dwc2_hsotg_epint: XferCompl:
>> DxEPCTL=0x00028000, DXEPTSIZ=00000000
>> [ 1260.278182] g_audio gadget: Calling uac2_cs_control_sam_freq 2.
>> [ 1260.278186] g_audio gadget: uac2_cs_control_sam_freq val: 96000.
>> ============
>>

View attachment "regdump" of type "text/plain" (7526 bytes)

Powered by blists - more mailing lists