Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Fri, 18 Feb 2022 13:44:44 +0900
From:   Jung Daehwan <dh10.jung@samsung.com>
To:     Thinh Nguyen <Thinh.Nguyen@synopsys.com>
Cc:     Felipe Balbi <balbi@kernel.org>,
        Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        "linux-usb@vger.kernel.org" <linux-usb@vger.kernel.org>,
        open list <linux-kernel@vger.kernel.org>,
        "quic_wcheng@quicinc.com" <quic_wcheng@quicinc.com>,
        "quic_jackp@quicinc.com" <quic_jackp@quicinc.com>
Subject: Re: [PATCH v2 1/2] usb: dwc3: Not set DWC3_EP_END_TRANSFER_PENDING
 in ep cmd fails
Message-ID: <20220218044444.GA48532@ubuntu>
MIME-Version: 1.0
In-Reply-To: <63c8c9d1-9b07-a9f2-3639-a38641e19a7a@synopsys.com>
User-Agent: Mutt/1.5.24 (2015-08-30)
Content-Type: multipart/mixed;
        boundary="----.rW42XXn7_Ji6OxwuAF4RAMbP.qed.OeqKlvEhSLhB3noATS=_1086b7_"
CMS-TYPE: 102P
DLP-Filter: Pass
References: <1644836933-141376-1-git-send-email-dh10.jung@samsung.com>
        <CGME20220214111149epcas2p1a1faeda037991885fd6f2f026fa44ec5@epcas2p1.samsung.com>
        <1644836933-141376-2-git-send-email-dh10.jung@samsung.com>
        <ff604504-00df-0c1b-673e-892e42737f7a@synopsys.com>
        <20220215063925.GC144890@ubuntu>
        <63c8c9d1-9b07-a9f2-3639-a38641e19a7a@synopsys.com>
Precedence: bulk

------.rW42XXn7_Ji6OxwuAF4RAMbP.qed.OeqKlvEhSLhB3noATS=_1086b7_
Content-Type: text/plain; charset="us-ascii"
Content-Disposition: inline

On Tue, Feb 15, 2022 at 05:14:50PM +0000, Thinh Nguyen wrote:
> Jung Daehwan wrote:
> > Hi Thinh,
> > 
> > On Mon, Feb 14, 2022 at 06:44:33PM +0000, Thinh Nguyen wrote:
> >> Hi,
> >>
> >> Daehwan Jung wrote:
> >>> It always sets DWC3_EP_END_TRANSFER_PENDING in dwc3_stop_active_transfer
> >>> even if dwc3_send_gadget_ep_cmd fails. It can cause some problems like
> >>
> >> How does it fail? Timed out?
> > 
> > Yes, timed out.
> >>
> >>> skipping clear stall commmand or giveback from dequeue. We fix to set it
> >>> only when ep cmd success. Additionally, We clear DWC3_EP_TRANSFER_STARTED
> >>> for next trb to start transfer not update transfer.
> >>
> >> We shouldn't do this. Things will be out of sync. It may work for 1
> >> scenario, but it won't work for others.
> >>
> >> Please help me understand a few things:
> >>
> >> 1) What is the scenario that triggers this? Is it random?
> >>
> > ep cmd timeout occurs on dequeue request from user side. End Transfer command
> > would be sent in dwc3_stop_active transfer.
> 
> At the high level, what's triggering the request dequeue? Is it from a
> disconnect, change of interface, or simply function driver protocol that
> changes it.
> 
> What application was used to trigger this?
> 
Removing function driver requests dequeue.
> > 
> >> 2) Are there other traffics pending while issuing the End Transfer
> >> command? If so, what transfer type(s)?
> >>
> > I haven't checked it yet. 
> 
> Can you check?
> 
It seems there's no pending traffic.
> > 
> >> 3) Have you tried increasing the timeout?
> >>
> > No, I haven't.
> 
> Can you try up to 10 seconds (just for experiment)
> 
Yes, it's reproduced on 10 secs.
> >> BR,
> >> Thinh
> >>
> > 
> > This issue occurs very rarely on customer. I only have restricted
> > information. That's why I've been trying to reproduce it.
> 
> How did you test your fix if you can't reproduce it?
> 

I sent patches to my client and he said this issue would not occur after
applying them. In fact, They are not totally equal with those we are
discussing. I've refactor-ed and pushed them here.

