All of lore.kernel.org
 help / color / mirror / Atom feed
* USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
@ 2021-01-22  8:06 Andreas Hartmann
  2021-01-22  8:09 ` Andreas Hartmann
  0 siblings, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-22  8:06 UTC (permalink / raw)
  To: linux-usb


Hello!

Since a new Notebook, which sadly only provides USB 3 interfaces, I have a more or 
less big problem with an old driver (rt5572sta), which not just sometimes produces 
those warn messages, but even stalls sometimes after those warn messages (e,g, 
Kernel 5.3.x or 5.10.x or 5.8.x) - see attached log file.

The driver uses the bulk method to communicate with the USB bus. By reducing the 
max. bulk size from 24 kByte to 12 kByte, I was able to massively reduce those 
warning messages and now, the USB bus even seldom stalls any more.

I achieved this by changing the building of the bulk package from

if (((ThisBulkSize&0xffff8000) != 0) || ((ThisBulkSize&0x6000) == 0x6000))

to

if (((ThisBulkSize&0xffff8000) != 0) || ((ThisBulkSize&0x3000) == 0x3000))


I can see this problem on two different AMD USB 3 controller, e.g. X370 Series 
Chipset USB 3.1 xHCI Controller [1022:43b9] (rev 02).

I'm wondering how to solve this problem? But mostly I'm wondering, why a USB 2 
device is handled by USB 3 code, expecting to follow USB 3 rules at all? Is it 
possible to bind the driver to the USB 2 code path?

At the moment I think, that the attempt to "transfer" a valid USB 2 package to a 
valid USB 3 package by xhci_hcd seems not always to be transparent to the driver 
producing and controlling its send packets. Could it be possible, that there are 
some situations, where the driver can't check the package after manipulation 
through xhci_hcd any more? Please see the attached log file.

Or how should I fix the driver to be USB 3 ready? Please take into account, that 
I'm not an USB protocol specialist and I don't know, at which level or how to 
build a valid bulk packet which confirms to USB3 rules.

At the time being, I'm debugging on base of the pretty loud debug messages of the 
rt5572sta driver and the xhci_hcd debug messages (echo "module xhci_hcd =pf" > 
/sys/kernel/debug/dynamic_debug/control)


Thanks for any idea how to proceed!
Andreas Hartmann

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-22  8:06 USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512 Andreas Hartmann
@ 2021-01-22  8:09 ` Andreas Hartmann
  2021-01-24 17:28   ` Andreas Hartmann
  0 siblings, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-22  8:09 UTC (permalink / raw)
  To: linux-usb

[-- Attachment #1: Type: text/plain, Size: 2207 bytes --]

Sorry, forgot to attach the log file ... .

Now, it's there.


Thanks
Andreas Hartmann



On 22.01.21 at 09:06 Andreas Hartmann wrote:
> 
> Hello!
> 
> Since a new Notebook, which sadly only provides USB 3 interfaces, I have a more or 
> less big problem with an old driver (rt5572sta), which not just sometimes produces 
> those warn messages, but even stalls sometimes after those warn messages (e,g, 
> Kernel 5.3.x or 5.10.x or 5.8.x) - see attached log file.
> 
> The driver uses the bulk method to communicate with the USB bus. By reducing the 
> max. bulk size from 24 kByte to 12 kByte, I was able to massively reduce those 
> warning messages and now, the USB bus even seldom stalls any more.
> 
> I achieved this by changing the building of the bulk package from
> 
> if (((ThisBulkSize&0xffff8000) != 0) || ((ThisBulkSize&0x6000) == 0x6000))
> 
> to
> 
> if (((ThisBulkSize&0xffff8000) != 0) || ((ThisBulkSize&0x3000) == 0x3000))
> 
> 
> I can see this problem on two different AMD USB 3 controller, e.g. X370 Series 
> Chipset USB 3.1 xHCI Controller [1022:43b9] (rev 02).
> 
> I'm wondering how to solve this problem? But mostly I'm wondering, why a USB 2 
> device is handled by USB 3 code, expecting to follow USB 3 rules at all? Is it 
> possible to bind the driver to the USB 2 code path?
> 
> At the moment I think, that the attempt to "transfer" a valid USB 2 package to a 
> valid USB 3 package by xhci_hcd seems not always to be transparent to the driver 
> producing and controlling its send packets. Could it be possible, that there are 
> some situations, where the driver can't check the package after manipulation 
> through xhci_hcd any more? Please see the attached log file.
> 
> Or how should I fix the driver to be USB 3 ready? Please take into account, that 
> I'm not an USB protocol specialist and I don't know, at which level or how to 
> build a valid bulk packet which confirms to USB3 rules.
> 
> At the time being, I'm debugging on base of the pretty loud debug messages of the 
> rt5572sta driver and the xhci_hcd debug messages (echo "module xhci_hcd =pf" > 
> /sys/kernel/debug/dynamic_debug/control)
> 
> 
> Thanks for any idea how to proceed!
> Andreas Hartmann


[-- Attachment #2: usb3-alignment_error.txt --]
[-- Type: text/plain, Size: 3198 bytes --]

2021-01-19T14:01:47.492316+01:00 localhost kernel: [26509.686972] xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
2021-01-19T14:01:48.947710+01:00 localhost kernel: [26511.142333] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:01:48.947737+01:00 localhost kernel: [26511.142356]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x2
2021-01-19T14:01:48.947739+01:00 localhost kernel: [26511.142361]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:01:54.303312+01:00 localhost kernel: [26516.498060] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:01:54.303333+01:00 localhost kernel: [26516.498078]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x3
2021-01-19T14:01:54.303335+01:00 localhost kernel: [26516.498083]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:01:59.676016+01:00 localhost kernel: [26521.870773] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:01:59.676044+01:00 localhost kernel: [26521.870800]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x4
2021-01-19T14:01:59.676046+01:00 localhost kernel: [26521.870815]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:02:04.999737+01:00 localhost kernel: [26527.194549] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:02:04.999762+01:00 localhost kernel: [26527.194573]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x5
2021-01-19T14:02:04.999764+01:00 localhost kernel: [26527.194577]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:02:10.439333+01:00 localhost kernel: [26532.634186] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:02:10.439355+01:00 localhost kernel: [26532.634202]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x6
2021-01-19T14:02:10.439357+01:00 localhost kernel: [26532.634207]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:02:15.788389+01:00 localhost kernel: [26537.983270] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:02:15.788413+01:00 localhost kernel: [26537.983292]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x7
2021-01-19T14:02:15.788414+01:00 localhost kernel: [26537.983297]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:02:21.231765+01:00 localhost kernel: [26543.426680] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:02:21.231788+01:00 localhost kernel: [26543.426701]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x8
2021-01-19T14:02:21.231790+01:00 localhost kernel: [26543.426706]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:02:26.527355+01:00 localhost kernel: [26548.722310] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:02:26.527377+01:00 localhost kernel: [26548.722327]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0x9
2021-01-19T14:02:26.527379+01:00 localhost kernel: [26548.722331]       >>BulkOut Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:02:31.999097+01:00 localhost kernel: [26554.194080] BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:02:31.999121+01:00 localhost kernel: [26554.194101]       >>BulkOut Req=0xc7f93, Complete=0xc7f92, Other=0xa
2021-01-19T14:02:31.999122+01:00 localhost kernel: [26554.194106]       >>BulkOut Header:10 6 0 44 d0 0 8f 80


^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-22  8:09 ` Andreas Hartmann
@ 2021-01-24 17:28   ` Andreas Hartmann
  2021-01-25 10:18     ` Andreas Hartmann
  0 siblings, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-24 17:28 UTC (permalink / raw)
  To: linux-usb, mathias.nyman


On 22.01.21 at 09:09 Andreas Hartmann wrote:
> On 22.01.21 at 09:06 Andreas Hartmann wrote:
>>
>> Hello!
>>
>> Since a new Notebook, which sadly only provides USB 3 interfaces, I have a more 
>> or less big problem with an old driver (rt5572sta), which not just sometimes 
>> produces those warn messages, but even stalls sometimes after those warn 
>> messages (e,g, Kernel 5.3.x or 5.10.x or 5.8.x) - see attached log file.
>>
>> The driver uses the bulk method to communicate with the USB bus. By reducing the 
>> max. bulk size from 24 kByte to 12 kByte, I was able to massively reduce those 
>> warning messages and now, the USB bus even seldom stalls any more.
>>
>> I achieved this by changing the building of the bulk package from
>>
>> if (((ThisBulkSize&0xffff8000) != 0) || ((ThisBulkSize&0x6000) == 0x6000))
>>
>> to
>>
>> if (((ThisBulkSize&0xffff8000) != 0) || ((ThisBulkSize&0x3000) == 0x3000))
>>
>>
>> I can see this problem on two different AMD USB 3 controller, e.g. X370 Series 
>> Chipset USB 3.1 xHCI Controller [1022:43b9] (rev 02).

After doing some deeper investigations, I can say, that there are 4(!) different 
behaviors - besides the point, that the original sized bulk packages (24 kB) are 
working much more worse than 12 kB (reducing it further more doesn't make any 
difference any more):

1. No problem at all even over hours of stress test (netperf).


2. Sometimes "WARN Wrong bounce buffer write length" entries appear - but nothing 
more.


3. The problems shown in the attachment of the previous mail are coming up. The 
communication to the device stalls for some time or even breaks completely. It's 
when the completion routine called by the kernel detects the problem:

2021-01-19T14:01:47.492316+01:00 localhost kernel: [26509.686972] xhci_hcd 
0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
2021-01-19T14:01:48.947710+01:00 localhost kernel: [26511.142333] 
BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:01:48.947737+01:00 localhost kernel: [26511.142356]       >>BulkOut 
Req=0xc7f93, Complete=0xc7f92, Other=0x2
2021-01-19T14:01:48.947739+01:00 localhost kernel: [26511.142361]       >>BulkOut 
Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:01:54.303312+01:00 localhost kernel: [26516.498060] 
BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:01:54.303333+01:00 localhost kernel: [26516.498078]       >>BulkOut 
Req=0xc7f93, Complete=0xc7f92, Other=0x3
2021-01-19T14:01:54.303335+01:00 localhost kernel: [26516.498083]       >>BulkOut 
Header:10 6 0 44 d0 0 8f 80
2021-01-19T14:01:59.676016+01:00 localhost kernel: [26521.870773] 
BulkOutDataPacket failed: ReasonCode=-2!
2021-01-19T14:01:59.676044+01:00 localhost kernel: [26521.870800]       >>BulkOut 
Req=0xc7f93, Complete=0xc7f92, Other=0x4
2021-01-19T14:01:59.676046+01:00 localhost kernel: [26521.870815]       >>BulkOut 
Header:10 6 0 44 d0 0 8f 80

The reason code -2 (ENOENT?) is the status given by the urb struct. The driver 
tries to send the same packet again and again and suddenly it's working again 
after n retries. This mostly "works" - but not always.


