dwc2 gadget rejecting new AIO transfer when bus is suspended

dwc2 gadget rejecting new AIO transfer when bus is suspended

[Vincent Pelletier]

Hello,

I am writing a functionfs-based gadget, using the raspberry pi zero.
Depending on the time my userland process takes between the moment the
UDC is bound to the gadget and the moment it submits AIO transfers, it
either works as expected or results in immediate transfer completion
with status -11 (-EAGAIN).

Enabling dynamic debug, I see the
  dev_dbg(hs->dev, "%s: submit request only in active state\n",
line being output when this issue occurs (see log extract at the end of
this email - note the 4 seconds gap between GINTSTS_ErlySusp - whatever
that means - and io happening and being rejected).

While I am sure there are hardware-dependent reasons to reject these
transfers, and while I can shift processing around to reduce this
delay and (apparently) reliably avoid this error, I think it is making
using this UDC rather hard: if my understanding is correct, this is a
race between userland and the bus. If the HCI suspends the bus first, I
cannot even submit buffers to be ready to receive some future OUT
transfer, but if the userland submits these buffers before suspension
then they are accepted - even if they get filled hours later.
In my case, the IN transfer is on an interrupt endpoint, so I also
think it would make more sense for the UDC to accept it: then, data is
ready for whenever the host wakes the bus and polls for interrupt
transfers.

Being a very occasional kernel contributor, have no immediate idea on
how both sides could be conciliated, so this is more a "I noticed that
it could be more convenient if..." than a proper bug report.

Checking the dwc3 I do not identify such EAGAIN in its io submission
code, and I did not (yet ?) trigger such error on my Intel Edison.

Dec 24 12:29:19 sushi kernel: [218828.497937] dwc2 20980000.usb: ep0 state:1
Dec 24 12:29:19 sushi kernel: [218828.497948] dwc2 20980000.usb: dwc2_hsotg_start_req: DxEPCTL=0x84028000
Dec 24 12:29:19 sushi kernel: [218828.497959] dwc2 20980000.usb: dwc2_hsotg_start_req: DXEPCTL=0x80008000
Dec 24 12:29:19 sushi kernel: [218828.497984] dwc2 20980000.usb: dwc2_hsotg_irq: 04048028 00040000 (d0bc3cc4) retry 8
Dec 24 12:29:19 sushi kernel: [218828.497996] dwc2 20980000.usb: dwc2_hsotg_irq: daint=00000001
Dec 24 12:29:19 sushi kernel: [218828.498008] dwc2 20980000.usb: dwc2_hsotg_epint: ep0(in) DxEPINT=0x00000001
Dec 24 12:29:19 sushi kernel: [218828.498022] dwc2 20980000.usb: dwc2_hsotg_epint: XferCompl: DxEPCTL=0x00008000, DXEPTSIZ=00000000
Dec 24 12:29:19 sushi kernel: [218828.498034] dwc2 20980000.usb: dwc2_hsotg_complete_in: adjusting size done 0 => 36
Dec 24 12:29:19 sushi kernel: [218828.498046] dwc2 20980000.usb: req->length:36 req->actual:36 req->zero:1
Dec 24 12:29:19 sushi kernel: [218828.498056] dwc2 20980000.usb: Receiving zero-length packet on ep0
Dec 24 12:29:19 sushi kernel: [218828.498078] dwc2 20980000.usb: dwc2_hsotg_irq: 04088028 00080000 (d0bc3cc4) retry 8
Dec 24 12:29:19 sushi kernel: [218828.498089] dwc2 20980000.usb: dwc2_hsotg_irq: daint=00010000
Dec 24 12:29:19 sushi kernel: [218828.498101] dwc2 20980000.usb: dwc2_hsotg_epint: ep0(out) DxEPINT=0x00000001
Dec 24 12:29:19 sushi kernel: [218828.498113] dwc2 20980000.usb: dwc2_hsotg_epint: XferCompl: DxEPCTL=0x00028000, DXEPTSIZ=20000000
Dec 24 12:29:19 sushi kernel: [218828.498122] dwc2 20980000.usb: zlp packet received
Dec 24 12:29:19 sushi kernel: [218828.498138] dwc2 20980000.usb: complete: ep 42dd5aad ep0, req 29f392ab, 0 => 5c316413
Dec 24 12:29:19 sushi kernel: [218828.498152] dwc2 20980000.usb: dwc2_hsotg_enqueue_setup: queueing setup request
Dec 24 12:29:19 sushi kernel: [218828.498169] dwc2 20980000.usb: ep0: req 8e14c7b2: 8@d91bfc39, noi=0, zero=0, snok=0
Dec 24 12:29:19 sushi kernel: [218828.498186] dwc2 20980000.usb: dwc2_hsotg_start_req: DxEPCTL=0x00028000, ep 0, dir out
Dec 24 12:29:19 sushi kernel: [218828.498198] dwc2 20980000.usb: ureq->length:8 ureq->actual:0
Dec 24 12:29:19 sushi kernel: [218828.498212] dwc2 20980000.usb: dwc2_hsotg_start_req: 1@8/8, 0x00080008 => 0x00000b10
Dec 24 12:29:19 sushi kernel: [218828.498225] dwc2 20980000.usb: dwc2_hsotg_start_req: 0x54ab8a20 => 0x00000b14
Dec 24 12:29:19 sushi kernel: [218828.498235] dwc2 20980000.usb: ep0 state:0
Dec 24 12:29:19 sushi kernel: [218828.498245] dwc2 20980000.usb: dwc2_hsotg_start_req: DxEPCTL=0x80028000
Dec 24 12:29:19 sushi kernel: [218828.498256] dwc2 20980000.usb: dwc2_hsotg_start_req: DXEPCTL=0x80028000
Dec 24 12:29:22 sushi kernel: [218830.967016] dwc2 20980000.usb: dwc2_hsotg_irq: 04008428 00000400 (d0bc3cc4) retry 8
Dec 24 12:29:22 sushi kernel: [218830.967035] dwc2 20980000.usb: GINTSTS_ErlySusp
Dec 24 12:29:22 sushi kernel: [218830.970039] dwc2 20980000.usb: dwc2_hsotg_irq: 04008028 00000000 (d0bc3cc4) retry 8
Dec 24 12:29:25 sushi kernel: [218834.485152] dwc2 20980000.usb: ep1out: req 91851ac5: 10240@e55aa59c, noi=0, zero=0, snok=0
Dec 24 12:29:25 sushi kernel: [218834.485172] dwc2 20980000.usb: dwc2_hsotg_ep_queue: submit request only in active state
Dec 24 12:29:25 sushi kernel: [218834.485261] dwc2 20980000.usb: ep1out: req 91851ac5: 10240@e55aa59c, noi=0, zero=0, snok=0
Dec 24 12:29:25 sushi kernel: [218834.485273] dwc2 20980000.usb: dwc2_hsotg_ep_queue: submit request only in active state
Dec 24 12:29:25 sushi kernel: [218834.515516] dwc2 20980000.usb: ep2in: req 91851ac5: 2@8925e53a, noi=0, zero=0, snok=0
Dec 24 12:29:25 sushi kernel: [218834.515536] dwc2 20980000.usb: dwc2_hsotg_ep_queue: submit request only in active state
Dec 24 12:29:31 sushi kernel: [218840.337809] dwc2 20980000.usb: dwc2_hsotg_pullup: is_on: 0 op_state: 3
Dec 24 12:29:31 sushi kernel: [218840.337844] dwc2 20980000.usb: complete: ep 42dd5aad ep0, req 8e14c7b2, -108 => 97e9bd28
Dec 24 12:29:31 sushi kernel: [218840.337865] dwc2 20980000.usb: dwc2_hsotg_complete_setup: failed -108

Regards,
-- 
Vincent Pelletier

Re: dwc2 gadget rejecting new AIO transfer when bus is suspended

[Artur Petrosyan]

Hi Vincent,

On 12/24/2020 16:50, Vincent Pelletier wrote:
> Hello,
> 
> I am writing a functionfs-based gadget, using the raspberry pi zero.
> Depending on the time my userland process takes between the moment the
> UDC is bound to the gadget and the moment it submits AIO transfers, it
> either works as expected or results in immediate transfer completion
> with status -11 (-EAGAIN).
> 
> Enabling dynamic debug, I see the
>    dev_dbg(hs->dev, "%s: submit request only in active state\n",
> line being output when this issue occurs (see log extract at the end of
> this email - note the 4 seconds gap between GINTSTS_ErlySusp - whatever
> that means - and io happening and being rejected).

According your debug log core enters suspend on receiving an 
GINTSTS_ErlySusp interrupt. It means that the driver goes to L2 state 
(suspend). In suspend mode accepting and processing EP requests can lead 
to unexpected behavior. That is why the driver rejects EP request with 
-EAGAIN.

As core may use power saving modes which are initiated by the Suspend 
interrupt, then in any suspend mode whether it is hibernation or partial 
power down the core registers are not available. This is why we avoid to 
get new EP requests.

The main question is why on usb bus seen ErlySusp interrupt. Is it 
initiated by host? If yes, why?


> 
> While I am sure there are hardware-dependent reasons to reject these
> transfers, and while I can shift processing around to reduce this
> delay and (apparently) reliably avoid this error, I think it is making
> using this UDC rather hard: if my understanding is correct, this is a
> race between userland and the bus. If the HCI suspends the bus first, I
> cannot even submit buffers to be ready to receive some future OUT
> transfer, but if the userland submits these buffers before suspension
> then they are accepted - even if they get filled hours later.
> In my case, the IN transfer is on an interrupt endpoint, so I also
> think it would make more sense for the UDC to accept it: then, data is
> ready for whenever the host wakes the bus and polls for interrupt
> transfers.
> 
> Being a very occasional kernel contributor, have no immediate idea on
> how both sides could be conciliated, so this is more a "I noticed that
> it could be more convenient if..." than a proper bug report.
> 
> Checking the dwc3 I do not identify such EAGAIN in its io submission
> code, and I did not (yet ?) trigger such error on my Intel Edison.
> 
> Dec 24 12:29:19 sushi kernel: [218828.497937] dwc2 20980000.usb: ep0 state:1
> Dec 24 12:29:19 sushi kernel: [218828.497948] dwc2 20980000.usb: dwc2_hsotg_start_req: DxEPCTL=0x84028000
> Dec 24 12:29:19 sushi kernel: [218828.497959] dwc2 20980000.usb: dwc2_hsotg_start_req: DXEPCTL=0x80008000
> Dec 24 12:29:19 sushi kernel: [218828.497984] dwc2 20980000.usb: dwc2_hsotg_irq: 04048028 00040000 (d0bc3cc4) retry 8
> Dec 24 12:29:19 sushi kernel: [218828.497996] dwc2 20980000.usb: dwc2_hsotg_irq: daint=00000001
> Dec 24 12:29:19 sushi kernel: [218828.498008] dwc2 20980000.usb: dwc2_hsotg_epint: ep0(in) DxEPINT=0x00000001
> Dec 24 12:29:19 sushi kernel: [218828.498022] dwc2 20980000.usb: dwc2_hsotg_epint: XferCompl: DxEPCTL=0x00008000, DXEPTSIZ=00000000
> Dec 24 12:29:19 sushi kernel: [218828.498034] dwc2 20980000.usb: dwc2_hsotg_complete_in: adjusting size done 0 => 36
> Dec 24 12:29:19 sushi kernel: [218828.498046] dwc2 20980000.usb: req->length:36 req->actual:36 req->zero:1
> Dec 24 12:29:19 sushi kernel: [218828.498056] dwc2 20980000.usb: Receiving zero-length packet on ep0
> Dec 24 12:29:19 sushi kernel: [218828.498078] dwc2 20980000.usb: dwc2_hsotg_irq: 04088028 00080000 (d0bc3cc4) retry 8
> Dec 24 12:29:19 sushi kernel: [218828.498089] dwc2 20980000.usb: dwc2_hsotg_irq: daint=00010000
> Dec 24 12:29:19 sushi kernel: [218828.498101] dwc2 20980000.usb: dwc2_hsotg_epint: ep0(out) DxEPINT=0x00000001
> Dec 24 12:29:19 sushi kernel: [218828.498113] dwc2 20980000.usb: dwc2_hsotg_epint: XferCompl: DxEPCTL=0x00028000, DXEPTSIZ=20000000
> Dec 24 12:29:19 sushi kernel: [218828.498122] dwc2 20980000.usb: zlp packet received
> Dec 24 12:29:19 sushi kernel: [218828.498138] dwc2 20980000.usb: complete: ep 42dd5aad ep0, req 29f392ab, 0 => 5c316413
> Dec 24 12:29:19 sushi kernel: [218828.498152] dwc2 20980000.usb: dwc2_hsotg_enqueue_setup: queueing setup request
> Dec 24 12:29:19 sushi kernel: [218828.498169] dwc2 20980000.usb: ep0: req 8e14c7b2: 8@d91bfc39, noi=0, zero=0, snok=0
> Dec 24 12:29:19 sushi kernel: [218828.498186] dwc2 20980000.usb: dwc2_hsotg_start_req: DxEPCTL=0x00028000, ep 0, dir out
> Dec 24 12:29:19 sushi kernel: [218828.498198] dwc2 20980000.usb: ureq->length:8 ureq->actual:0
> Dec 24 12:29:19 sushi kernel: [218828.498212] dwc2 20980000.usb: dwc2_hsotg_start_req: 1@8/8, 0x00080008 => 0x00000b10
> Dec 24 12:29:19 sushi kernel: [218828.498225] dwc2 20980000.usb: dwc2_hsotg_start_req: 0x54ab8a20 => 0x00000b14
> Dec 24 12:29:19 sushi kernel: [218828.498235] dwc2 20980000.usb: ep0 state:0
> Dec 24 12:29:19 sushi kernel: [218828.498245] dwc2 20980000.usb: dwc2_hsotg_start_req: DxEPCTL=0x80028000
> Dec 24 12:29:19 sushi kernel: [218828.498256] dwc2 20980000.usb: dwc2_hsotg_start_req: DXEPCTL=0x80028000
> Dec 24 12:29:22 sushi kernel: [218830.967016] dwc2 20980000.usb: dwc2_hsotg_irq: 04008428 00000400 (d0bc3cc4) retry 8
> Dec 24 12:29:22 sushi kernel: [218830.967035] dwc2 20980000.usb: GINTSTS_ErlySusp
> Dec 24 12:29:22 sushi kernel: [218830.970039] dwc2 20980000.usb: dwc2_hsotg_irq: 04008028 00000000 (d0bc3cc4) retry 8
> Dec 24 12:29:25 sushi kernel: [218834.485152] dwc2 20980000.usb: ep1out: req 91851ac5: 10240@e55aa59c, noi=0, zero=0, snok=0
> Dec 24 12:29:25 sushi kernel: [218834.485172] dwc2 20980000.usb: dwc2_hsotg_ep_queue: submit request only in active state
> Dec 24 12:29:25 sushi kernel: [218834.485261] dwc2 20980000.usb: ep1out: req 91851ac5: 10240@e55aa59c, noi=0, zero=0, snok=0
> Dec 24 12:29:25 sushi kernel: [218834.485273] dwc2 20980000.usb: dwc2_hsotg_ep_queue: submit request only in active state
> Dec 24 12:29:25 sushi kernel: [218834.515516] dwc2 20980000.usb: ep2in: req 91851ac5: 2@8925e53a, noi=0, zero=0, snok=0
> Dec 24 12:29:25 sushi kernel: [218834.515536] dwc2 20980000.usb: dwc2_hsotg_ep_queue: submit request only in active state
> Dec 24 12:29:31 sushi kernel: [218840.337809] dwc2 20980000.usb: dwc2_hsotg_pullup: is_on: 0 op_state: 3
> Dec 24 12:29:31 sushi kernel: [218840.337844] dwc2 20980000.usb: complete: ep 42dd5aad ep0, req 8e14c7b2, -108 => 97e9bd28
> Dec 24 12:29:31 sushi kernel: [218840.337865] dwc2 20980000.usb: dwc2_hsotg_complete_setup: failed -108
> 
> Regards,
> 

Regards,
Artur

Re: dwc2 gadget rejecting new AIO transfer when bus is suspended

[Vincent Pelletier]

Hello Artur,

On Fri, 25 Dec 2020 10:56:02 +0000, Artur Petrosyan <Arthur.Petrosyan@synopsys.com> wrote:
> According your debug log core enters suspend on receiving an 
> GINTSTS_ErlySusp interrupt. It means that the driver goes to L2 state 
> (suspend). In suspend mode accepting and processing EP requests can lead 
> to unexpected behavior. That is why the driver rejects EP request with 
> -EAGAIN.
> 
> As core may use power saving modes which are initiated by the Suspend 
> interrupt, then in any suspend mode whether it is hibernation or partial 
> power down the core registers are not available. This is why we avoid to 
> get new EP requests.

This is my understanding from reading the commit history, yes.

But from userland's point of view this causes a weird situation:
- sequence 1:
  - userland submits buffer (ex: to receive the next host request)
  - UDC is suspended
  - UDC is awoken by host initiating a transfer
  Result: the AIO completes successfully, the suspension was completely
  invisible to userland, and I'm happy.
- sequence 2:
  - UDC is suspended
  - userland submits buffer (ex: to receive the next host request)
  Result: the AIO completes with an error, the suspension got in the
  way, and I'm confused about what I need to make my code do to
  recover: should I change my IO completion codepath so that it
  resubmits any EAGAIN completion, hoping to catch the UDC at a time it
  is awoken so the AIO finally sticks and everything can sleep until an
  actual transfer completion ?

I do not know if it makes sense from a kernel point of view, but would
it be possible for the dwc2 module to sit on the AIO requests while the
controller is suspended, and submit them when it wakes up rather than
failing them immediately and sending them back to userland ?
I expect that this code actually knows (without polling) when the
controller is awoken.

> The main question is why on usb bus seen ErlySusp interrupt. Is it 
> initiated by host? If yes, why?

My pre-USB-analyser guess is it would just be the normal USB-idle-to-
bus-suspend behaviour. Besides device enumeration, the host is not
accessing the device right after it is plugged in, so there should be
no reason to keep the bus ticking.

Unless there is something fundamentally wrong with the suspension
happening at all, my biggest issue is the poor userland-level usability
*if* suspension happens, and the race-condition this behaviour creates
(IO cannot be submitted before the UDC is bound to the gadget, and IO
cannot be submitted after either if it happens after an external event,
leaving only a short time window where it works).

If I am missing anything there which would allow userland to guarantee
keeping the UDC awoken so the transfers would stay in-queue, please do
tell me.

Regards,
-- 
Vincent Pelletier

Re: dwc2 gadget rejecting new AIO transfer when bus is suspended

[Alan Stern]

On Sat, Dec 26, 2020 at 12:46:27AM +0000, Vincent Pelletier wrote:
> Hello Artur,
> 
> On Fri, 25 Dec 2020 10:56:02 +0000, Artur Petrosyan <Arthur.Petrosyan@synopsys.com> wrote:
> > According your debug log core enters suspend on receiving an 
> > GINTSTS_ErlySusp interrupt. It means that the driver goes to L2 state 
> > (suspend). In suspend mode accepting and processing EP requests can lead 
> > to unexpected behavior. That is why the driver rejects EP request with 
> > -EAGAIN.
> > 
> > As core may use power saving modes which are initiated by the Suspend 
> > interrupt, then in any suspend mode whether it is hibernation or partial 
> > power down the core registers are not available. This is why we avoid to 
> > get new EP requests.

This seems like a design mistake.  Even though the controller may be in 
a low-power state, there's no reason the UDC driver can't accept new 
requests or unlink old ones.  It even ought to be willing to halt 
endpoints.

None of these actions require the driver to touch the hardware.  The 
hardware-specific parts of the actions can be carried out when the 
controller returns to full power.

> This is my understanding from reading the commit history, yes.
> 
> But from userland's point of view this causes a weird situation:
> - sequence 1:
>   - userland submits buffer (ex: to receive the next host request)
>   - UDC is suspended
>   - UDC is awoken by host initiating a transfer
>   Result: the AIO completes successfully, the suspension was completely
>   invisible to userland, and I'm happy.
> - sequence 2:
>   - UDC is suspended
>   - userland submits buffer (ex: to receive the next host request)
>   Result: the AIO completes with an error, the suspension got in the
>   way, and I'm confused about what I need to make my code do to
>   recover: should I change my IO completion codepath so that it
>   resubmits any EAGAIN completion, hoping to catch the UDC at a time it
>   is awoken so the AIO finally sticks and everything can sleep until an
>   actual transfer completion ?

Indeed, the same problem will occur with synchronous (non-AIO) 
submissions.

> I do not know if it makes sense from a kernel point of view, but would
> it be possible for the dwc2 module to sit on the AIO requests while the
> controller is suspended, and submit them when it wakes up rather than
> failing them immediately and sending them back to userland ?
> I expect that this code actually knows (without polling) when the
> controller is awoken.

The kernel shouldn't have to sit on anything.  The requests should be 
accepted immediately.

Alan Stern

Re: dwc2 gadget rejecting new AIO transfer when bus is suspended

[Vincent Pelletier]

Hello Alan,

On Sat, 26 Dec 2020 11:52:30 -0500, Alan Stern <stern@rowland.harvard.edu> wrote:
> The kernel shouldn't have to sit on anything.  The requests should be 
> accepted immediately.

I must have used this sentence incorrectly: I meant what you described,
the kernel accepting the transfer and the module submitting it to
hardware whenever able.

Also, strictly speaking (and to avoid confusion if I failed further at
English expression in my previous emails) aio_submit itself does
succeed, so in a sense the kernel already accepts the transfer. The
issue is that the transfer completion happens immediately after, with
this EAGAIN status.

Regards,
-- 
Vincent Pelletier

Re: dwc2 gadget rejecting new AIO transfer when bus is suspended

[Artur Petrosyan]

Hi Vincent,

On 12/27/2020 05:49, Vincent Pelletier wrote:
> Hello Alan,
> 
> On Sat, 26 Dec 2020 11:52:30 -0500, Alan Stern <stern@rowland.harvard.edu> wrote:
>> The kernel shouldn't have to sit on anything.  The requests should be
>> accepted immediately.
> 
> I must have used this sentence incorrectly: I meant what you described,
> the kernel accepting the transfer and the module submitting it to
> hardware whenever able.
> 
> Also, strictly speaking (and to avoid confusion if I failed further at
> English expression in my previous emails) aio_submit itself does
> succeed, so in a sense the kernel already accepts the transfer. The
> issue is that the transfer completion happens immediately after, with
> this EAGAIN status.

Refactoring the driver to always accept any EP request independent of 
the state (suspend), requires lot of investigation. We will decide and 
implement later.

For your case we suggest the following workaround in 
"dwc2_hsotg_ep_queue()" function to additionally check "hsotg->power_down":

/* Prevent new request submission when controller is suspended */
if (hs->lx_state != DWC2_L0 && hsotg->power_down) {
	dev_dbg(hs->dev, "%s: submit request only in active state\n",
		__func__);
	return -EAGAIN;
}

Please test and let us know the results.

> 
> Regards,
> 

Re: dwc2 gadget rejecting new AIO transfer when bus is suspended

[Vincent Pelletier]

Hello Artur,

On Tue, 29 Dec 2020 07:29:27 +0000, Artur Petrosyan <Arthur.Petrosyan@synopsys.com> wrote:
> Refactoring the driver to always accept any EP request independent of 
> the state (suspend), requires lot of investigation. We will decide and 
> implement later.
> 
> For your case we suggest the following workaround in 
> "dwc2_hsotg_ep_queue()" function to additionally check "hsotg->power_down":

I did test your change (with a trivial adaptation, see below) on
5.11.0-rc1 and I can confirm the AIO submission is accepted in my
use-case, despite a 4-seconds sleep between UDC being bound and AIO
submission to try to trigger the issue (which it does on an unpatched
5.10).

The gadget goes on to correctly respond to the host, so this looks good
to me.

diff --git a/drivers/usb/dwc2/gadget.c b/drivers/usb/dwc2/gadget.c
index 0a0d11151cfb8..dc676f3b1d799 100644
--- a/drivers/usb/dwc2/gadget.c
+++ b/drivers/usb/dwc2/gadget.c
@@ -1387,7 +1387,7 @@ static int dwc2_hsotg_ep_queue(struct usb_ep *ep, struct usb_request *req,
 		req->zero, req->short_not_ok);
 
 	/* Prevent new request submission when controller is suspended */
-	if (hs->lx_state != DWC2_L0) {
+	if (hs->lx_state != DWC2_L0 && hs->params.power_down) {
 		dev_dbg(hs->dev, "%s: submit request only in active state\n",
 			__func__);
 		return -EAGAIN;

Regards,
-- 
Vincent Pelletier