[PATCH] usb: xhci: fix event trb handling missed

[Bin Meng]

Hi Ran,

On Wed, Nov 11, 2020 at 4:07 PM Ran Wang <ran.wang_1 at nxp.com> wrote:
>
> Hi Bin
>
> On Tuesday, November 10, 2020 5:55 PM, Ran Wang wrote:
> >
> > Hi Bin,
> >
>
> <snip>
>
> > > > record_transfer_result():comp_code: 1 csw org 00000000fbb4ec90,
> > > > adjusted to 00000000fbb4fffe
> > > > record_transfer_result():comp_code: 1
> > > > record_transfer_result():comp_code: 1
> > > > record_transfer_result():comp_code: 1 csw org 00000000fbb4ec90,
> > > > adjusted to 00000000fbb4fffe
> > > > record_transfer_result():comp_code: 1
> > > > record_transfer_result():comp_code: 1
> > > > record_transfer_result():comp_code: 1 csw org 00000000fbb4ec90,
> > > > adjusted to 00000000fbb4fffe
> > > > record_transfer_result():comp_code: 1
> > > > record_transfer_result():comp_code: 1
> > > > record_transfer_result():comp_code: 1
> > >
> > > In the earlier log you sent, you have the following:
> > >
> > > dev=00000000fbb4f3c0, pipe=c0010283, buffer=00000000fbb4fd80,
> > > length=2048----------------------------buffer would cross 64KB
> > > boundary, so we will send request in more than 1 TRB, this is the key
> > > issue trigger condition
> > > xhci_bulk_tx()#0.1.running_total:0x280
> > > xhci_bulk_tx()#0.2.trb_buff_len:0x280
> > > xhci_bulk_tx()#0.3.running_total:0x280
> > > xhci_bulk_tx()#0.4.num_trbs:0x2--------------------------2 Transfer
> > > TRB
> > > xhci_bulk_tx()#0.5.running_total:0x10280
> > > xhci_bulk_tx()#0.start_trb:0x00000000fbb47140
> > > ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47140-
> > > --------
> > > -Assemble
> > > 1st Transfer TRB
> > > xhci_bulk_tx()#0.addr:0xfbb4fd80
> > > xhci_bulk_tx()#0.trb_buff_len:0x280
> > > xhci_bulk_tx()#0.running_total:0x280
> > > xhci_bulk_tx()#0.length:0x800
> > > xhci_bulk_tx()#0.TRB_MAX_BUFF_SIZE:0x10000
> > > ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47150-
> > > --------
> > > -Assemble
> > > 2nd Transfer TRB
> > > xhci_bulk_tx()#0.addr:0xfbb50000
> > > xhci_bulk_tx()#0.trb_buff_len:0x580
> > > xhci_bulk_tx()#0.running_total:0x800
> > > xhci_bulk_tx()#0.length:0x800
> > > xhci_bulk_tx()#0.TRB_MAX_BUFF_SIZE:0x10000
> > >
> > > Could you please specify where this output is for?
> >
> > All this prints is within function xhci_bulk_tx(),
> >
> > Let me open those verbose output and check if that crossing 64KB case has been
> > triggered or not.
> > But I have to get back to you later (tomorrow).
>
> With your test commit and my verbose print code, issue cannot be reproduced in mass storage usage
> (although crossing 64KB boundary condition has met), so looks like the only different to ethernet device
> is that if xHC would receive short packet:
>

Thank you.