4. There isn't any completion any more received. At this point, the watchdog kicks 
in and tries to reset the hardware. This mostly works (after some time) - but not 
always. Question is, why there isn't any completion call at all coming up. 
Something seems to hang completely in this case.

2021-01-24T17:11:17.562705+01:00 localhost kernel: [ 3181.024863] xhci_hcd 
0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
2021-01-24T17:11:20.191792+01:00 localhost kernel: [ 3183.651100] Maybe the Tx 
Bulk-Out hanged! Cancel the pending Tx bulks request of idx(0)!
2021-01-24T17:11:20.191821+01:00 localhost kernel: [ 3183.651103] Unlink the 
pending URB!

2021-01-24T17:11:20.191823+01:00 localhost kernel: [ 3183.651287] set 
RTMP_ADAPTER_BULKOUT_RESET (rtusb_dataout_complete - called from done_tasklet)
2021-01-24T17:11:20.191825+01:00 localhost kernel: [ 3183.651288] 
BulkOutDataPacket failed: ReasonCode=-2!
2021-01-24T17:11:20.191826+01:00 localhost kernel: [ 3183.651290]       >>BulkOut 
Req=0x4566e8, Complete=0x4566e7, Other=0x7
2021-01-24T17:11:20.191828+01:00 localhost kernel: [ 3183.651292]       >>BulkOut 
Header:10 6 0 44 d0 0 96 80

2021-01-24T17:11:20.191829+01:00 localhost kernel: [ 3183.651299] 
CMDTHREAD_RESET_BULK_OUT(ResetPipeid=0x0)===>
2021-01-24T17:11:21.559776+01:00 localhost kernel: [ 3185.018969]       Set 0x2a0 
bit19. Clear USB DMA TX path
2021-01-24T17:11:21.559801+01:00 localhost kernel: [ 3185.018977] 
CMDTHREAD_RESET_BULK_OUT: TxContext[0]:CWPos=52912, NBPos=74696, ENBPos=87144, 
bCopy=1, pending=1!
2021-01-24T17:11:21.559803+01:00 localhost kernel: [ 3185.018978] 
BulkOut Req=0x4566e8, Complete=0x4566e7, Other=0x7
2021-01-24T17:11:21.559804+01:00 localhost kernel: [ 3185.018980] 
CMDTHREAD_RESET_BULK_OUT: Submit Tx DATA URB for failed BulkReq(0x4566e8) Done, 
status=-115!
2021-01-24T17:11:21.559805+01:00 localhost kernel: [ 3185.019001] CmdThread : 
CMDTHREAD_RESET_BULK_OUT<===


2021-01-24T17:11:25.479870+01:00 localhost kernel: [ 3188.938847] Maybe the Tx 
Bulk-Out hanged! Cancel the pending Tx bulks request of idx(0)!
2021-01-24T17:11:25.479898+01:00 localhost kernel: [ 3188.938850] Unlink the 
pending URB!

2021-01-24T17:11:25.479899+01:00 localhost kernel: [ 3188.939052] set 
RTMP_ADAPTER_BULKOUT_RESET
2021-01-24T17:11:25.479901+01:00 localhost kernel: [ 3188.939054] 
BulkOutDataPacket failed: ReasonCode=-2!
2021-01-24T17:11:25.479902+01:00 localhost kernel: [ 3188.939055]       >>BulkOut 
Req=0x4566e8, Complete=0x4566e7, Other=0x8
2021-01-24T17:11:25.479903+01:00 localhost kernel: [ 3188.939057]       >>BulkOut 
Header:10 6 0 44 d0 0 96 80

2021-01-24T17:11:25.479904+01:00 localhost kernel: [ 3188.939065] 
CMDTHREAD_RESET_BULK_OUT(ResetPipeid=0x0)===>
2021-01-24T17:11:26.844167+01:00 localhost kernel: [ 3190.303636]       Set 0x2a0 
bit19. Clear USB DMA TX path
2021-01-24T17:11:26.844192+01:00 localhost kernel: [ 3190.303644] 
CMDTHREAD_RESET_BULK_OUT: TxContext[0]:CWPos=59136, NBPos=74696, ENBPos=87144, 
bCopy=1, pending=1!
2021-01-24T17:11:26.844194+01:00 localhost kernel: [ 3190.303645] 
BulkOut Req=0x4566e8, Complete=0x4566e7, Other=0x8
2021-01-24T17:11:26.844195+01:00 localhost kernel: [ 3190.303646] 
CMDTHREAD_RESET_BULK_OUT: Submit Tx DATA URB for failed BulkReq(0x4566e8) Done, 
status=-115!
2021-01-24T17:11:26.844196+01:00 localhost kernel: [ 3190.303659] CmdThread : 
CMDTHREAD_RESET_BULK_OUT<===

