Received-SPF: pass (google.com: domain of linux-kernel+bounces-135863-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:40f1:3f00::1 as permitted sender) client-ip=2604:1380:40f1:3f00::1;
Date: Mon, 8 Apr 2024 21:05:41 +0200
From: =?UTF-8?B?TWljaGHFgg==?= Pecio <michal.pecio@gmail.com>
To: Mathias Nyman <mathias.nyman@linux.intel.com>
Cc: Paul Menzel <pmenzel@molgen.mpg.de>, Mathias Nyman
 <mathias.nyman@intel.com>, LKML <linux-kernel@vger.kernel.org>,
 linux-usb@vger.kernel.org
Subject: Re: xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not
 part of current TD ep_index 1 comp_code 1
Message-ID: <20240408210541.771253ff@foxbook>
In-Reply-To: <1f64af9a-0618-a7da-4acc-f043b6580308@linux.intel.com>
References: <58bca6f2-797a-4e20-a476-2294309afdd5@molgen.mpg.de>
	<20240405113247.743e34b2@foxbook>
	<7090d3af-18ce-40e1-8ac2-bf18152e5c4a@molgen.mpg.de>
	<20240406183659.3daf4fa0@foxbook>
	<c57f2116-8c42-44fb-9c32-6115ad88f914@molgen.mpg.de>
	<20240407142542.036fb02f@foxbook>
	<1f64af9a-0618-a7da-4acc-f043b6580308@linux.intel.com>
Precedence: bulk
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit

> It's also possible this TD/TRB was cancelled due to the disconnect.
> Could be that even if driver removes the TD from the list and cleans
> out the TRB from the ring buffer (turns TRB to no-op) hardware may
> have read ahead and cached the TRB, and process it anyway.

I thought about it, but my debug patch says that the missing TD was
freed by finish_td(), which is called on TDs considered completed by
hardware. A cancelled TD would show giveback_invalidated_tds().


Anyway, we now have new information from the reporter. My v2 patch
keeps a log of the last five events processed on each transfer ring
and dumps the log on TRB mismatch errors.

Unfortunately, it looks like the host controller is broken and signals
completion of those transfers twice. The log below shows two distinct
events for TRB 32959a1c0 and that the coresponding TD has just been
freed by finish_td().

[33819.676314] usb 1-2: USB disconnect, device number 7
[33819.676331] usb 1-2: unregistering device
[33819.676347] usb 1-2: unregistering interface 1-2:1.0
[33819.677861] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 1 comp_code 1
[33819.677886] xhci_hcd 0000:00:14.0: Looking for event-dma 000000032959a1c0 trb-start 000000032959a1d0 trb-end 000000032959a1d0 seg-start 000000032959a000 seg-end 000000032959aff0
[33819.677902] xhci_hcd 0000:00:14.0: last xhci_td_cleanup: first_dma 32959a1c0 last_dma 32959a1c0 status -115 from finish_td
[33819.677915] xhci_hcd 0000:00:14.0: handle_tx_event log -4: event ffff9e19c38eb1f0 ep_trb_dma 32959a190 comp_code 1 len 0 slot 6 ep 1
[33819.677925] xhci_hcd 0000:00:14.0: handle_tx_event log -3: event ffff9e19c38eb200 ep_trb_dma 32959a1a0 comp_code 1 len 0 slot 6 ep 1
[33819.677934] xhci_hcd 0000:00:14.0: handle_tx_event log -2: event ffff9e19c38eb220 ep_trb_dma 32959a1b0 comp_code 1 len 0 slot 6 ep 1
[33819.677941] xhci_hcd 0000:00:14.0: handle_tx_event log -1: event ffff9e19c38eb230 ep_trb_dma 32959a1c0 comp_code 1 len 0 slot 6 ep 1
[33819.677949] xhci_hcd 0000:00:14.0: handle_tx_event log  0: event ffff9e19c38eb260 ep_trb_dma 32959a1c0 comp_code 1 len 0 slot 6 ep 1

At this point we have set the "interesting" flag on this transfer ring,
so the handling of the next event is logged. We observe TD 32959a1d0
completing normally here.

[33819.677965] xhci_hcd 0000:00:14.0: handle_tx_event event ffff9e19c38eb270 ep_trb_dma 32959a1d0 comp_code 1 len 0 slot 6 ep 1
[33819.677979] xhci_hcd 0000:00:14.0: handle_tx_event event ffff9e19c38eb270 first_trb 32959a1d0 last_trb 32959a1d0 ep_seg 32959a000
[33819.677993] xhci_hcd 0000:00:14.0: process_isoc_td event ffff9e19c38eb270 requested 192 ep_trb_len 192 remaining 0
[33819.678004] xhci_hcd 0000:00:14.0: finish_td td_status -115 comp_code 1 frame_status 0 frame_actual_length 192

And then we get a TRB mismatch error on this same TD.
The dumped log shows duplicate events once again.

[33819.678022] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 1 comp_code 1
[33819.678034] xhci_hcd 0000:00:14.0: Looking for event-dma 000000032959a1d0 trb-start 000000032959a1e0 trb-end 000000032959a1e0 seg-start 000000032959a000 seg-end 000000032959aff0
[33819.678047] xhci_hcd 0000:00:14.0: last xhci_td_cleanup: first_dma 32959a1d0 last_dma 32959a1d0 status -115 from finish_td
[33819.678058] xhci_hcd 0000:00:14.0: handle_tx_event log -4: event ffff9e19c38eb220 ep_trb_dma 32959a1b0 comp_code 1 len 0 slot 6 ep 1
[33819.678066] xhci_hcd 0000:00:14.0: handle_tx_event log -3: event ffff9e19c38eb230 ep_trb_dma 32959a1c0 comp_code 1 len 0 slot 6 ep 1
[33819.678074] xhci_hcd 0000:00:14.0: handle_tx_event log -2: event ffff9e19c38eb260 ep_trb_dma 32959a1c0 comp_code 1 len 0 slot 6 ep 1
[33819.678082] xhci_hcd 0000:00:14.0: handle_tx_event log -1: event ffff9e19c38eb270 ep_trb_dma 32959a1d0 comp_code 1 len 0 slot 6 ep 1
[33819.678089] xhci_hcd 0000:00:14.0: handle_tx_event log  0: event ffff9e19c38eb280 ep_trb_dma 32959a1d0 comp_code 1 len 0 slot 6 ep 1

Regards,
Michal