linux-usb.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP + DATA OUT transaction
@ 2021-01-31 23:44 Ruslan Bilovol
  2021-02-11 11:21 ` Minas Harutyunyan
  0 siblings, 1 reply; 4+ messages in thread
From: Ruslan Bilovol @ 2021-01-31 23:44 UTC (permalink / raw)
  To: Minas Harutyunyan, Linux USB; +Cc: linux-kernel

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.

However, when I disable DMA for DWC2 controller (see the patch below)
it starts to work as expected and correctly copies data transferred from
the host in the DATA OUT stage, to the usb_request->buf buffer.

So far I tested it on v5.9 kernel and v5.10.10 stable kernel both have
the same issue.

This issue is easily reproducible with RNDIS gadget which also
uses ep0 SETUP + DATA OUT transactions for transferring
RNDIS control messages.

During enumeration of RNDIS gadget attached to Linux host,
I see next messages for RPi4 DWC2 with DMA enabled:

| ## RPi4 DWC2 DMA
| [   91.029881] rndis_msg_parser: unknown RNDIS message 0x0052033A len 4456526
| [   91.029889] RNDIS command error -524, 24/24

In this case rndis_msg_parser can't parse messages from the host
because they are sent through SETUP + DATA OUT transaction and
DWC2 didn't copy that messages to the buffer, so buffer contains
some garbage from previous transactions which can't be parsed.

In case of BBB black or DWC2 with disabled DMA, it looks like:

| ## BBB black
| [   32.867751] rndis_msg_parser: RNDIS_MSG_INIT

| ## RPi4 DWC2 no DMA
| [  151.080724] rndis_msg_parser: RNDIS_MSG_INIT

I also did a quick googling and found that same issue was
recently reported for Raspberry pi OS:
https://github.com/raspberrypi/Raspberry-Pi-OS-64bit/issues/127

I spent some time on debugging this issue, but without having
DWC2 documentation and experience with DWC2 internals
that's all that I found so far.

Is this a known issue? Anybody debugging it? Any ideas?

Thanks,
Ruslan

-------------------------------------8<----------------------------------------
From ced7a3631d9800d04bcbcd756dac4583459fe48c Mon Sep 17 00:00:00 2001
From: Ruslan Bilovol <ruslan.bilovol@gmail.com>
Date: Wed, 20 Jan 2021 00:27:52 +0200
Subject: [PATCH] usb: dwc2: workaround: disable DMA for gadget

On Raspberry PI 4 it was observer that in case of control
transfers with DATA phase from a host, the driver for some
reason doesn't copy transferred data to the buffer, leaving
previous data in it.

With disabled DMA the issue isn't reproducible, thus
temporarily disable it

Signed-off-by: Ruslan Bilovol <ruslan.bilovol@gmail.com>
---
 drivers/usb/dwc2/params.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/drivers/usb/dwc2/params.c b/drivers/usb/dwc2/params.c
index 267543c..46c18af 100644
--- a/drivers/usb/dwc2/params.c
+++ b/drivers/usb/dwc2/params.c
@@ -357,7 +357,11 @@ static void dwc2_set_default_params(struct
dwc2_hsotg *hsotg)
 {
  struct dwc2_hw_params *hw = &hsotg->hw_params;
  struct dwc2_core_params *p = &hsotg->params;
+#if 0
  bool dma_capable = !(hw->arch == GHWCFG2_SLAVE_ONLY_ARCH);
+#else
+ bool dma_capable = 0;
+#endif

  dwc2_set_param_otg_cap(hsotg);
  dwc2_set_param_phy_type(hsotg);
@@ -651,7 +655,11 @@ static void dwc2_check_params(struct dwc2_hsotg *hsotg)
 {
  struct dwc2_hw_params *hw = &hsotg->hw_params;
  struct dwc2_core_params *p = &hsotg->params;
+#if 0
  bool dma_capable = !(hw->arch == GHWCFG2_SLAVE_ONLY_ARCH);
+#else
+ bool dma_capable = 0;
+#endif

  dwc2_check_param_otg_cap(hsotg);
  dwc2_check_param_phy_type(hsotg);
-- 
1.9.1

^ permalink raw reply related	[flat|nested] 4+ messages in thread

* Re: RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP + DATA OUT transaction
  2021-01-31 23:44 RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP + DATA OUT transaction Ruslan Bilovol
@ 2021-02-11 11:21 ` Minas Harutyunyan
       [not found]   ` <f0379d74-82fd-949f-f151-6b2a0d7b51ff@ivitera.com>
  0 siblings, 1 reply; 4+ messages in thread
From: Minas Harutyunyan @ 2021-02-11 11:21 UTC (permalink / raw)
  To: Ruslan Bilovol, Linux USB; +Cc: linux-kernel

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.

Thanks,
Minas

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP + DATA OUT transaction
       [not found]   ` <f0379d74-82fd-949f-f151-6b2a0d7b51ff@ivitera.com>