> > 
> > Wesley may have run into same issue and you can see this issue in detail.
> > https://protect2.fireeye.com/v1/url?k=39bd3e50-66260725-39bcb51f-0cc47a31ce4e-bf000d5a697ead66&q=1&e=b04500ad-43d0-4ee7-b5f0-a7283d8fc0da&u=https%3A%2F%2Furldefense.com%2Fv3%2F__https%3A%2F%2Fprotect2.fireeye.com%2Fv1%2Furl%3Fk%3D9d423b69-fc3fd32e-9d43b026-74fe485fff30-77a099b52659410d%26q%3D1%26e%3D20b4d9f5-2599-4f57-8b6a-7c4ec167d228%26u%3Dhttps%2A3A%2A2F%2A2Flore.kernel.org%2A2Flinux-usb%2A2F20220203080017.27339-1-quic_wcheng%2A40quicinc.com%2A2F__%3BJSUlJSUlJQ%21%21A4F2R9G_pg%21JWPzNLoO3BFX_IZCVzmHPtxq6frr_VFbSNNaxSQylunt1Y4EauTOefth2LCIcVEuTx8E%24 
> > 
> 
> I can take a look, but please provide the tracepoints of the failure if
> you can reproduce it.
> 

Thanks to client's help, I could reproduce it in my envrionment.

1. Trace

MtpServer-2484    [003] d..2   114.376829: dwc3_ep_queue: ep1out: req 0000000055561867 length 0/512 zsI ==> -115
MtpServer-2484    [003] d..2   114.376838: dwc3_prepare_trb: ep1out: trb 0000000074078a95 (E23:D22) buf 0000000954845600 size 512 ctrl 0000001d (HlCS:sc:normal)
MtpServer-2484    [003] d..2   114.376844: dwc3_prepare_trb: ep1out: trb 0000000095f503e7 (E24:D22) buf 00000000e1303000 size 512 ctrl 00000819 (HlcS:sC:normal)
MtpServer-2484    [003] d..2   114.376867: dwc3_gadget_ep_cmd: ep1out: cmd 'Update Transfer' [20007] params 00000000 00000000 00000000 --> status: Successful
ksoftirqd/2-23      [002] d.s2   190.428752: dwc3_ep_dequeue: ep2out: req 00000000732c0f69 length 0/16384 zsI ==> -115
ksoftirqd/2-23      [002] dns3   190.447625: dwc3_gadget_ep_cmd: ep2out: cmd 'End Transfer' [40d08] params 00000000 00000000 00000000 --> status: Timed Out
ksoftirqd/2-23      [002] dns2   190.450596: dwc3_ep_dequeue: ep2out: req 00000000be3434d4 length 0/16384 zsI ==> -115
ksoftirqd/2-23      [002] dns2   190.450618: dwc3_ep_dequeue: ep2out: req 0000000033655f2e length 0/16384 zsI ==> -115
ksoftirqd/2-23      [002] dns2   190.450625: dwc3_ep_dequeue: ep2out: req 00000000dc0ff635 length 0/16384 zsI ==> -115
ksoftirqd/2-23      [002] dns2   190.450633: dwc3_ep_dequeue: ep2out: req 0000000023ffb8e8 length 0/16384 zsI ==> -115
ksoftirqd/2-23      [002] dns2   190.450641: dwc3_ep_dequeue: ep2out: req 000000005fab61aa length 0/16384 zsI ==> -115
ksoftirqd/2-23      [002] dns2   190.450648: dwc3_ep_dequeue: ep2out: req 000000001f618cd8 length 0/16384 zsI ==> -115
ksoftirqd/2-23      [002] dns2   190.450654: dwc3_ep_dequeue: ep2out: req 00000000da0ea1b1 length 0/16384 zsI ==> -115
##### CPU 6 buffer started ####
HwBinder:636_1-658     [006] d..1   190.735324: dwc3_gadget_ep_disable: ep0out: mps 512/512 streams 0 burst 1 ring 0/0 flags e:swbp:>
HwBinder:636_1-658     [006] d..1   190.735327: dwc3_gadget_ep_disable: ep0in: mps 512/512 streams 0 burst 1 ring 0/0 flags e:swbp:<
HwBinder:636_1-658     [003] dn.1   214.206652: dwc3_gadget_ep_disable: ep0out: mps 512/512 streams 0 burst 1 ring 0/0 flags e:swbp:>
HwBinder:636_1-658     [003] dn.1   214.206677: dwc3_gadget_ep_disable: ep0in: mps 512/512 streams 0 burst 1 ring 0/0 flags e:swbp:<

2. Kernel log