Sending the urb again (usb_submit_urb) after resetting the hardware and unlinking 
the urb fails with status -115 (EINPROGRESS) and the watchdog kicks in again after 
4 s, trying the same process again - until it works again (= submit is ok and 
completion doesn't complain - could take up to 1 minute or more).


Hope this helps to get an idea of the problem!



Thanks
Andreas

About the hardware I'm currently testing on:
# lspci -s0000:00:06.0 -vv
00:06.0 USB controller: Advanced Micro Devices, Inc. [AMD] X370 Series Chipset USB 
3.1 xHCI Controller (rev 02) (prog-if 30 [XHCI])
         Subsystem: ASMedia Technology Inc. Device 1142
         Physical Slot: 6
         Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- 
Stepping- SERR+ FastB2B- DisINTx+
         Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- 
<MAbort- >SERR- <PERR- INTx-
         Latency: 0, Cache Line Size: 64 bytes
         Interrupt: pin A routed to IRQ 29
         Region 0: Memory at febd0000 (64-bit, non-prefetchable) [size=32K]
         Capabilities: [50] MSI: Enable+ Count=1/8 Maskable- 64bit+
                 Address: 00000000fee0e000  Data: 4023
         Capabilities: [78] Power Management version 3
                 Flags: PMEClk- DSI- D1- D2- AuxCurrent=55mA 
PME(D0-,D1-,D2-,D3hot+,D3cold+)
                 Status: D0 NoSoftRst+ PME-Enable- DSel=0 DScale=0 PME-
         Capabilities: [80] Express (v2) Legacy Endpoint, MSI 00
                 DevCap: MaxPayload 512 bytes, PhantFunc 0, Latency L0s <64ns, L1 <2us
                         ExtTag+ AttnBtn- AttnInd- PwrInd- RBE+ FLReset-
                 DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
                         RlxdOrd+ ExtTag+ PhantFunc- AuxPwr- NoSnoop+
                         MaxPayload 128 bytes, MaxReadReq 512 bytes
                 DevSta: CorrErr+ UncorrErr- FatalErr- UnsuppReq+ AuxPwr+ TransPend-
                 LnkCap: Port #0, Speed 8GT/s, Width x4, ASPM L0s L1, Exit Latency 
L0s <2us, L1 unlimited
                         ClockPM- Surprise- LLActRep- BwNot- ASPMOptComp+
                 LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- CommClk+
                         ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
                 LnkSta: Speed 8GT/s, Width x4, TrErr- Train- SlotClk+ DLActive- 
BWMgmt- ABWMgmt-
                 DevCap2: Completion Timeout: Not Supported, TimeoutDis-, LTR+, 
OBFF Not Supported
                          AtomicOpsCap: 32bit- 64bit- 128bitCAS-
                 DevCtl2: Completion Timeout: 50us to 50ms, TimeoutDis-, LTR-, 
OBFF Disabled
                          AtomicOpsCtl: ReqEn-
                 LnkSta2: Current De-emphasis Level: -6dB, EqualizationComplete+, 
EqualizationPhase1+
                          EqualizationPhase2-, EqualizationPhase3-, 
LinkEqualizationRequest-
         Kernel driver in use: xhci_hcd
         Kernel modules: xhci_pci

Bus 003 Device 002: ID 05e3:0732 Genesys Logic, Inc. All-in-One Cardreader
Bus 003 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 002: ID 13b1:003b Linksys AE3000 802.11abgn (3x3) Wireless Adapter 
[Ralink RT3573]
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

# lsusb -t
/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/8p, 10000M
     |__ Port 4: Dev 2, If 0, Class=Mass Storage, Driver=usb-storage, 5000M
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=uhci_hcd/2p, 12M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/14p, 480M
     |__ Port 3: Dev 2, If 0, Class=Vendor Specific Class, Driver=rt2870, 480M

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-24 17:28   ` Andreas Hartmann
@ 2021-01-25 10:18     ` Andreas Hartmann
  2021-01-25 18:28       ` Mathias Nyman
  0 siblings, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-25 10:18 UTC (permalink / raw)
  To: linux-usb, mathias.nyman

[-- Attachment #1: Type: text/plain, Size: 6114 bytes --]


Hello!

Meanwhile I found the culprit:

https://www.spinics.net/lists/linux-usb/msg141467.html
and
https://www.spinics.net/lists/linux-usb/msg141468.html

Especially the last change breaks things here completely. After removing them by 
the attached patch, problems are gone and device works again as expected (I tested 
with the original 24 kB bulk size which was horribly broken w/o the attached 
patch). This means: the additional repair steps are not just breaking things but 
are even unnecessary (it's working perfectly without those changes) here.


I tested with 2 USB 3.1 host controllers:

USB controller: Advanced Micro Devices, Inc. [AMD] Raven USB 3.1 (prog-if 30 [XHCI])

05:00.3 0c03: 1022:15e0 (prog-if 30 [XHCI])
         Subsystem: 1043:201f
         Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- 
Stepping- SERR- FastB2B- DisINTx+
         Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- 
<MAbort- >SERR- <PERR- INTx-
         Latency: 0, Cache Line Size: 64 bytes
         Interrupt: pin D routed to IRQ 37
         Region 0: Memory at f7300000 (64-bit, non-prefetchable) [size=1M]
         Capabilities: [48] Vendor Specific Information: Len=08 <?>
         Capabilities: [50] Power Management version 3
                 Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA 
PME(D0+,D1-,D2-,D3hot+,D3cold+)
                 Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
         Capabilities: [64] Express (v2) Endpoint, MSI 00
                 DevCap: MaxPayload 256 bytes, PhantFunc 0, Latency L0s <4us, L1 
unlimited
                         ExtTag+ AttnBtn- AttnInd- PwrInd- RBE+ FLReset- 
SlotPowerLimit 0.000W
                 DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
                         RlxdOrd+ ExtTag+ PhantFunc- AuxPwr- NoSnoop+
                         MaxPayload 256 bytes, MaxReadReq 512 bytes
                 DevSta: CorrErr- UncorrErr- FatalErr- UnsuppReq- AuxPwr- TransPend-
                 LnkCap: Port #0, Speed 8GT/s, Width x16, ASPM L0s L1, Exit 
Latency L0s <64ns, L1 <1us
                         ClockPM- Surprise- LLActRep- BwNot- ASPMOptComp+
                 LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- CommClk+
                         ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
                 LnkSta: Speed 8GT/s, Width x16, TrErr- Train- SlotClk+ DLActive- 
BWMgmt- ABWMgmt-
                 DevCap2: Completion Timeout: Not Supported, TimeoutDis-, LTR+, 
OBFF Not Supported
                          AtomicOpsCap: 32bit- 64bit- 128bitCAS-
                 DevCtl2: Completion Timeout: 50us to 50ms, TimeoutDis-, LTR-, 
OBFF Disabled
                          AtomicOpsCtl: ReqEn-
                 LnkSta2: Current De-emphasis Level: -3.5dB, 
EqualizationComplete-, EqualizationPhase1-
                          EqualizationPhase2-, EqualizationPhase3-, 
LinkEqualizationRequest-
         Capabilities: [a0] MSI: Enable- Count=1/8 Maskable- 64bit+
                 Address: 0000000000000000  Data: 0000
         Capabilities: [c0] MSI-X: Enable+ Count=8 Masked-
                 Vector table: BAR=0 offset=000fe000
                 PBA: BAR=0 offset=000ff000
         Capabilities: [100 v1] Vendor Specific Information: ID=0001 Rev=1 Len=010 <?>
         Kernel driver in use: xhci_hcd
         Kernel modules: xhci_pci

The 2. device on the same machine has the PCI-ID 1022:15e1


Another USB3.1 host device tested with was:
USB controller: Advanced Micro Devices, Inc. [AMD] X370 Series Chipset USB 3.1 
xHCI Controller (rev 02) (prog-if 30 [XHCI])

00:06.0 0c03: 1022:43b9 (rev 02) (prog-if 30 [XHCI])
         Subsystem: 1b21:1142
         Physical Slot: 6
         Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- 
Stepping- SERR+ FastB2B- DisINTx+
         Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- 
<MAbort- >SERR- <PERR- INTx-
         Latency: 0, Cache Line Size: 64 bytes
         Interrupt: pin A routed to IRQ 29
         Region 0: Memory at febd0000 (64-bit, non-prefetchable) [size=32K]
         Capabilities: [50] MSI: Enable+ Count=1/8 Maskable- 64bit+
                 Address: 00000000fee0e000  Data: 4023
         Capabilities: [78] Power Management version 3
                 Flags: PMEClk- DSI- D1- D2- AuxCurrent=55mA 
PME(D0-,D1-,D2-,D3hot+,D3cold+)
                 Status: D0 NoSoftRst+ PME-Enable- DSel=0 DScale=0 PME-
         Capabilities: [80] Express (v2) Legacy Endpoint, MSI 00
                 DevCap: MaxPayload 512 bytes, PhantFunc 0, Latency L0s <64ns, L1 <2us
                         ExtTag+ AttnBtn- AttnInd- PwrInd- RBE+ FLReset-
                 DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
                         RlxdOrd+ ExtTag+ PhantFunc- AuxPwr- NoSnoop+
                         MaxPayload 128 bytes, MaxReadReq 512 bytes
                 DevSta: CorrErr+ UncorrErr- FatalErr- UnsuppReq+ AuxPwr+ TransPend-
                 LnkCap: Port #0, Speed 8GT/s, Width x4, ASPM L0s L1, Exit Latency 
L0s <2us, L1 unlimited
                         ClockPM- Surprise- LLActRep- BwNot- ASPMOptComp+
                 LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- CommClk+
                         ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
                 LnkSta: Speed 8GT/s, Width x4, TrErr- Train- SlotClk+ DLActive- 
BWMgmt- ABWMgmt-
                 DevCap2: Completion Timeout: Not Supported, TimeoutDis-, LTR+, 
OBFF Not Supported
                          AtomicOpsCap: 32bit- 64bit- 128bitCAS-
                 DevCtl2: Completion Timeout: 50us to 50ms, TimeoutDis-, LTR-, 
OBFF Disabled
                          AtomicOpsCtl: ReqEn-
                 LnkSta2: Current De-emphasis Level: -6dB, EqualizationComplete+, 
EqualizationPhase1+
                          EqualizationPhase2-, EqualizationPhase3-, 
LinkEqualizationRequest-
         Kernel driver in use: xhci_hcd
         Kernel modules: xhci_pci


Please fix those changes or disable them for the mentioned devices or add an 
option to disable this additional alignment feature.


Thanks
Andreas

[-- Attachment #2: xhci-ring-no-alignment.c.diff --]
[-- Type: text/x-patch, Size: 483 bytes --]

--- 1/drivers/usb/host/xhci-ring.c	2021-01-25 08:57:52.199210954 +0100
+++ 2/drivers/usb/host/xhci-ring.c	2021-01-25 08:59:29.450511420 +0100
@@ -3250,6 +3250,10 @@ static int xhci_align_td(struct xhci_hcd
 	/* we got lucky, last normal TRB data on segment is packet aligned */
 	if (unalign == 0)
 		return 0;
+	else {
+		xhci_dbg(xhci, "unaligned - but ignored\n");
+		return 0;
+	}
 
 	xhci_dbg(xhci, "Unaligned %d bytes, buff len %d\n",
 		 unalign, *trb_buff_len);

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-25 10:18     ` Andreas Hartmann
@ 2021-01-25 18:28       ` Mathias Nyman
  2021-01-25 18:48         ` Andreas Hartmann
  2021-01-25 20:06         ` Andreas Hartmann
  0 siblings, 2 replies; 17+ messages in thread
From: Mathias Nyman @ 2021-01-25 18:28 UTC (permalink / raw)
  To: Andreas Hartmann, linux-usb

Hi

On 25.1.2021 12.18, Andreas Hartmann wrote:
> 
> Hello!
> 
> Meanwhile I found the culprit:
> 
> https://www.spinics.net/lists/linux-usb/msg141467.html
> and
> https://www.spinics.net/lists/linux-usb/msg141468.html
> 
> Especially the last change breaks things here completely. After removing them
> by the attached patch, problems are gone and device works again as expected
> (I tested with the original 24 kB bulk size which was horribly broken w/o the
> attached patch). This means: the additional repair steps are not just breaking
> things but are even unnecessary (it's working perfectly without those changes)
> here.

Unfortunately this isn't enough to remove the alignment code for those
controllers. This is just once specific usecase. We need to figure out what
really goes wrong.

Looks like 0 bytes is copied from sg list to bounce buffer when we want 512
bytes copied. Just noticed the alignment code assumes sg lists are used without
checking it first.

Could you add the below code and test again, it should print more debugging info.

Thanks
-Mathias

8<---

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 5677b81c0915..6a4578a45eb1 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -3253,13 +3253,13 @@ static int xhci_align_td(struct xhci_hcd *xhci, struct urb *urb, u32 enqd_len,
 	if (unalign == 0)
 		return 0;
 
-	xhci_dbg(xhci, "Unaligned %d bytes, buff len %d\n",
+	xhci_warn(xhci, "Unaligned %d bytes, buff len %d\n",
 		 unalign, *trb_buff_len);
 
 	/* is the last nornal TRB alignable by splitting it */
 	if (*trb_buff_len > unalign) {
 		*trb_buff_len -= unalign;
-		xhci_dbg(xhci, "split align, new buff len %d\n", *trb_buff_len);
+		xhci_warn(xhci, "split align, new buff len %d\n", *trb_buff_len);
 		return 0;
 	}
 
@@ -3275,12 +3275,26 @@ static int xhci_align_td(struct xhci_hcd *xhci, struct urb *urb, u32 enqd_len,
 
 	/* create a max max_pkt sized bounce buffer pointed to by last trb */
 	if (usb_urb_dir_out(urb)) {
+		unsigned int nents;
 		len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
 				   seg->bounce_buf, new_buff_len, enqd_len);
-		if (len != new_buff_len)
+		if (len != new_buff_len) {
 			xhci_warn(xhci,
 				"WARN Wrong bounce buffer write length: %zu != %d\n",
 				len, new_buff_len);
+			xhci_warn(xhci,	"urb->num_sgs %d\n", urb->num_sgs);
+			xhci_warn(xhci,	"urb->num_mapped_sgs %d\n", urb->num_mapped_sgs);
+			xhci_warn(xhci,	"urb->transfer_buffer_length %d\n", urb->transfer_buffer_length);
+			xhci_warn(xhci,	"enqd_len %d\n", enqd_len);
+			xhci_warn(xhci,	"max_pkt %d\n", max_pkt);
+			if (urb->sg) {
+				struct scatterlist *sg;
+				for (nents = 0; sg; sg = sg_next(sg)) {
+					nents++;
+					xhci_warn(xhci, "%d: sg->length %d\n", nents, sg->length);
+				}
+			}
+		}
 		seg->bounce_dma = dma_map_single(dev, seg->bounce_buf,
 						 max_pkt, DMA_TO_DEVICE);
 	} else {



^ permalink raw reply related	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-25 18:28       ` Mathias Nyman
@ 2021-01-25 18:48         ` Andreas Hartmann
  2021-01-25 20:06         ` Andreas Hartmann
  1 sibling, 0 replies; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-25 18:48 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb

Hello Mathias!

On 25.01.21 at 19:28 Mathias Nyman wrote:
> Hi
> 
> On 25.1.2021 12.18, Andreas Hartmann wrote:
>>
>> Hello!
>>
>> Meanwhile I found the culprit:
>>
>> https://www.spinics.net/lists/linux-usb/msg141467.html
>> and
>> https://www.spinics.net/lists/linux-usb/msg141468.html
>>
>> Especially the last change breaks things here completely. After removing them
>> by the attached patch, problems are gone and device works again as expected
>> (I tested with the original 24 kB bulk size which was horribly broken w/o the
>> attached patch). This means: the additional repair steps are not just breaking
>> things but are even unnecessary (it's working perfectly without those changes)
>> here.
> 
> Unfortunately this isn't enough to remove the alignment code for those
> controllers. This is just once specific usecase. We need to figure out what
> really goes wrong.
> 
> Looks like 0 bytes is copied from sg list to bounce buffer when we want 512
> bytes copied.

I don't have only 512 bytes cases, but also 100, 136, 424, 396, 144,
292. It's working anyway w/o any modifications. Why does it work w/o any
modification? Do those chips really need any alignment?

> Just noticed the alignment code assumes sg lists are used without
> checking it first.
> 
> Could you add the below code and test again, it should print more debugging info.

Is there a way to compile this code external - w/o recompiling the whole
kernel?


Thanks
Andreas

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-25 18:28       ` Mathias Nyman
  2021-01-25 18:48         ` Andreas Hartmann
@ 2021-01-25 20:06         ` Andreas Hartmann
  2021-01-26  7:26           ` Andreas Hartmann
  1 sibling, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-25 20:06 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb

[-- Attachment #1: Type: text/plain, Size: 1506 bytes --]

Hello Mathias,

On 25.01.21 at 19:28 Mathias Nyman wrote:
> Hi
> 
> On 25.1.2021 12.18, Andreas Hartmann wrote:
>>
>> Hello!
>>
>> Meanwhile I found the culprit:
>>
>> https://www.spinics.net/lists/linux-usb/msg141467.html
>> and
>> https://www.spinics.net/lists/linux-usb/msg141468.html
>>
>> Especially the last change breaks things here completely. After removing them
>> by the attached patch, problems are gone and device works again as expected
>> (I tested with the original 24 kB bulk size which was horribly broken w/o the
>> attached patch). This means: the additional repair steps are not just breaking
>> things but are even unnecessary (it's working perfectly without those changes)
>> here.
> 
> Unfortunately this isn't enough to remove the alignment code for those
> controllers. This is just once specific usecase. We need to figure out what
> really goes wrong.
> 
> Looks like 0 bytes is copied from sg list to bounce buffer when we want 512
> bytes copied. Just noticed the alignment code assumes sg lists are used without
> checking it first.
> 
> Could you add the below code and test again, it should print more debugging info.

See the attached file. That's the result of two times coping 1.3 GB via scp.

As the transfer mostly breaks after the wrong alignments and because
there isn't any further alignment needed at all, I didn't do more tests.
Hope this helps. Most importantly it should be investigated, why there
isn't any additional alignment needed at all.


Thanks
Andreas

[-- Attachment #2: debug.txt --]
[-- Type: text/plain, Size: 28573 bytes --]

2021-01-25T20:48:05.432669+01:00 localhost kernel: [  219.779879] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:05.432696+01:00 localhost kernel: [  219.779886] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:06.684039+01:00 localhost kernel: [  221.031279] xhci_hcd 0000:05:00.3: Unaligned 244 bytes, buff len 7924
2021-01-25T20:48:06.684064+01:00 localhost kernel: [  221.031283] xhci_hcd 0000:05:00.3: split align, new buff len 7680
2021-01-25T20:48:06.963774+01:00 localhost kernel: [  221.311019] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:06.963797+01:00 localhost kernel: [  221.311023] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:07.544122+01:00 localhost kernel: [  221.891370] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:07.544142+01:00 localhost kernel: [  221.891374] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:14.059866+01:00 localhost kernel: [  228.407127] xhci_hcd 0000:05:00.3: Unaligned 300 bytes, buff len 11052
2021-01-25T20:48:14.059890+01:00 localhost kernel: [  228.407131] xhci_hcd 0000:05:00.3: split align, new buff len 10752
2021-01-25T20:48:14.253496+01:00 localhost kernel: [  228.599397] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:14.253520+01:00 localhost kernel: [  228.599401] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:15.133583+01:00 localhost kernel: [  229.480857] xhci_hcd 0000:05:00.3: Unaligned 160 bytes, buff len 160
2021-01-25T20:48:15.133598+01:00 localhost kernel: [  229.480860] xhci_hcd 0000:05:00.3: WARN Wrong bounce buffer write length: 0 != 512
2021-01-25T20:48:15.133599+01:00 localhost kernel: [  229.480861] xhci_hcd 0000:05:00.3: urb->num_sgs 0
2021-01-25T20:48:15.133600+01:00 localhost kernel: [  229.480862] xhci_hcd 0000:05:00.3: urb->num_mapped_sgs 0
2021-01-25T20:48:15.133600+01:00 localhost kernel: [  229.480863] xhci_hcd 0000:05:00.3: urb->transfer_buffer_length 24900
2021-01-25T20:48:15.133601+01:00 localhost kernel: [  229.480864] xhci_hcd 0000:05:00.3: enqd_len 0
2021-01-25T20:48:15.133601+01:00 localhost kernel: [  229.480864] xhci_hcd 0000:05:00.3: max_pkt 512
2021-01-25T20:48:16.315613+01:00 localhost kernel: [  230.662880] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:16.315639+01:00 localhost kernel: [  230.662885] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:18.648749+01:00 localhost kernel: [  232.996022] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:18.648773+01:00 localhost kernel: [  232.996027] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:19.219018+01:00 localhost kernel: [  233.566301] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:19.219043+01:00 localhost kernel: [  233.566306] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:20.818958+01:00 localhost kernel: [  235.166240] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:20.818986+01:00 localhost kernel: [  235.166245] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:21.896537+01:00 localhost kernel: [  236.243835] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:21.896558+01:00 localhost kernel: [  236.243839] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:23.962820+01:00 localhost kernel: [  238.310123] xhci_hcd 0000:05:00.3: Unaligned 232 bytes, buff len 6376
2021-01-25T20:48:23.962836+01:00 localhost kernel: [  238.310127] xhci_hcd 0000:05:00.3: split align, new buff len 6144
2021-01-25T20:48:26.477497+01:00 localhost kernel: [  240.822066] xhci_hcd 0000:05:00.3: Unaligned 288 bytes, buff len 12576
2021-01-25T20:48:26.477528+01:00 localhost kernel: [  240.822072] xhci_hcd 0000:05:00.3: split align, new buff len 12288
2021-01-25T20:48:32.237504+01:00 localhost kernel: [  246.583028] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:32.237529+01:00 localhost kernel: [  246.583032] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:32.609500+01:00 localhost kernel: [  246.956710] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:32.609528+01:00 localhost kernel: [  246.956715] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:33.384467+01:00 localhost kernel: [  247.731802] xhci_hcd 0000:05:00.3: Unaligned 204 bytes, buff len 4812
2021-01-25T20:48:33.384489+01:00 localhost kernel: [  247.731808] xhci_hcd 0000:05:00.3: split align, new buff len 4608
2021-01-25T20:48:36.168882+01:00 localhost kernel: [  250.516217] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:36.168905+01:00 localhost kernel: [  250.516221] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:36.390007+01:00 localhost kernel: [  250.737347] xhci_hcd 0000:05:00.3: Unaligned 368 bytes, buff len 15728
2021-01-25T20:48:36.390031+01:00 localhost kernel: [  250.737351] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:36.888094+01:00 localhost kernel: [  251.235422] xhci_hcd 0000:05:00.3: Unaligned 280 bytes, buff len 9496
2021-01-25T20:48:36.888122+01:00 localhost kernel: [  251.235426] xhci_hcd 0000:05:00.3: split align, new buff len 9216
2021-01-25T20:48:39.457905+01:00 localhost kernel: [  253.805243] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:39.457933+01:00 localhost kernel: [  253.805247] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:44.096031+01:00 localhost kernel: [  258.443399] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:44.096051+01:00 localhost kernel: [  258.443401] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:47.166279+01:00 localhost kernel: [  261.513632] xhci_hcd 0000:05:00.3: Unaligned 280 bytes, buff len 15640
2021-01-25T20:48:47.166307+01:00 localhost kernel: [  261.513636] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:47.573499+01:00 localhost kernel: [  261.919729] xhci_hcd 0000:05:00.3: Unaligned 368 bytes, buff len 15728
2021-01-25T20:48:47.573523+01:00 localhost kernel: [  261.919733] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:50.720531+01:00 localhost kernel: [  265.067893] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:50.720559+01:00 localhost kernel: [  265.067897] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:54.182808+01:00 localhost kernel: [  268.278671] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:54.182834+01:00 localhost kernel: [  268.278677] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:54.401591+01:00 localhost kernel: [  268.480636] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:54.401616+01:00 localhost kernel: [  268.480641] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:56.100003+01:00 localhost kernel: [  270.048395] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:56.100028+01:00 localhost kernel: [  270.048400] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:56.312818+01:00 localhost kernel: [  270.250076] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:56.312842+01:00 localhost kernel: [  270.250081] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:48:56.501147+01:00 localhost kernel: [  270.438530] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:48:56.501171+01:00 localhost kernel: [  270.438535] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:03.551863+01:00 localhost kernel: [  277.489761] xhci_hcd 0000:05:00.3: Unaligned 368 bytes, buff len 15728
2021-01-25T20:49:03.551888+01:00 localhost kernel: [  277.489765] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:04.137489+01:00 localhost kernel: [  278.071863] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:04.137512+01:00 localhost kernel: [  278.071868] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:05.852773+01:00 localhost kernel: [  279.790685] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:05.852794+01:00 localhost kernel: [  279.790690] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:06.303813+01:00 localhost kernel: [  280.241731] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:06.303837+01:00 localhost kernel: [  280.241736] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:06.862751+01:00 localhost kernel: [  280.800670] xhci_hcd 0000:05:00.3: Unaligned 280 bytes, buff len 15640
2021-01-25T20:49:06.862770+01:00 localhost kernel: [  280.800675] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:08.366705+01:00 localhost kernel: [  282.304624] xhci_hcd 0000:05:00.3: Unaligned 280 bytes, buff len 15640
2021-01-25T20:49:08.366729+01:00 localhost kernel: [  282.304629] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:09.358719+01:00 localhost kernel: [  283.296633] xhci_hcd 0000:05:00.3: Unaligned 144 bytes, buff len 144
2021-01-25T20:49:09.358741+01:00 localhost kernel: [  283.296638] xhci_hcd 0000:05:00.3: WARN Wrong bounce buffer write length: 0 != 512
2021-01-25T20:49:09.358743+01:00 localhost kernel: [  283.296640] xhci_hcd 0000:05:00.3: urb->num_sgs 0
2021-01-25T20:49:09.358745+01:00 localhost kernel: [  283.296642] xhci_hcd 0000:05:00.3: urb->num_mapped_sgs 0
2021-01-25T20:49:09.358746+01:00 localhost kernel: [  283.296644] xhci_hcd 0000:05:00.3: urb->transfer_buffer_length 6228
2021-01-25T20:49:09.358747+01:00 localhost kernel: [  283.296646] xhci_hcd 0000:05:00.3: enqd_len 0
2021-01-25T20:49:09.358748+01:00 localhost kernel: [  283.296647] xhci_hcd 0000:05:00.3: max_pkt 512
2021-01-25T20:49:09.559923+01:00 localhost kernel: [  283.497856] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:09.559943+01:00 localhost kernel: [  283.497859] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:10.249484+01:00 localhost kernel: [  284.187186] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:10.249504+01:00 localhost kernel: [  284.187189] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:13.310514+01:00 localhost kernel: [  287.248469] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:13.310530+01:00 localhost kernel: [  287.248471] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:14.732785+01:00 localhost kernel: [  288.670725] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:14.732809+01:00 localhost kernel: [  288.670730] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:17.650404+01:00 localhost kernel: [  291.588351] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:17.650427+01:00 localhost kernel: [  291.588356] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:18.052537+01:00 localhost kernel: [  291.990508] xhci_hcd 0000:05:00.3: Unaligned 280 bytes, buff len 15640
2021-01-25T20:49:18.052551+01:00 localhost kernel: [  291.990510] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:18.777480+01:00 localhost kernel: [  292.715323] xhci_hcd 0000:05:00.3: Unaligned 160 bytes, buff len 3232
2021-01-25T20:49:18.777494+01:00 localhost kernel: [  292.715325] xhci_hcd 0000:05:00.3: split align, new buff len 3072
2021-01-25T20:49:20.845487+01:00 localhost kernel: [  294.781639] xhci_hcd 0000:05:00.3: Unaligned 368 bytes, buff len 15728
2021-01-25T20:49:20.845507+01:00 localhost kernel: [  294.781642] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:21.033620+01:00 localhost kernel: [  294.971593] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:21.033641+01:00 localhost kernel: [  294.971597] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:22.847230+01:00 localhost kernel: [  296.785201] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:22.847254+01:00 localhost kernel: [  296.785206] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:26.653505+01:00 localhost kernel: [  300.589168] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:26.653536+01:00 localhost kernel: [  300.589172] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:28.068406+01:00 localhost kernel: [  302.006391] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:28.068431+01:00 localhost kernel: [  302.006396] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:29.014069+01:00 localhost kernel: [  302.952052] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:29.014093+01:00 localhost kernel: [  302.952057] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:29.942425+01:00 localhost kernel: [  303.880414] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:29.942447+01:00 localhost kernel: [  303.880419] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:49:30.942988+01:00 localhost kernel: [  304.880987] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:49:30.943012+01:00 localhost kernel: [  304.880992] xhci_hcd 0000:05:00.3: split align, new buff len 15360


2021-01-25T20:52:54.649241+01:00 localhost kernel: [  508.586898] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:52:54.649267+01:00 localhost kernel: [  508.586903] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:52:55.917197+01:00 localhost kernel: [  509.854848] xhci_hcd 0000:05:00.3: Unaligned 468 bytes, buff len 23508
2021-01-25T20:52:55.917223+01:00 localhost kernel: [  509.854854] xhci_hcd 0000:05:00.3: split align, new buff len 23040
2021-01-25T20:52:56.208083+01:00 localhost kernel: [  510.145741] xhci_hcd 0000:05:00.3: Unaligned 280 bytes, buff len 15640
2021-01-25T20:52:56.208110+01:00 localhost kernel: [  510.145746] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:52:56.506004+01:00 localhost kernel: [  510.443649] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:52:56.506030+01:00 localhost kernel: [  510.443654] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:52:57.006628+01:00 localhost kernel: [  510.944273] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:52:57.006655+01:00 localhost kernel: [  510.944278] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:01.084710+01:00 localhost kernel: [  515.022362] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:01.084736+01:00 localhost kernel: [  515.022368] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:07.813507+01:00 localhost kernel: [  521.750591] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:07.813541+01:00 localhost kernel: [  521.750597] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:08.337508+01:00 localhost kernel: [  522.272737] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:08.337538+01:00 localhost kernel: [  522.272742] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:08.741501+01:00 localhost kernel: [  522.677834] xhci_hcd 0000:05:00.3: Unaligned 336 bytes, buff len 15696
2021-01-25T20:53:08.741525+01:00 localhost kernel: [  522.677838] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:09.345505+01:00 localhost kernel: [  523.279711] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:09.345535+01:00 localhost kernel: [  523.279716] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:09.553507+01:00 localhost kernel: [  523.488681] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:09.553538+01:00 localhost kernel: [  523.488687] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:10.581501+01:00 localhost kernel: [  524.518552] xhci_hcd 0000:05:00.3: Unaligned 280 bytes, buff len 15640
2021-01-25T20:53:10.581526+01:00 localhost kernel: [  524.518557] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:11.022998+01:00 localhost kernel: [  524.960689] xhci_hcd 0000:05:00.3: Unaligned 368 bytes, buff len 15728
2021-01-25T20:53:11.023021+01:00 localhost kernel: [  524.960694] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:11.866753+01:00 localhost kernel: [  525.804428] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:11.866777+01:00 localhost kernel: [  525.804433] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:14.299164+01:00 localhost kernel: [  528.236850] xhci_hcd 0000:05:00.3: Unaligned 252 bytes, buff len 7932
2021-01-25T20:53:14.299190+01:00 localhost kernel: [  528.236855] xhci_hcd 0000:05:00.3: split align, new buff len 7680
2021-01-25T20:53:17.021509+01:00 localhost kernel: [  530.957559] xhci_hcd 0000:05:00.3: Unaligned 168 bytes, buff len 3240
2021-01-25T20:53:17.021534+01:00 localhost kernel: [  530.957564] xhci_hcd 0000:05:00.3: split align, new buff len 3072
2021-01-25T20:53:17.200557+01:00 localhost kernel: [  531.138252] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:17.200584+01:00 localhost kernel: [  531.138257] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:17.376444+01:00 localhost kernel: [  531.314128] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:17.376470+01:00 localhost kernel: [  531.314133] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:21.103355+01:00 localhost kernel: [  535.041064] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:21.103377+01:00 localhost kernel: [  535.041068] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:22.681712+01:00 localhost kernel: [  536.615630] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:22.681738+01:00 localhost kernel: [  536.615635] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:23.262498+01:00 localhost kernel: [  537.200175] xhci_hcd 0000:05:00.3: Unaligned 144 bytes, buff len 144
2021-01-25T20:53:23.262524+01:00 localhost kernel: [  537.200181] xhci_hcd 0000:05:00.3: WARN Wrong bounce buffer write length: 0 != 512
2021-01-25T20:53:23.262527+01:00 localhost kernel: [  537.200183] xhci_hcd 0000:05:00.3: urb->num_sgs 0
2021-01-25T20:53:23.262529+01:00 localhost kernel: [  537.200185] xhci_hcd 0000:05:00.3: urb->num_mapped_sgs 0
2021-01-25T20:53:23.262530+01:00 localhost kernel: [  537.200187] xhci_hcd 0000:05:00.3: urb->transfer_buffer_length 24900
2021-01-25T20:53:23.262532+01:00 localhost kernel: [  537.200188] xhci_hcd 0000:05:00.3: enqd_len 0
2021-01-25T20:53:23.262533+01:00 localhost kernel: [  537.200190] xhci_hcd 0000:05:00.3: max_pkt 512
2021-01-25T20:53:23.685505+01:00 localhost kernel: [  537.622567] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:23.685757+01:00 localhost kernel: [  537.622572] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:23.881468+01:00 localhost kernel: [  537.819157] xhci_hcd 0000:05:00.3: Unaligned 200 bytes, buff len 3272
2021-01-25T20:53:23.881492+01:00 localhost kernel: [  537.819163] xhci_hcd 0000:05:00.3: split align, new buff len 3072
2021-01-25T20:53:26.398176+01:00 localhost kernel: [  540.335857] xhci_hcd 0000:05:00.3: Unaligned 248 bytes, buff len 9464
2021-01-25T20:53:26.398203+01:00 localhost kernel: [  540.335862] xhci_hcd 0000:05:00.3: split align, new buff len 9216
2021-01-25T20:53:29.086359+01:00 localhost kernel: [  543.024087] xhci_hcd 0000:05:00.3: Unaligned 392 bytes, buff len 18824
2021-01-25T20:53:29.086380+01:00 localhost kernel: [  543.024091] xhci_hcd 0000:05:00.3: split align, new buff len 18432
2021-01-25T20:53:29.489512+01:00 localhost kernel: [  543.425986] xhci_hcd 0000:05:00.3: Unaligned 360 bytes, buff len 15720
2021-01-25T20:53:29.489539+01:00 localhost kernel: [  543.425991] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:30.578180+01:00 localhost kernel: [  544.515887] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:30.578211+01:00 localhost kernel: [  544.515892] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:33.416061+01:00 localhost kernel: [  547.353782] xhci_hcd 0000:05:00.3: Unaligned 420 bytes, buff len 20388
2021-01-25T20:53:33.416089+01:00 localhost kernel: [  547.353788] xhci_hcd 0000:05:00.3: split align, new buff len 19968
2021-01-25T20:53:34.081496+01:00 localhost kernel: [  548.017944] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:34.081780+01:00 localhost kernel: [  548.017949] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:34.621505+01:00 localhost kernel: [  548.559085] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:34.621532+01:00 localhost kernel: [  548.559089] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:37.834070+01:00 localhost kernel: [  551.771798] xhci_hcd 0000:05:00.3: Unaligned 340 bytes, buff len 14164
2021-01-25T20:53:37.834100+01:00 localhost kernel: [  551.771803] xhci_hcd 0000:05:00.3: split align, new buff len 13824
2021-01-25T20:53:38.449501+01:00 localhost kernel: [  552.384534] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:38.449527+01:00 localhost kernel: [  552.384539] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:45.565760+01:00 localhost kernel: [  559.503498] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:45.565790+01:00 localhost kernel: [  559.503503] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:47.137570+01:00 localhost kernel: [  561.075199] xhci_hcd 0000:05:00.3: Unaligned 168 bytes, buff len 168
2021-01-25T20:53:47.137594+01:00 localhost kernel: [  561.075205] xhci_hcd 0000:05:00.3: WARN Wrong bounce buffer write length: 0 != 512
2021-01-25T20:53:47.137597+01:00 localhost kernel: [  561.075208] xhci_hcd 0000:05:00.3: urb->num_sgs 0
2021-01-25T20:53:47.137599+01:00 localhost kernel: [  561.075210] xhci_hcd 0000:05:00.3: urb->num_mapped_sgs 0
2021-01-25T20:53:47.137603+01:00 localhost kernel: [  561.075212] xhci_hcd 0000:05:00.3: urb->transfer_buffer_length 1560
2021-01-25T20:53:47.137605+01:00 localhost kernel: [  561.075214] xhci_hcd 0000:05:00.3: enqd_len 0
2021-01-25T20:53:47.137606+01:00 localhost kernel: [  561.075215] xhci_hcd 0000:05:00.3: max_pkt 512
2021-01-25T20:53:51.525297+01:00 localhost kernel: [  565.463059] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:51.525320+01:00 localhost kernel: [  565.463063] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:54.331675+01:00 localhost kernel: [  568.269446] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:54.331699+01:00 localhost kernel: [  568.269450] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:53:56.588689+01:00 localhost kernel: [  570.526439] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:53:56.588714+01:00 localhost kernel: [  570.526445] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:01.622038+01:00 localhost kernel: [  575.559798] xhci_hcd 0000:05:00.3: Unaligned 340 bytes, buff len 14164
2021-01-25T20:54:01.622065+01:00 localhost kernel: [  575.559804] xhci_hcd 0000:05:00.3: split align, new buff len 13824
2021-01-25T20:54:03.807069+01:00 localhost kernel: [  577.744837] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:03.807094+01:00 localhost kernel: [  577.744843] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:04.133080+01:00 localhost kernel: [  578.070862] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:04.133109+01:00 localhost kernel: [  578.070867] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:04.601587+01:00 localhost kernel: [  578.539362] xhci_hcd 0000:05:00.3: Unaligned 220 bytes, buff len 4828
2021-01-25T20:54:04.601614+01:00 localhost kernel: [  578.539367] xhci_hcd 0000:05:00.3: split align, new buff len 4608
2021-01-25T20:54:07.485308+01:00 localhost kernel: [  581.423106] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:07.485329+01:00 localhost kernel: [  581.423110] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:08.049501+01:00 localhost kernel: [  581.985364] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:08.049529+01:00 localhost kernel: [  581.985368] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:08.633543+01:00 localhost kernel: [  582.569227] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:08.633587+01:00 localhost kernel: [  582.569235] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:09.197516+01:00 localhost kernel: [  583.131888] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:09.197539+01:00 localhost kernel: [  583.131893] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:18.825193+01:00 localhost kernel: [  592.763004] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:18.825217+01:00 localhost kernel: [  592.763008] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:19.191806+01:00 localhost kernel: [  593.129517] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:19.191833+01:00 localhost kernel: [  593.129522] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:20.256271+01:00 localhost kernel: [  594.194106] xhci_hcd 0000:05:00.3: Unaligned 156 bytes, buff len 1692
2021-01-25T20:54:20.256300+01:00 localhost kernel: [  594.194111] xhci_hcd 0000:05:00.3: split align, new buff len 1536
2021-01-25T20:54:20.466527+01:00 localhost kernel: [  594.404144] xhci_hcd 0000:05:00.3: Unaligned 368 bytes, buff len 18800
2021-01-25T20:54:20.466553+01:00 localhost kernel: [  594.404149] xhci_hcd 0000:05:00.3: split align, new buff len 18432
2021-01-25T20:54:22.901256+01:00 localhost kernel: [  596.839080] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:22.901284+01:00 localhost kernel: [  596.839085] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:23.098582+01:00 localhost kernel: [  597.036427] xhci_hcd 0000:05:00.3: Unaligned 388 bytes, buff len 17284
2021-01-25T20:54:23.098610+01:00 localhost kernel: [  597.036432] xhci_hcd 0000:05:00.3: split align, new buff len 16896
2021-01-25T20:54:26.543491+01:00 localhost kernel: [  600.481319] xhci_hcd 0000:05:00.3: Unaligned 376 bytes, buff len 15736
2021-01-25T20:54:26.543517+01:00 localhost kernel: [  600.481324] xhci_hcd 0000:05:00.3: split align, new buff len 15360
2021-01-25T20:54:27.545714+01:00 localhost kernel: [  601.481064] xhci_hcd 0000:05:00.3: Unaligned 160 bytes, buff len 160
2021-01-25T20:54:27.545740+01:00 localhost kernel: [  601.481070] xhci_hcd 0000:05:00.3: WARN Wrong bounce buffer write length: 0 != 512
2021-01-25T20:54:27.545742+01:00 localhost kernel: [  601.481074] xhci_hcd 0000:05:00.3: urb->num_sgs 0
2021-01-25T20:54:27.545744+01:00 localhost kernel: [  601.481076] xhci_hcd 0000:05:00.3: urb->num_mapped_sgs 0
2021-01-25T20:54:27.545745+01:00 localhost kernel: [  601.481079] xhci_hcd 0000:05:00.3: urb->transfer_buffer_length 24900
2021-01-25T20:54:27.545746+01:00 localhost kernel: [  601.481082] xhci_hcd 0000:05:00.3: enqd_len 0
2021-01-25T20:54:27.545748+01:00 localhost kernel: [  601.481084] xhci_hcd 0000:05:00.3: max_pkt 512

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-25 20:06         ` Andreas Hartmann
@ 2021-01-26  7:26           ` Andreas Hartmann
  2021-01-26 14:11             ` Mathias Nyman
  0 siblings, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-26  7:26 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb


On 25.01.21 at 21:06 Andreas Hartmann wrote:
> Hello Mathias,
> 
> On 25.01.21 at 19:28 Mathias Nyman wrote:
>> Hi
>>
>> On 25.1.2021 12.18, Andreas Hartmann wrote:
>>>
>>> Hello!
>>>
>>> Meanwhile I found the culprit:
>>>
>>> https://www.spinics.net/lists/linux-usb/msg141467.html
>>> and
>>> https://www.spinics.net/lists/linux-usb/msg141468.html
>>>
>>> Especially the last change breaks things here completely. After removing them
>>> by the attached patch, problems are gone and device works again as expected
>>> (I tested with the original 24 kB bulk size which was horribly broken w/o the
>>> attached patch). This means: the additional repair steps are not just breaking
>>> things but are even unnecessary (it's working perfectly without those changes)
>>> here.
>>
>> Unfortunately this isn't enough to remove the alignment code for those
>> controllers. This is just once specific usecase. We need to figure out what
>> really goes wrong.
>>
>> Looks like 0 bytes is copied from sg list to bounce buffer when we want 512
>> bytes copied. Just noticed the alignment code assumes sg lists are used without
>> checking it first.
>>
>> Could you add the below code and test again, it should print more debugging info.
> 
> See the attached file. That's the result of two times coping 1.3 GB via scp.
> 
> As the transfer mostly breaks after the wrong alignments and because
> there isn't any further alignment needed at all, I didn't do more tests.
> Hope this helps. Most importantly it should be investigated, why there
> isn't any additional alignment needed at all.

I'm not sure if it's important for you to know: The driver doesn't use struct 
scatterlist or num_mapped_sgs at all (if it's meant to be used by the sender at all).

But it sets URB_NO_TRANSFER_DMA_MAP (for data transfer among others).

Mlme packets are sent w/o bulk and w/o setting URB_NO_TRANSFER_DMA_MAP. All other 
packets are sent with URB_NO_TRANSFER_DMA_MAP turned on.



Thanks
Andreas

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-26  7:26           ` Andreas Hartmann
@ 2021-01-26 14:11             ` Mathias Nyman
  2021-01-26 17:29               ` Mathias Nyman
  0 siblings, 1 reply; 17+ messages in thread
From: Mathias Nyman @ 2021-01-26 14:11 UTC (permalink / raw)
  To: Andreas Hartmann, linux-usb

On 26.1.2021 9.26, Andreas Hartmann wrote:
> 
> On 25.01.21 at 21:06 Andreas Hartmann wrote:
>> Hello Mathias,
>>
>> On 25.01.21 at 19:28 Mathias Nyman wrote:
>>> Hi
>>>
>>> On 25.1.2021 12.18, Andreas Hartmann wrote:
>>>>
>>>> Hello!
>>>>
>>>> Meanwhile I found the culprit:
>>>>
>>>> https://www.spinics.net/lists/linux-usb/msg141467.html
>>>> and
>>>> https://www.spinics.net/lists/linux-usb/msg141468.html
>>>>
>>>> Especially the last change breaks things here completely. After removing them
>>>> by the attached patch, problems are gone and device works again as expected
>>>> (I tested with the original 24 kB bulk size which was horribly broken w/o the
>>>> attached patch). This means: the additional repair steps are not just breaking
>>>> things but are even unnecessary (it's working perfectly without those changes)
>>>> here.
>>>
>>> Unfortunately this isn't enough to remove the alignment code for those
>>> controllers. This is just once specific usecase. We need to figure out what
>>> really goes wrong.
>>>
>>> Looks like 0 bytes is copied from sg list to bounce buffer when we want 512
>>> bytes copied. Just noticed the alignment code assumes sg lists are used without
>>> checking it first.
>>>
>>> Could you add the below code and test again, it should print more debugging info.
>>
>> See the attached file. That's the result of two times coping 1.3 GB via scp.
>>
>> As the transfer mostly breaks after the wrong alignments and because
>> there isn't any further alignment needed at all, I didn't do more tests.
>> Hope this helps. Most importantly it should be investigated, why there
>> isn't any additional alignment needed at all.
> 
> I'm not sure if it's important for you to know: The driver doesn't use struct scatterlist or num_mapped_sgs at all (if it's meant to be used by the sender at all).
> 
> But it sets URB_NO_TRANSFER_DMA_MAP (for data transfer among others).
> 
> Mlme packets are sent w/o bulk and w/o setting URB_NO_TRANSFER_DMA_MAP. All other packets are sent with URB_NO_TRANSFER_DMA_MAP turned on.
> 

Ok, thanks, I see what's going on here.

Short recap of xhci alignment requirements.
1. Data pointed to by a transfer request block (TRB) may not span 64k boundary
2. If a transfer contains several TRBs, and spans over two TRB ringbuffer
   segments, then the sum of the TRB data in the first segment must be a 
   multiple of max packets in size.
 
Code assumes that if transfer is split into several blocks,(TRBs) and a block
in the middle of a transfer is smaller than max packet size, then it must be sg list.

But this is not necessarily the case if data was already DMA mapped beforehand.
Data might start just before a 64k boundary, causing first TRB to be less than
packet size.

I'll start implementing a fix for this.

-Mathias



^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-26 14:11             ` Mathias Nyman
@ 2021-01-26 17:29               ` Mathias Nyman
  2021-01-26 17:48                 ` Andreas Hartmann
  2021-01-26 21:16                 ` Andreas Hartmann
  0 siblings, 2 replies; 17+ messages in thread
From: Mathias Nyman @ 2021-01-26 17:29 UTC (permalink / raw)
  To: Andreas Hartmann, linux-usb


>> I'm not sure if it's important for you to know: The driver doesn't use struct scatterlist or num_mapped_sgs at all (if it's meant to be used by the sender at all).
>>
>> But it sets URB_NO_TRANSFER_DMA_MAP (for data transfer among others).
>>
>> Mlme packets are sent w/o bulk and w/o setting URB_NO_TRANSFER_DMA_MAP. All other packets are sent with URB_NO_TRANSFER_DMA_MAP turned on.
>>
> 
> Ok, thanks, I see what's going on here.
> 
> Short recap of xhci alignment requirements.
> 1. Data pointed to by a transfer request block (TRB) may not span 64k boundary
> 2. If a transfer contains several TRBs, and spans over two TRB ringbuffer
>    segments, then the sum of the TRB data in the first segment must be a 
>    multiple of max packets in size.
>  
> Code assumes that if transfer is split into several blocks,(TRBs) and a block
> in the middle of a transfer is smaller than max packet size, then it must be sg list.
> 
> But this is not necessarily the case if data was already DMA mapped beforehand.
> Data might start just before a 64k boundary, causing first TRB to be less than
> packet size.
> 
> I'll start implementing a fix for this.

Got a first iteration ready,
any change you could try it out?

Thanks
-Mathias

8<---

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 5677b81c0915..8df30618aaf1 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -699,11 +699,16 @@ static void xhci_unmap_td_bounce_buffer(struct xhci_hcd *xhci,
 	dma_unmap_single(dev, seg->bounce_dma, ring->bounce_buf_len,
 			 DMA_FROM_DEVICE);
 	/* for in tranfers we need to copy the data from bounce to sg */
-	len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
-			     seg->bounce_len, seg->bounce_offs);
-	if (len != seg->bounce_len)
-		xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
-				len, seg->bounce_len);
+	if (urb->num_sgs) {
+		len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
+					   seg->bounce_len, seg->bounce_offs);
+		if (len != seg->bounce_len)
+			xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
+				  len, seg->bounce_len);
+	} else {
+		memcpy(urb->transfer_buffer + seg->bounce_offs, seg->bounce_buf,
+		       seg->bounce_len);
+	}
 	seg->bounce_len = 0;
 	seg->bounce_offs = 0;
 }