@ 2021-04-19 16:30     ` Minas Harutyunyan
  2021-04-20  8:19       ` Pavel Hofman
  0 siblings, 1 reply; 4+ messages in thread
From: Minas Harutyunyan @ 2021-04-19 16:30 UTC (permalink / raw)
  To: Pavel Hofman, Minas Harutyunyan, Ruslan Bilovol, Linux USB; +Cc: linux-kernel

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      <------------------------------
> ===============
> 
> 

Some clarifications required:
1. gadget works in scatter/gather DMA mode (g_dma_desc is true)?
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?

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

[ 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.

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

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@000000000e574c90, 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@000000000e574c90, 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.
> ============
> 
> Please find attached the whole dmesg from modprobing the gadget modules
> through playback of 192000.
> 
> Please let me know if you need any more logs/tests. Thank you very much
> for your help.
> 
> Best regards,
> 
> Pavel.
> 
> 
> 


^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP + DATA OUT transaction
  2021-04-19 16:30     ` Minas Harutyunyan
@ 2021-04-20  8:19       ` Pavel Hofman
  0 siblings, 0 replies; 4+ messages in thread
From: Pavel Hofman @ 2021-04-20  8:19 UTC (permalink / raw)
  To: Minas Harutyunyan, Ruslan Bilovol, Linux USB; +Cc: linux-kernel

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


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@000000000e574c90, 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@000000000e574c90, 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@000000000e574c90, 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@000000000e574c90, 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.
>> ============
>>

[-- Attachment #2: regdump --]
[-- Type: text/plain, Size: 7526 bytes --]

GOTGCTL = 0x000d0000
GOTGINT = 0x00000000
GAHBCFG = 0x00000031
GUSBCFG = 0x00001400
GRSTCTL = 0x800001c0
GINTSTS = 0x0400802a
GINTMSK = 0xd0bc3c44
GRXSTSR = 0x6311a7d3
GRXFSIZ = 0x0000022e
GNPTXFSIZ = 0x0020022e
GNPTXSTS = 0x00080020
GI2CCTL = 0x00000000
GPVNDCTL = 0x00000000
GGPIO = 0x00000000
GUID = 0x2708a000
GSNPSID = 0x4f54280a
GHWCFG1 = 0x00000000
GHWCFG2 = 0x228ddd50
GHWCFG3 = 0x0ff000e8
GHWCFG4 = 0x1ff00020
GLPMCFG = 0x75736230
GPWRDN = 0x00000000
GDFIFOCFG = 0x00000000
ADPCTL = 0x00000000
HPTXFSIZ = 0x01000d4e
DPTXFSIZN(1) = 0x0200024e
DPTXFSIZN(2) = 0x0200044e
DPTXFSIZN(3) = 0x0200064e
DPTXFSIZN(4) = 0x0200084e
DPTXFSIZN(5) = 0x02000a4e
DPTXFSIZN(6) = 0x01000c4e
DPTXFSIZN(7) = 0x01000d4e
DPTXFSIZN(8) = 0x01000d4e
DPTXFSIZN(9) = 0x0200024e
DPTXFSIZN(10) = 0x0200044e
DPTXFSIZN(11) = 0x0200064e
DPTXFSIZN(12) = 0x0200084e
DPTXFSIZN(13) = 0x02000a4e
DPTXFSIZN(14) = 0x01000c4e
DPTXFSIZN(15) = 0x01000d4e
DCFG = 0x00040020
DCTL = 0x00000000
DSTS = 0x0001bf02
DIEPMSK = 0x0000200f
DOEPMSK = 0x0000000f
DAINT = 0x00000000
DAINTMSK = 0x00010003
DTKNQR1 = 0x00000000
DTKNQR2 = 0x00000000
DTKNQR3 = 0x0c100020
DTKNQR4 = 0x00000000
DVBUSDIS = 0x000017d7
DVBUSPULSE = 0x000005b8
DIEPCTL(0) = 0x00008000
DIEPCTL(1) = 0x018c8006
DIEPCTL(2) = 0x01c60003
DIEPCTL(3) = 0x004603ff
DIEPCTL(4) = 0x000003ff
DIEPCTL(5) = 0x000003ff
DIEPCTL(6) = 0x000003ff
DIEPCTL(7) = 0x000003ff
DIEPCTL(8) = 0x000003ff
DIEPCTL(9) = 0x000003ff
DIEPCTL(10) = 0x000003ff
DIEPCTL(11) = 0x000003ff
DIEPCTL(12) = 0x000003ff
DIEPCTL(13) = 0x000003ff
DIEPCTL(14) = 0x000003ff
DIEPCTL(15) = 0x000003ff
DOEPCTL(0) = 0x80028000
DOEPCTL(1) = 0x000703ff
DOEPCTL(2) = 0x000003ff
DOEPCTL(3) = 0x000003ff
DOEPCTL(4) = 0x000003ff
DOEPCTL(5) = 0x000003ff
DOEPCTL(6) = 0x000003ff
DOEPCTL(7) = 0x000003ff
DOEPCTL(8) = 0x000003ff
DOEPCTL(9) = 0x000003ff
DOEPCTL(10) = 0x000003ff
DOEPCTL(11) = 0x000003ff
DOEPCTL(12) = 0x000003ff
DOEPCTL(13) = 0x000003ff
DOEPCTL(14) = 0x000003ff
DOEPCTL(15) = 0x000003ff
DIEPINT(0) = 0x000000d0
DIEPINT(1) = 0x00000010
DIEPINT(2) = 0x00000000
DIEPINT(3) = 0x00000080
DIEPINT(4) = 0x00000080
DIEPINT(5) = 0x00000080
DIEPINT(6) = 0x00000080
DIEPINT(7) = 0x00000080
DIEPINT(8) = 0x00000080
DIEPINT(9) = 0x00000080
DIEPINT(10) = 0x00000080
DIEPINT(11) = 0x00000080
DIEPINT(12) = 0x00000080
DIEPINT(13) = 0x00000080
DIEPINT(14) = 0x00000080
DIEPINT(15) = 0x00000080
DOEPINT(0) = 0x00002000
DOEPINT(1) = 0x00000000
DOEPINT(2) = 0x00000000
DOEPINT(3) = 0x00000000
DOEPINT(4) = 0x00000000
DOEPINT(5) = 0x00000000
DOEPINT(6) = 0x00000000
DOEPINT(7) = 0x00000000
DOEPINT(8) = 0x00000000
DOEPINT(9) = 0x00000000
DOEPINT(10) = 0x00000000
DOEPINT(11) = 0x00000000
DOEPINT(12) = 0x00000000
DOEPINT(13) = 0x00000000
DOEPINT(14) = 0x00000000
DOEPINT(15) = 0x00000000
DIEPTSIZ(0) = 0x00000000
DIEPTSIZ(1) = 0x00000000
DIEPTSIZ(2) = 0x20080000
DIEPTSIZ(3) = 0x00000000
DIEPTSIZ(4) = 0x00000000
DIEPTSIZ(5) = 0x00000000
DIEPTSIZ(6) = 0x00000000
DIEPTSIZ(7) = 0x00000000
DIEPTSIZ(8) = 0x00000000
DIEPTSIZ(9) = 0x00000000
DIEPTSIZ(10) = 0x00000000
DIEPTSIZ(11) = 0x00000000
DIEPTSIZ(12) = 0x00000000
DIEPTSIZ(13) = 0x00000000
DIEPTSIZ(14) = 0x00000000
DIEPTSIZ(15) = 0x00000000
DOEPTSIZ(0) = 0x00080008
DOEPTSIZ(1) = 0x000803ff
DOEPTSIZ(2) = 0x00000000
DOEPTSIZ(3) = 0x00000000
DOEPTSIZ(4) = 0x00000000
DOEPTSIZ(5) = 0x00000000
DOEPTSIZ(6) = 0x00000000
DOEPTSIZ(7) = 0x00000000
DOEPTSIZ(8) = 0x00000000
DOEPTSIZ(9) = 0x00000000
DOEPTSIZ(10) = 0x00000000
DOEPTSIZ(11) = 0x00000000
DOEPTSIZ(12) = 0x00000000
DOEPTSIZ(13) = 0x00000000
DOEPTSIZ(14) = 0x00000000
DOEPTSIZ(15) = 0x00000000
DIEPDMA(0) = 0xfb227804
DIEPDMA(1) = 0xcf8a0285
DIEPDMA(2) = 0xf85ce804
DIEPDMA(3) = 0x6231e1a9
DIEPDMA(4) = 0x58ab6e94
DIEPDMA(5) = 0xed702e1d
DIEPDMA(6) = 0xdbc16a94
DIEPDMA(7) = 0x2ee9992c
DIEPDMA(8) = 0x25688211
DIEPDMA(9) = 0x25688211
DIEPDMA(10) = 0x25688211
DIEPDMA(11) = 0x25688211
DIEPDMA(12) = 0x25688211
DIEPDMA(13) = 0x25688211
DIEPDMA(14) = 0x25688211
DIEPDMA(15) = 0x25688211
DOEPDMA(0) = 0xf85cf000
DOEPDMA(1) = 0xf85c6000
DOEPDMA(2) = 0xe66c1f8c
DOEPDMA(3) = 0x0a264345
DOEPDMA(4) = 0x6fee07bd
DOEPDMA(5) = 0x7215380f
DOEPDMA(6) = 0x6311a7d3
DOEPDMA(7) = 0x25688211
DOEPDMA(8) = 0x00000000
DOEPDMA(9) = 0x00000000
DOEPDMA(10) = 0x00000000
DOEPDMA(11) = 0x00000000
DOEPDMA(12) = 0x00000000
DOEPDMA(13) = 0x00000000
DOEPDMA(14) = 0x00000000
DOEPDMA(15) = 0x00000000
DTXFSTS(0) = 0x00000020
DTXFSTS(1) = 0x00000100
DTXFSTS(2) = 0x00000100
DTXFSTS(3) = 0x00000200
DTXFSTS(4) = 0x00000020
DTXFSTS(5) = 0x00000020
DTXFSTS(6) = 0x00000020
DTXFSTS(7) = 0x00000020
DTXFSTS(8) = 0x00000020
DTXFSTS(9) = 0x00000020
DTXFSTS(10) = 0x00000020
DTXFSTS(11) = 0x00000020
DTXFSTS(12) = 0x00000020
DTXFSTS(13) = 0x00000020
DTXFSTS(14) = 0x00000020
DTXFSTS(15) = 0x00000020
PCGCTL = 0x00000000
HCFG = 0x00040020
HFIR = 0x000017d7
HFNUM = 0x6d5401bf
HPTXSTS = 0x00080200
HAINT = 0x00000000
HAINTMSK = 0x00000003
HFLBADDR = 0x00000000
HPRT0 = 0x00000400
HCCHAR(0) = 0x018c8006
HCCHAR(1) = 0x000703ff
HCCHAR(2) = 0x000003ff
HCCHAR(3) = 0x000003ff
HCCHAR(4) = 0x000003ff
HCCHAR(5) = 0x000003ff
HCCHAR(6) = 0x000003ff
HCCHAR(7) = 0x000003ff
HCCHAR(8) = 0x000003ff
HCCHAR(9) = 0x000003ff
HCCHAR(10) = 0x000003ff
HCCHAR(11) = 0x000003ff
HCCHAR(12) = 0x000003ff
HCCHAR(13) = 0x000003ff
HCCHAR(14) = 0x000003ff
HCCHAR(15) = 0x000003ff
HCSPLT(0) = 0x00000000
HCSPLT(1) = 0x00000000
HCSPLT(2) = 0x00000000
HCSPLT(3) = 0x00000000
HCSPLT(4) = 0x00000000
HCSPLT(5) = 0x00000000
HCSPLT(6) = 0x00000000
HCSPLT(7) = 0x00000000
HCSPLT(8) = 0x00000000
HCSPLT(9) = 0x00000000
HCSPLT(10) = 0x00000000
HCSPLT(11) = 0x00000000
HCSPLT(12) = 0x00000000
HCSPLT(13) = 0x00000000
HCSPLT(14) = 0x00000000
HCSPLT(15) = 0x00000000
HCINT(0) = 0x00000010
HCINT(1) = 0x00000000
HCINT(2) = 0x00000000
HCINT(3) = 0x00000000
HCINT(4) = 0x00000000
HCINT(5) = 0x00000000
HCINT(6) = 0x00000000
HCINT(7) = 0x00000000
HCINT(8) = 0x00000000
HCINT(9) = 0x00000000
HCINT(10) = 0x00000000
HCINT(11) = 0x00000000
HCINT(12) = 0x00000000
HCINT(13) = 0x00000000
HCINT(14) = 0x00000000
HCINT(15) = 0x00000000
HCINTMSK(0) = 0x0000000f
HCINTMSK(1) = 0x00000000
HCINTMSK(2) = 0x00000000
HCINTMSK(3) = 0x00000000
HCINTMSK(4) = 0x00000000
HCINTMSK(5) = 0x00000000
HCINTMSK(6) = 0x00000000
HCINTMSK(7) = 0x00000000
HCINTMSK(8) = 0x00000000
HCINTMSK(9) = 0x00000000
HCINTMSK(10) = 0x00000000
HCINTMSK(11) = 0x00000000
HCINTMSK(12) = 0x00000000
HCINTMSK(13) = 0x00000000
HCINTMSK(14) = 0x00000000
HCINTMSK(15) = 0x00000000
HCTSIZ(0) = 0x00000000
HCTSIZ(1) = 0x000803ff
HCTSIZ(2) = 0x00000000
HCTSIZ(3) = 0x00000000
HCTSIZ(4) = 0x00000000
HCTSIZ(5) = 0x00000000
HCTSIZ(6) = 0x00000000
HCTSIZ(7) = 0x00000000
HCTSIZ(8) = 0x00000000
HCTSIZ(9) = 0x00000000
HCTSIZ(10) = 0x00000000
HCTSIZ(11) = 0x00000000
HCTSIZ(12) = 0x00000000
HCTSIZ(13) = 0x00000000
HCTSIZ(14) = 0x00000000
HCTSIZ(15) = 0x00000000
HCDMA(0) = 0xf85cf000
HCDMA(1) = 0xf85c6000
HCDMA(2) = 0xe66c1f8c
HCDMA(3) = 0x0a264345
HCDMA(4) = 0x6fee07bd
HCDMA(5) = 0x7215380f
HCDMA(6) = 0x6311a7d3
HCDMA(7) = 0x25688211
HCDMA(8) = 0x00000000
HCDMA(9) = 0x00000000
HCDMA(10) = 0x00000000
HCDMA(11) = 0x00000000
HCDMA(12) = 0x00000000
HCDMA(13) = 0x00000000
HCDMA(14) = 0x00000000
HCDMA(15) = 0x00000000
HCDMAB(0) = 0x00000000
HCDMAB(1) = 0xf85cf000
HCDMAB(2) = 0xf85c6000
HCDMAB(3) = 0xe66c1f8c
HCDMAB(4) = 0x0a264345
HCDMAB(5) = 0x6fee07bd
HCDMAB(6) = 0x7215380f
HCDMAB(7) = 0x6311a7d3
HCDMAB(8) = 0x25688211
HCDMAB(9) = 0x00000000
HCDMAB(10) = 0x00000000
HCDMAB(11) = 0x00000000
HCDMAB(12) = 0x00000000
HCDMAB(13) = 0x00000000
HCDMAB(14) = 0x00000000
HCDMAB(15) = 0x00000000

^ permalink raw reply	[flat|nested] 4+ messages in thread

end of thread, other threads:[~2021-04-20  8:19 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-01-31 23:44 RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP + DATA OUT transaction Ruslan Bilovol
2021-02-11 11:21 ` Minas Harutyunyan
     [not found]   ` <f0379d74-82fd-949f-f151-6b2a0d7b51ff@ivitera.com>
2021-04-19 16:30     ` Minas Harutyunyan
2021-04-20  8:19       ` Pavel Hofman

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).