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

[Ran Wang]

Hi Bin,

On Friday, November 13, 2020 2:25 PM Bin Meng wrote:
> 
> 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:0x00000000fbb47
> > > > 140-
> > > > --------
> > > > -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:0x00000000fbb47
> > > > 150-
> > > > --------
> > > > -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:0x00000000fbb4957
> > ++++++++++++0
> > xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb49570
> > --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb
> > 49570
> > 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:0x00000000fbb4918
> > ++++++++++++0
> > xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb49180
> > --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb
> > 49180
> > 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:0x00000000fbb4919
> > ++++++++++++0----------------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:0x00000000fbb491a
> > ++++++++++++0----------------2nd transfer TRB queued
> > xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb491a0
> > --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb
> > 491a0---------------------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:0x00000000fbb4979
> > ++++++++++++0
> > xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb49790
> > --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb
> > 49790
> > 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:0x00000000fbb492a
> > ++++++++++++0----------------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:0x00000000fbb492b
> > ++++++++++++0----------------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:0x00000000fbb492c
> > ++++++++++++0----------------3rd transfer TRB queued
> > xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492c0
> > --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb
> > 492c0---------------------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:0x00000000fbb492d
> > ++++++++++++0
> > xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492d0
> > xhci_bulk_tx()#set
> > TRB_ISP---------------------------------------------------------------
> > ------------------------Set ISP
> >
> ++++++++++++xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb492e
> > ++++++++++++0
> > xhci_bulk_tx()#0.last_transfer_trb_addr:0x00000000fbb492e0
> > --------------xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb
> > 492e0
> > 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.

Got it, will work out v2, thanks for the review.

Regards,
Ran

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