@@ -3275,12 +3280,16 @@ static int xhci_align_td(struct xhci_hcd *xhci, struct urb *urb, u32 enqd_len,
 
 	/* create a max max_pkt sized bounce buffer pointed to by last trb */
 	if (usb_urb_dir_out(urb)) {
-		len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
-				   seg->bounce_buf, new_buff_len, enqd_len);
-		if (len != new_buff_len)
-			xhci_warn(xhci,
-				"WARN Wrong bounce buffer write length: %zu != %d\n",
-				len, new_buff_len);
+		if (urb->num_sgs) {
+			len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
+						 seg->bounce_buf, new_buff_len, enqd_len);
+			if (len != new_buff_len)
+				xhci_warn(xhci, "WARN Wrong bounce buffer write length: %zu != %d\n",
+					  len, new_buff_len);
+		} else {
+			memcpy(seg->bounce_buf, urb->transfer_buffer + enqd_len, new_buff_len);
+		}
+
 		seg->bounce_dma = dma_map_single(dev, seg->bounce_buf,
 						 max_pkt, DMA_TO_DEVICE);
 	} else {

^ permalink raw reply related	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-26 17:29               ` Mathias Nyman
@ 2021-01-26 17:48                 ` Andreas Hartmann
  2021-01-26 21:16                 ` Andreas Hartmann
  1 sibling, 0 replies; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-26 17:48 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb

Hello Mathias,

I'll test it ASAP!

Thanks
Andreas

On 26.01.21 at 18:29 Mathias Nyman wrote:
> 
>>> I'm not sure if it's important for you to know: The driver doesn't use struct scatterlist or num_mapped_sgs at all (if it's meant to be used by the sender at all).
>>>
>>> But it sets URB_NO_TRANSFER_DMA_MAP (for data transfer among others).
>>>
>>> Mlme packets are sent w/o bulk and w/o setting URB_NO_TRANSFER_DMA_MAP. All other packets are sent with URB_NO_TRANSFER_DMA_MAP turned on.
>>>
>>
>> Ok, thanks, I see what's going on here.
>>
>> Short recap of xhci alignment requirements.
>> 1. Data pointed to by a transfer request block (TRB) may not span 64k boundary
>> 2. If a transfer contains several TRBs, and spans over two TRB ringbuffer
>>    segments, then the sum of the TRB data in the first segment must be a 
>>    multiple of max packets in size.
>>  
>> Code assumes that if transfer is split into several blocks,(TRBs) and a block
>> in the middle of a transfer is smaller than max packet size, then it must be sg list.
>>
>> But this is not necessarily the case if data was already DMA mapped beforehand.
>> Data might start just before a 64k boundary, causing first TRB to be less than
>> packet size.
>>
>> I'll start implementing a fix for this.
> 
> Got a first iteration ready,
> any change you could try it out?
> 
> Thanks
> -Mathias
> 
> 8<---
> 
> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
> index 5677b81c0915..8df30618aaf1 100644
> --- a/drivers/usb/host/xhci-ring.c
> +++ b/drivers/usb/host/xhci-ring.c
> @@ -699,11 +699,16 @@ static void xhci_unmap_td_bounce_buffer(struct xhci_hcd *xhci,
>  	dma_unmap_single(dev, seg->bounce_dma, ring->bounce_buf_len,
>  			 DMA_FROM_DEVICE);
>  	/* for in tranfers we need to copy the data from bounce to sg */
> -	len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
> -			     seg->bounce_len, seg->bounce_offs);
> -	if (len != seg->bounce_len)
> -		xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
> -				len, seg->bounce_len);
> +	if (urb->num_sgs) {
> +		len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
> +					   seg->bounce_len, seg->bounce_offs);
> +		if (len != seg->bounce_len)
> +			xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
> +				  len, seg->bounce_len);
> +	} else {
> +		memcpy(urb->transfer_buffer + seg->bounce_offs, seg->bounce_buf,
> +		       seg->bounce_len);
> +	}
>  	seg->bounce_len = 0;
>  	seg->bounce_offs = 0;
>  }
> @@ -3275,12 +3280,16 @@ static int xhci_align_td(struct xhci_hcd *xhci, struct urb *urb, u32 enqd_len,
>  
>  	/* create a max max_pkt sized bounce buffer pointed to by last trb */
>  	if (usb_urb_dir_out(urb)) {
> -		len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
> -				   seg->bounce_buf, new_buff_len, enqd_len);
> -		if (len != new_buff_len)
> -			xhci_warn(xhci,
> -				"WARN Wrong bounce buffer write length: %zu != %d\n",
> -				len, new_buff_len);
> +		if (urb->num_sgs) {
> +			len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
> +						 seg->bounce_buf, new_buff_len, enqd_len);
> +			if (len != new_buff_len)
> +				xhci_warn(xhci, "WARN Wrong bounce buffer write length: %zu != %d\n",
> +					  len, new_buff_len);
> +		} else {
> +			memcpy(seg->bounce_buf, urb->transfer_buffer + enqd_len, new_buff_len);
> +		}
> +
>  		seg->bounce_dma = dma_map_single(dev, seg->bounce_buf,
>  						 max_pkt, DMA_TO_DEVICE);
>  	} else {
> 

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-26 17:29               ` Mathias Nyman
  2021-01-26 17:48                 ` Andreas Hartmann
@ 2021-01-26 21:16                 ` Andreas Hartmann
  2021-01-27  6:43                   ` Andreas Hartmann
  1 sibling, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-26 21:16 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb

Hello Mathias!

On 26.01.21 at 18:29 Mathias Nyman wrote:
> 
>>> I'm not sure if it's important for you to know: The driver doesn't use struct scatterlist or num_mapped_sgs at all (if it's meant to be used by the sender at all).
>>>
>>> But it sets URB_NO_TRANSFER_DMA_MAP (for data transfer among others).
>>>
>>> Mlme packets are sent w/o bulk and w/o setting URB_NO_TRANSFER_DMA_MAP. All other packets are sent with URB_NO_TRANSFER_DMA_MAP turned on.
>>>
>>
>> Ok, thanks, I see what's going on here.
>>
>> Short recap of xhci alignment requirements.
>> 1. Data pointed to by a transfer request block (TRB) may not span 64k boundary
>> 2. If a transfer contains several TRBs, and spans over two TRB ringbuffer
>>    segments, then the sum of the TRB data in the first segment must be a 
>>    multiple of max packets in size.
>>  
>> Code assumes that if transfer is split into several blocks,(TRBs) and a block
>> in the middle of a transfer is smaller than max packet size, then it must be sg list.
>>
>> But this is not necessarily the case if data was already DMA mapped beforehand.
>> Data might start just before a 64k boundary, causing first TRB to be less than
>> packet size.
>>
>> I'll start implementing a fix for this.
> 
> Got a first iteration ready,
> any change you could try it out?
> 
> Thanks
> -Mathias
> 
> 8<---
> 
> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
> index 5677b81c0915..8df30618aaf1 100644
> --- a/drivers/usb/host/xhci-ring.c
> +++ b/drivers/usb/host/xhci-ring.c
> @@ -699,11 +699,16 @@ static void xhci_unmap_td_bounce_buffer(struct xhci_hcd *xhci,
>  	dma_unmap_single(dev, seg->bounce_dma, ring->bounce_buf_len,
>  			 DMA_FROM_DEVICE);
>  	/* for in tranfers we need to copy the data from bounce to sg */
> -	len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
> -			     seg->bounce_len, seg->bounce_offs);
> -	if (len != seg->bounce_len)
> -		xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
> -				len, seg->bounce_len);
> +	if (urb->num_sgs) {
> +		len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
> +					   seg->bounce_len, seg->bounce_offs);
> +		if (len != seg->bounce_len)
> +			xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
> +				  len, seg->bounce_len);
> +	} else {
> +		memcpy(urb->transfer_buffer + seg->bounce_offs, seg->bounce_buf,
> +		       seg->bounce_len);
> +	}
>  	seg->bounce_len = 0;
>  	seg->bounce_offs = 0;
>  }
> @@ -3275,12 +3280,16 @@ static int xhci_align_td(struct xhci_hcd *xhci, struct urb *urb, u32 enqd_len,
>  
>  	/* create a max max_pkt sized bounce buffer pointed to by last trb */
>  	if (usb_urb_dir_out(urb)) {
> -		len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
> -				   seg->bounce_buf, new_buff_len, enqd_len);
> -		if (len != new_buff_len)
> -			xhci_warn(xhci,
> -				"WARN Wrong bounce buffer write length: %zu != %d\n",
> -				len, new_buff_len);
> +		if (urb->num_sgs) {
> +			len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
> +						 seg->bounce_buf, new_buff_len, enqd_len);
> +			if (len != new_buff_len)
> +				xhci_warn(xhci, "WARN Wrong bounce buffer write length: %zu != %d\n",
> +					  len, new_buff_len);
> +		} else {
> +			memcpy(seg->bounce_buf, urb->transfer_buffer + enqd_len, new_buff_len);
> +		}
> +

If I'm understanding it correctly, you're always creating a bounce
buffer though it is not necessary (at least in my case - my test patch
proofed, that no changes at all are necessary). Why aren't you checking
for URB_NO_TRANSFER_DMA_MAP at the very beginning? Or is it your purpose
to first basically test your new code path? That would be ok.

I tested with the notebook (in both directions) - it seems to work - I
didn't get any problems though I used 24 kB bulk packets. Throughput was
unaltered high.

I'm doing the same test tomorrow with the other USB 3.1 controller!

>  		seg->bounce_dma = dma_map_single(dev, seg->bounce_buf,
>  						 max_pkt, DMA_TO_DEVICE);
>  	} else {
> 

Thanks
Andreas

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-26 21:16                 ` Andreas Hartmann
@ 2021-01-27  6:43                   ` Andreas Hartmann
  2021-01-28 14:14                     ` Mathias Nyman
  0 siblings, 1 reply; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-27  6:43 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb

On 26.01.21 at 22:16 Andreas Hartmann wrote:
> Hello Mathias!
> 
> On 26.01.21 at 18:29 Mathias Nyman wrote:
>> Got a first iteration ready,
>> any change you could try it out?
>>
>> Thanks
>> -Mathias
>>
>> 8<---
>>
>> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
>> index 5677b81c0915..8df30618aaf1 100644
>> --- a/drivers/usb/host/xhci-ring.c
>> +++ b/drivers/usb/host/xhci-ring.c
>> @@ -699,11 +699,16 @@ static void xhci_unmap_td_bounce_buffer(struct xhci_hcd *xhci,
>>  	dma_unmap_single(dev, seg->bounce_dma, ring->bounce_buf_len,
>>  			 DMA_FROM_DEVICE);
>>  	/* for in tranfers we need to copy the data from bounce to sg */
>> -	len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
>> -			     seg->bounce_len, seg->bounce_offs);
>> -	if (len != seg->bounce_len)
>> -		xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
>> -				len, seg->bounce_len);
>> +	if (urb->num_sgs) {
>> +		len = sg_pcopy_from_buffer(urb->sg, urb->num_sgs, seg->bounce_buf,
>> +					   seg->bounce_len, seg->bounce_offs);
>> +		if (len != seg->bounce_len)
>> +			xhci_warn(xhci, "WARN Wrong bounce buffer read length: %zu != %d\n",
>> +				  len, seg->bounce_len);
>> +	} else {
>> +		memcpy(urb->transfer_buffer + seg->bounce_offs, seg->bounce_buf,
>> +		       seg->bounce_len);
>> +	}
>>  	seg->bounce_len = 0;
>>  	seg->bounce_offs = 0;
>>  }
>> @@ -3275,12 +3280,16 @@ static int xhci_align_td(struct xhci_hcd *xhci, struct urb *urb, u32 enqd_len,
>>  
>>  	/* create a max max_pkt sized bounce buffer pointed to by last trb */
>>  	if (usb_urb_dir_out(urb)) {
>> -		len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
>> -				   seg->bounce_buf, new_buff_len, enqd_len);
>> -		if (len != new_buff_len)
>> -			xhci_warn(xhci,
>> -				"WARN Wrong bounce buffer write length: %zu != %d\n",
>> -				len, new_buff_len);
>> +		if (urb->num_sgs) {
>> +			len = sg_pcopy_to_buffer(urb->sg, urb->num_sgs,
>> +						 seg->bounce_buf, new_buff_len, enqd_len);
>> +			if (len != new_buff_len)
>> +				xhci_warn(xhci, "WARN Wrong bounce buffer write length: %zu != %d\n",
>> +					  len, new_buff_len);
>> +		} else {
>> +			memcpy(seg->bounce_buf, urb->transfer_buffer + enqd_len, new_buff_len);
>> +		}
>> +
> 
> If I'm understanding it correctly, you're always creating a bounce
> buffer though it is not necessary (at least in my case - my test patch
> proofed, that no changes at all are necessary). Why aren't you checking
> for URB_NO_TRANSFER_DMA_MAP at the very beginning? Or is it your purpose
> to first basically test your new code path? That would be ok.
> 
> I tested with the notebook (in both directions) - it seems to work - I
> didn't get any problems though I used 24 kB bulk packets. Throughput was
> unaltered high.
> 
> I'm doing the same test tomorrow with the other USB 3.1 controller!

Successfully tested on the other USB 3.1 host.

> 
>>  		seg->bounce_dma = dma_map_single(dev, seg->bounce_buf,
>>  						 max_pkt, DMA_TO_DEVICE);
>>  	} else {
>>
> 
> Thanks
> Andreas
> 


^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-27  6:43                   ` Andreas Hartmann
@ 2021-01-28 14:14                     ` Mathias Nyman
  2021-01-28 17:01                       ` Andreas Hartmann
                                         ` (2 more replies)
  0 siblings, 3 replies; 17+ messages in thread
From: Mathias Nyman @ 2021-01-28 14:14 UTC (permalink / raw)
  To: Andreas Hartmann, linux-usb


>> If I'm understanding it correctly, you're always creating a bounce
>> buffer though it is not necessary (at least in my case - my test patch
>> proofed, that no changes at all are necessary). Why aren't you checking
>> for URB_NO_TRANSFER_DMA_MAP at the very beginning? Or is it your purpose
>> to first basically test your new code path? That would be ok.

Bounce buffer is only used when there is no other way of meeting the xHCI
alignment requirements. Worst case is once every 255 TRB, and for maximum 1024bytes.
Each TRB can point to 64K of data.

I can't go against the spec just because it doesn't cause issues in your
two usecases. The overhead of the bounce buffer usage is so small there's no
point in that kind of optimization.

URB_NO_TRANSFER_DMA_MAP only indicates the data was DMA mapped before driver 
submitted the URB, so usb core does not need to map it.

I was speculating that it could be a cause why data is so oddly aligned
(urbs with data starting at less than 512 bytes from 64k boundary), and
thus not meeting the xHC boundary and aligment requirements even if data
is otherwise contiguous.

xHC controller doesn't care who mapped the data, or if data is in a sg list
or already contiguous in urb->transfer_buffer as long as we follow
the aligment and boudary rules.

Bug was that driver assumed the data that needed to be bounce
buffered was in a sg list. Your cased proved it could be in
urb->tranfer_buffer instead.

>>
>> I tested with the notebook (in both directions) - it seems to work - I
>> didn't get any problems though I used 24 kB bulk packets. Throughput was
>> unaltered high.
>>
>> I'm doing the same test tomorrow with the other USB 3.1 controller!
> 
> Successfully tested on the other USB 3.1 host.
> 

Thank you, much appreciated.

I think I'll submit this patch as it is (with a proper commit message)
can I add reported-by: Andreas Hartmann <andihartmann@01019freenet.de>, and
tested-by: Andreas Hartmann <andihartmann@01019freenet.de> tags to the patch?

-Mathias

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-28 14:14                     ` Mathias Nyman
@ 2021-01-28 17:01                       ` Andreas Hartmann
  2021-01-28 17:36                       ` Andreas Hartmann
  2021-01-28 18:27                       ` Andreas Hartmann
  2 siblings, 0 replies; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-28 17:01 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb


On 28.01.21 at 15:14 Mathias Nyman wrote:
> 
>>> If I'm understanding it correctly, you're always creating a bounce
>>> buffer though it is not necessary (at least in my case - my test patch
>>> proofed, that no changes at all are necessary). Why aren't you checking
>>> for URB_NO_TRANSFER_DMA_MAP at the very beginning? Or is it your purpose
>>> to first basically test your new code path? That would be ok.
> 
> Bounce buffer is only used when there is no other way of meeting the xHCI
> alignment requirements. Worst case is once every 255 TRB, and for maximum 1024bytes.
> Each TRB can point to 64K of data.

This driver is from ~2012 - I'm not sure if they already considered USB 3.x at 
this time (comments to USB 2 and 1 can be found). *I* could not find any 512 Bytes 
related alignment code - but that doesn't say much. I tried to map the xHCI spec 
to the Linux urb API - I'm not sure how to map TRBs or TDs. Could a urb be 
understood as a TRB?

> I can't go against the spec just because it doesn't cause issues in your
> two usecases. The overhead of the bounce buffer usage is so small there's no
> point in that kind of optimization.

That's why I am a bit unsure at the moment regarding the result of the test. As I 
meanwhile know that it's working even w/o doing anything (by chance?), I can't say 
for sure that your patch is working as expected. The only thing I can say, is (see 
below): it doesn't hurt any more.

> URB_NO_TRANSFER_DMA_MAP only indicates the data was DMA mapped before driver
> submitted the URB, so usb core does not need to map it.
> 
> I was speculating that it could be a cause why data is so oddly aligned
> (urbs with data starting at less than 512 bytes from 64k boundary), and
> thus not meeting the xHC boundary and aligment requirements even if data
> is otherwise contiguous.
> 
> xHC controller doesn't care who mapped the data, or if data is in a sg list
> or already contiguous in urb->transfer_buffer as long as we follow
> the aligment and boudary rules.
> 
> Bug was that driver assumed the data that needed to be bounce
> buffered was in a sg list. Your cased proved it could be in
> urb->transfer_buffer instead.

That's true for sure: the driver fills the data into transfer_buffer (it uses 
usb_fill_bulk_urb).