> => pri t
> t=usb read 0x82000000 0 300000
> => run t
>
> usb read: device 0 block # 0, count 3145728 ...
> usb_stor_BBB_transport()csw org 00000000fbb4ac90, adjusted to 00000000fbb4fffe
> xhci_bulk_tx()dev=00000000fbb49950, pipe=c0010203, buffer=00000000fbb1a9c0, length=0x1f
> xhci_bulk_tx()#0.4.num_trbs:0x1
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb49570
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb49570
> --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb49570
> xhci_bulk_tx()#0.event->complete_code:1
> xhci_bulk_tx()#3.ep_index:0x3
> xhci_bulk_tx()dev=00000000fbb49950, pipe=c0008283, buffer=00000000fbb1ab00, length=0x200
> xhci_bulk_tx()#0.4.num_trbs:0x1
> xhci_bulk_tx()#set TRB_ISP------------------------------------
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb49180
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb49180
> --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb49180
> xhci_bulk_tx()#0.event->complete_code:1
> xhci_bulk_tx()#3.ep_index:0x2
> xhci_bulk_tx()dev=00000000fbb49950, pipe=c0008283, buffer=00000000fbb4fffe, length=0xd-----------------buffer cross 64KB boundary
> xhci_bulk_tx()#0.4.num_trbs:0x2
> xhci_bulk_tx()#set TRB_ISP---------------------------------------------------------------------------------------Set ISP
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb49190----------------1st transfer TRB queued
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb49190
> xhci_bulk_tx()#set TRB_ISP---------------------------------------------------------------------------------------Set ISP
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb491a0----------------2nd transfer TRB queued
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb491a0
> --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb491a0---------------------event TRB that pointing to 2nd transfer TRB
> xhci_bulk_tx()#0.event->complete_code:1-----------------------------------------------------------------not short packet
> xhci_bulk_tx()#3.ep_index:0x2
> num_trbs_count > 1!!!!!!!!!
> ...
> usb_stor_BBB_transport()csw org 00000000fbb4aea0, adjusted to 00000000fbb4fffe
> xhci_bulk_tx()dev=00000000fbb49950, pipe=c0010203, buffer=00000000fbb1ad00, length=0x1f
> xhci_bulk_tx()#0.4.num_trbs:0x1
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb49790
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb49790
> --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb49790
> xhci_bulk_tx()#0.event->complete_code:1
> xhci_bulk_tx()#3.ep_index:0x3
> xhci_bulk_tx()dev=00000000fbb49950, pipe=c0008283, buffer=00000000883d8000, length=0x1e000-----------------buffer cross 64KB boundary
> xhci_bulk_tx()#0.4.num_trbs:0x3
> xhci_bulk_tx()#set TRB_ISP---------------------------------------------------------------------------------------Set ISP
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb492a0----------------1st transfer TRB queued
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492a0
> xhci_bulk_tx()#set TRB_ISP---------------------------------------------------------------------------------------Set ISP
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb492b0----------------2nd transfer TRB queued
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492b0
> xhci_bulk_tx()#set TRB_ISP---------------------------------------------------------------------------------------Set ISP
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb492c0----------------3rd transfer TRB queued
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492c0
> --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb492c0---------------------event TRB that pointing to 3rd transfer TRB
> xhci_bulk_tx()#0.event->complete_code:1-----------------------------------------------------------------not short packet
> xhci_bulk_tx()#3.ep_index:0x2
> num_trbs_count > 1!!!!!!!!!
> xhci_bulk_tx()dev=00000000fbb49950, pipe=c0008283, buffer=00000000fbb4fffe, length=0xd
> xhci_bulk_tx()#0.4.num_trbs:0x2
> xhci_bulk_tx()#set TRB_ISP---------------------------------------------------------------------------------------Set ISP
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb492d0
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492d0
> xhci_bulk_tx()#set TRB_ISP---------------------------------------------------------------------------------------Set ISP
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb492e0
> xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492e0
> --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb492e0
> xhci_bulk_tx()#0.event->complete_code:1
> xhci_bulk_tx()#3.ep_index:0x2
> num_trbs_count > 1!!!!!!!!!

Please rebase this patch against u-boot/master, and reword the
following commit message to indicate that it was because of the ISP
flag set on an input pipe. In the 64K boundary case, when the first
TRB ends up with a short packet condition it will trigger an short
packet code transfer event per ISP flag, and current codes will only
handle the first transfer event.

> However, on Layerscape platforms (LS1028A, LS1088A, etc), we observe xhci
> controller will generated more than 1 event TRB sometimes, this cause that
> function mishandle event TRB in next round call, then system hang due to
> BUG() checking.

Regards,
Bin