[  190.447711]I[2:    ksoftirqd/2:   23] ------------[ cut here ]------------
[  190.447777]I[2:    ksoftirqd/2:   23] WARNING: CPU: 2 PID: 23 at drivers/usb/dwc3/gadget.c:3632 dwc3_gadget_ep_dequeue+0x228/0x234
[  190.449587]I[2:    ksoftirqd/2:   23] pc : dwc3_gadget_ep_dequeue+0x228/0x234
[  190.449610]I[2:    ksoftirqd/2:   23] lr : dwc3_gadget_ep_dequeue+0x124/0x234
[  190.449629]I[2:    ksoftirqd/2:   23] sp : ffffffc01294bad0
[  190.449647]I[2:    ksoftirqd/2:   23] x29: ffffffc01294baf0 x28: 0000000000000000 
[  190.449679]I[2:    ksoftirqd/2:   23] x27: ffffffc0121e4000 x26: ffffff88208c9dc0 
[  190.449711]I[2:    ksoftirqd/2:   23] x25: ffffff893dd5c570 x24: ffffff893dd22080 
[  190.449742]I[2:    ksoftirqd/2:   23] x23: ffffff88a4f8a168 x22: ffffff88a4f8a100 
[  190.449773]I[2:    ksoftirqd/2:   23] x21: ffffff893dd5c500 x20: 0000000000000080 
[  190.449803]I[2:    ksoftirqd/2:   23] x19: ffffff893dd22238 x18: ffffffc01291d068 
[  190.449834]I[2:    ksoftirqd/2:   23] x17: 0000000000004000 x16: ffffff88bb0cc000 
[  190.449864]I[2:    ksoftirqd/2:   23] x15: 0000000000000200 x14: ffffff88208d4d00 
[  190.449895]I[2:    ksoftirqd/2:   23] x13: ffffff88208d4d00 x12: 00000000000001b5 
[  190.449926]I[2:    ksoftirqd/2:   23] x11: ffffff88208c9dc0 x10: 0000000100000103 
[  190.449958]I[2:    ksoftirqd/2:   23] x9 : ffffff88208c9dc0 x8 : 0000000000000008 
[  190.449989]I[2:    ksoftirqd/2:   23] x7 : fefefefefefefefe x6 : 0000000000008080 
[  190.450020]I[2:    ksoftirqd/2:   23] x5 : 0000000000000000 x4 : 0000000000000103 
[  190.450050]I[2:    ksoftirqd/2:   23] x3 : 0000000000000080 x2 : ffffff88208ac900 
[  190.450081]I[2:    ksoftirqd/2:   23] x1 : ffffff88208ac900 x0 : 00000000ffffff92 
[  190.450120]I[2:    ksoftirqd/2:   23] Call trace:
[  190.450153]I[2:    ksoftirqd/2:   23]  dwc3_gadget_ep_dequeue+0x228/0x234
[  190.450187]I[2:    ksoftirqd/2:   23]  usb_ep_dequeue+0x4c/0xa0
[  190.450219]I[2:    ksoftirqd/2:   23]  ffs_aio_cancel+0x4c/0x84
[  190.450247]I[2:    ksoftirqd/2:   23]  free_ioctx_users+0x80/0x110
[  190.450281]I[2:    ksoftirqd/2:   23]  percpu_ref_put_many+0xf0/0x164
[  190.450310]I[2:    ksoftirqd/2:   23]  percpu_ref_switch_to_atomic_rcu+0x13c/0x1dc
[  190.450339]I[2:    ksoftirqd/2:   23]  rcu_do_batch+0x208/0x5b4
[  190.450360]I[2:    ksoftirqd/2:   23]  rcu_core+0x22c/0x43c
[  190.450384]I[2:    ksoftirqd/2:   23]  rcu_core_si+0x14/0x24
[  190.450409]I[2:    ksoftirqd/2:   23]  efi_header_end+0x134/0x350
[  190.450437]I[2:    ksoftirqd/2:   23]  run_ksoftirqd+0x34/0x74

The point is there would be some requests pending without giveback-ed.
They're from removing function driver(ffs_aio_cancel). It could cause
the function driver would wait for dequeue requests completed.

Best Regards,
Jung Daehwan

> Thanks,
> Thinh

------.rW42XXn7_Ji6OxwuAF4RAMbP.qed.OeqKlvEhSLhB3noATS=_1086b7_
Content-Type: text/plain; charset="utf-8"


------.rW42XXn7_Ji6OxwuAF4RAMbP.qed.OeqKlvEhSLhB3noATS=_1086b7_--