>>> I tested with the notebook (in both directions) - it seems to work - I
>>> didn't get any problems though I used 24 kB bulk packets. Throughput was
>>> unaltered high.
>>>
>>> I'm doing the same test tomorrow with the other USB 3.1 controller!
>>
>> Successfully tested on the other USB 3.1 host.
>>
> 
> Thank you, much appreciated.
> 
> I think I'll submit this patch as it is (with a proper commit message)
> can I add reported-by: Andreas Hartmann <andihartmann@01019freenet.de>, and
> tested-by: Andreas Hartmann <andihartmann@01019freenet.de> tags to the patch?

That's OK for me.


Thanks
Andreas

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-28 14:14                     ` Mathias Nyman
  2021-01-28 17:01                       ` Andreas Hartmann
@ 2021-01-28 17:36                       ` Andreas Hartmann
  2021-01-28 18:27                       ` Andreas Hartmann
  2 siblings, 0 replies; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-28 17:36 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb

Hello Mathias,

On 28.01.21 at 15:14 Mathias Nyman wrote:
> 
> I think I'll submit this patch as it is (with a proper commit message)
> can I add reported-by: Andreas Hartmann <andihartmann@01019freenet.de>, and
> tested-by: Andreas Hartmann <andihartmann@01019freenet.de> tags to the patch?

I forgot:
Would it be possible to add the warning about wrong bounce buffer write
length to the transfer_buffer-case, too?


Thanks
Andreas

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512
  2021-01-28 14:14                     ` Mathias Nyman
  2021-01-28 17:01                       ` Andreas Hartmann
  2021-01-28 17:36                       ` Andreas Hartmann
@ 2021-01-28 18:27                       ` Andreas Hartmann
  2 siblings, 0 replies; 17+ messages in thread
From: Andreas Hartmann @ 2021-01-28 18:27 UTC (permalink / raw)
  To: Mathias Nyman, linux-usb

Hello Mathias,

out of curiosity: could the same happen, too, on the receive side? I can
see a similar check in static void xhci_unmap_td_bounce_buffer.
rt5572sta e.g. uses for receiving urb->transfer_buffer, too. I can see
no problems at all for this path at the moment (not even a warning) -
but couldn't this just be chance?


Thanks
Michael

^ permalink raw reply	[flat|nested] 17+ messages in thread

end of thread, other threads:[~2021-01-28 18:30 UTC | newest]

Thread overview: 17+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-01-22  8:06 USB2 / USB3 compatibility problems: xhci_hcd 0000:00:06.0: WARN Wrong bounce buffer write length: 0 != 512 Andreas Hartmann
2021-01-22  8:09 ` Andreas Hartmann
2021-01-24 17:28   ` Andreas Hartmann
2021-01-25 10:18     ` Andreas Hartmann
2021-01-25 18:28       ` Mathias Nyman
2021-01-25 18:48         ` Andreas Hartmann
2021-01-25 20:06         ` Andreas Hartmann
2021-01-26  7:26           ` Andreas Hartmann
2021-01-26 14:11             ` Mathias Nyman
2021-01-26 17:29               ` Mathias Nyman
2021-01-26 17:48                 ` Andreas Hartmann
2021-01-26 21:16                 ` Andreas Hartmann
2021-01-27  6:43                   ` Andreas Hartmann
2021-01-28 14:14                     ` Mathias Nyman
2021-01-28 17:01                       ` Andreas Hartmann
2021-01-28 17:36                       ` Andreas Hartmann
2021-01-28 18:27                       ` Andreas Hartmann

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.