New: Latent race condition in USB code unveiled with optimized memset_64.S

https://bugzilla.kernel.org/show_bug.cgi?id=220272

            Bug ID: 220272
           Summary: Latent race condition in USB code unveiled with
                    optimized memset_64.S
           Product: Drivers
           Version: 2.5
          Hardware: All
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P3
         Component: USB
          Assignee: [email protected]
          Reporter: [email protected]
        Regression: No

Created attachment 308313
--> https://bugzilla.kernel.org/attachment.cgi?id=308313&action=edit
Optimized memset_64.S for Intel Raptor Lake

Experimenting with AI to tune memset_64.S (see the attached file) for my Intel 14700KF-system unveiled a race condition in the USB code.

Once this significantly faster memset implementation is compiled-in, I've noticed that my USB mouse (Sharkoon Light2 100) is not recognized/detected any longer after each re-boot. The USB mouse is placed in one of the top USB slot next to my USB keyboard (which surprisingly still works fine) on my NZXT N5 Z690 motherboard. Which one doesn't matter.

I did not get any suspect dmesg entries, the mouse is simply not recognized at all.

I first thought of a hardware issue or defective USB slot, but re-slotting the mouse in a different USB slot did not fix the problem eventually. The mouse initially works fine there until the next reboot.

It also starts to work fine in the same USB slot where it wasn't recognized after a reboot once I unplug it and plug it in the same USB slot again.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

Odds are this is because your memset code is buggy :)

As this isn't an existing kernel issue, there's not much we can do about this at the moment, sorry.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #1 from Greg Kroah-Hartman ([email protected]) ---

Odds are this is because your memset code is buggy :)

As this isn't an existing kernel issue, there's not much we can do about this at the moment, sorry.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #2 from Alan Stern ([email protected]) --- What makes you think the mouse problem is caused by a race condition?

If you enable USB dynamic debugging, what shows up in the dmesg log when the mouse is plugged in (both successfully and unsuccessfully)?

echo module usbcore =p >/sys/kernel/debug/dynamic_debug/control

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #3 from Marcus Seyfarth ([email protected]) --- Created attachment 308314
--> https://bugzilla.kernel.org/attachment.cgi?id=308314&action=edit
Optimized memset_64.S for Intel Raptor Lake (patch)

Added the made changes to memset_64.S as a patch.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #4 from Marcus Seyfarth ([email protected]) --- (In reply to Greg Kroah-Hartman from comment #1)

@Greg and Alan
Understood, I thought so, too. But maybe there is some truth to the AI analysis. I cannot tell anything myself as I do not bring any programming expertise to the table and am fully dependant on AI (which is far from perfect at this point in time, I know). However, AI analysis by O3 and Gemini 2.5 Pro both claim that my custom memset is fine and pointed me towards multiple problems in the xhci_setup_device function of xhci.c.

All attempts to fix the problem failed so far. Hence this could be a red herring, I cannot tell.

If people are willing to spend some time on this, I have attached the customized memset_64.S as full file and as a patch. If people do not consider this actionable, that is totally fine with me, too.

Kernel: 6.15.3
Distro: CachyOS

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #5 from Marcus Seyfarth ([email protected]) --- Created attachment 308315
--> https://bugzilla.kernel.org/attachment.cgi?id=308315&action=edit
Added before logs

Added log from before the plug event using this command:

sudo journalctl -b | sudo tee /var/log/usbcore_debug.log > /home/marcus/usbcore_debug.log_before_replug

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #6 from Marcus Seyfarth ([email protected]) --- Created attachment 308316
--> https://bugzilla.kernel.org/attachment.cgi?id=308316&action=edit
Added logs after plug event

Added logs after the plug event using this command:

sudo journalctl -b | sudo tee /var/log/usbcore_debug.log > /home/marcus/usbcore_debug.log_after_replug2

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

Mathias Nyman ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------

                 CC|                            |[email protected]
                   |                            |om

--- Comment #7 from Mathias Nyman ([email protected]) ---

Could you share these AI reported xhci problems.
I'll be on vacation next week so reply will be slow, but I'm interested taking a look anyway

also log with xhci dynamic debug could be useful:
echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #8 from Marcus Seyfarth ([email protected]) --- Created attachment 308322
--> https://bugzilla.kernel.org/attachment.cgi?id=308322&action=edit
AI Analysis of memset_64.S and xhci_setup_device in xhci.c

Thanks a lot Mathias for willing to take a look. I've provided an edited version of the two Chats with Gemini 2.5 Pro and openAI O3 that guided me so far.

My comments are formatted as [** ... **].

I had not much luck using

echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control so far to get any meaningful output. I'll try to get it to work.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #9 from Alan Stern ([email protected]) ---
I don't understand exactly what the two logs in comments #5 and #6 are meant to show.

Is the #5 log just the initial portion of the #6 log? It looks that way. You really don't need to post two copies of the same information.

Also, when I asked for the dmesg log, I meant the output from the "dmesg" command. Not the output from journalctl.

As far as the logs indicate, the Sharkoon mouse was working correctly the whole time. It was detected during boot, and then about 4 minutes later you unplugged it, plugged it back into the same port, and it was detected properly again.

Your bug report says that the Sharkoon mouse is not recognized/detected with the new memset implementation, but the logs show that it is. Do you have any logs of a boot where the mouse was not detected?

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #10 from Marcus Seyfarth ([email protected]) --- @Alan
The logs contain the dmesg output (via journalctl) from a fresh boot (before) where the mouse does not work (after a fresh re-boot). And once after plugging it out and in again in the same USB slot (after).

I also find it perplexing that the dmesg output does show the Sharkoon mouse being detected early in the boot process (as seen in the before logs) but repeatedly and consistently not working once trying to use it on the Plasma desktop. I only see a static mouse pointer which does not move a bit when I move it.

I also could provide the dmesg output as I have these logs as well, but they just show the same output with more fine grained time stamps. No errors or other useful new information are shown there.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #11 from Alan Stern ([email protected]) --- What happens if you boot with the mouse plugged in, then disable it with:

echo 0 >/sys/bus/usb/devices/1-8/bConfigurationValue

and then enable it with:

echo 1 >/sys/bus/usb/devices/1-8/bConfigurationValue

? Does it work after this procedure or is it still non-responsive?

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #12 from Marcus Seyfarth ([email protected]) --- @Alen

Thanks for the trick, these commands bring it back to life without plugging it out and in again!

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #13 from Alan Stern ([email protected]) --- In a way, that's too bad. I was hoping that the mouse still wouldn't work, so we would be able to do further debugging to try and figure out the real cause.

Oh well, at least now you're better off than you were.

Note that the "1-8" in those commands will change when the mouse is plugged into a different USB port, so you'll have to be careful if you want to automate this. A udev script that triggers off the vendor ID and product ID should work.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #14 from Marcus Seyfarth ([email protected]) --- Could you please explain to me what the reported result means? Was there an error on my end or does it mean that there is something wrong in the USB code which is hard to debug further?

I came up with a less efficient memset_64.S implementation that does not unveil this issue, whatever it is.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #15 from Alan Stern ([email protected]) --- At the moment there's no way to know where the real problem lies. It could be something wrong with your new memset code; it could be something wrong in the USB drivers; it even could be something wrong with the mouse itself.

The only way to find out more is to record what happens when the mouse fails to work. But doing that requires you either to issue commands before the problem starts (that is, while the system is booting -- which can't be done) or else to use special (and expensive!) hardware to monitor the signals on the USB cable.

If you can come up with a way to cause a failure that involves plugging in the mouse cable after the system is running, then we would have some hope. But otherwise I'm afraid there's not much to try, other than guessing at possible solutions.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

Michał Pecio ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |[email protected]

--- Comment #16 from Michał Pecio ([email protected]) --- What if you disable and re-enable the whole USB bus? Based on your logs, this should do it:

echo 0000:00:14.0 > /sys/bus/pci/drivers/xhci_hcd/unbind echo 0000:00:14.0 > /sys/bus/pci/drivers/xhci_hcd/bind

Note that if you have a keyboard on this bus it will stop working. You may want to issue both commands at once: "echo xxxx ; echo yyyy".

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #17 from Michał Pecio ([email protected]) --- I also had a look at this LLM generated "report" and I can't see how the alleged issues are supposed to be real.

1. Replacing wmb() with dma_wmb() possibly makes sense, though on x86 wmb() is stronger than dma_wmb() so it can't be the cause of your problem. Other PCI drivers made such change for performance rather than correctness.

2. I'm not familiar with xhci->mutex use so no comment, but the alleged deadlock probably doesn't exist as there is no asynchronous completion callback here.

3. Pedantry with no functional impact.

4. The driver will abort a hanging command and signal the completion.

5. We immediately return so we don't go to the out label. No bug.

6. mutex != spinlock. No bug.

7. I see no bug. No static analyzer was run so that part is made up.

8. Doesn't matter if the value is zero.

9. No arithmetic is done on this variable.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #18 from Marcus Seyfarth ([email protected]) --- (In reply to Michał Pecio from comment #16)

I've just tested this and to my surprise, the mouse remained in a non-working state. The keyboard turned off and on again and was usable before and after.

(In reply to Michał Pecio from comment #17)

Thanks a lot for taking a look, even if only #1 ends up being worth of consideration.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #19 from Alan Stern ([email protected]) --- It's great that the mouse remains non-working after Michał's test!

You should collect two usbmon traces for bus 1. For the first, start the trace before issuing the second test command and don't end the trace until after you have tried (and failed!) to use the mouse. Example:

echo 0000:00:14.0 > /sys/bus/pci/drivers/xhci_hcd/unbind cat /sys/kernel/debug/usb/usbmon/1u >usbmon1.dat & echo 0000:00:14.0 > /sys/bus/pci/drivers/xhci_hcd/bind (try to move the mouse)
fg
^C

For the second, unplug the mouse, then start the trace, then plug the mouse back in. Don't end the trace until after you have tried (and succeeded!) to use the mouse.

The traces will be easier to read if you disconnect as many of the other USB devices on your system as possible.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #20 from Marcus Seyfarth ([email protected]) --- Created attachment 308334
--> https://bugzilla.kernel.org/attachment.cgi?id=308334&action=edit
Trace and Trace-Script

I've attached a zip file that contains the output that I gathered under both circumstances with a neat script that AI wrote for me (also attached) to automate the process as good as possible. Maybe that script is useful for someone else.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #21 from Alan Stern ([email protected]) --- Did you try moving the mouse or pressing any of the buttons while the "working" trace was being acquired? I don't see any signs of it in the trace.

In fact, apart from a little communication with the Razer Cynosa Lite and initialization of the ASM107x and NZXT devices, I don't see any significant differences between the two traces. They show the same amount of communication with the Sharkoon mouse; there's nothing to indicate that it's working in one trace but not in the other.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #22 from Marcus Seyfarth ([email protected]) --- Created attachment 308335
--> https://bugzilla.kernel.org/attachment.cgi?id=308335&action=edit
Trace - Second Attempt

I am sorry, I had missed the "use the mouse" part. I hope the second attempt of getting the traces are more helpful.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #23 from Alan Stern ([email protected]) --- Well, the new traces are a little more helpful but not much.

There is essentially no difference between the initialization portions of the two traces. The difference shows up when you start moving the mouse. In both traces the mouse sends data to the computer. In the working case, the data contains what you would expect: information about the mouse position and button presses. But in the failure case, the data contains nothing but 0's.

Here's where the data starts in the working trace:

ffffa25a535589c0 74469528 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76172178 C Ii:1:006:1 0:1 7 = 000000ff ff0000 ffffa25a535589c0 76172197 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76174062 C Ii:1:006:1 0:1 7 = 000000ff ff0000 ffffa25a535589c0 76174078 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76176189 C Ii:1:006:1 0:1 7 = 000000ff ff0000 ffffa25a535589c0 76176218 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76178108 C Ii:1:006:1 0:1 7 = 000000fd ff0000 ffffa25a535589c0 76178128 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76180102 C Ii:1:006:1 0:1 7 = 000000fc ff0000 ffffa25a535589c0 76180126 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76182070 C Ii:1:006:1 0:1 7 = 000000f9 ff0000 ffffa25a535589c0 76182086 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76184066 C Ii:1:006:1 0:1 7 = 000100f7 ff0000 ffffa25a535589c0 76184081 S Ii:1:006:1 -115:1 7 < ffffa25a535589c0 76186083 C Ii:1:006:1 0:1 7 = 000200f5 ff0000

You can see the changing values in the two right-hand columns. Here's the corresponding portion from the failure trace:

ffffa25a53558780 40179815 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40179828 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40181774 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40181787 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40183769 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40183782 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40185773 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40185783 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40187792 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40187799 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40189792 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40189798 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40191705 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40191716 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40192702 C Ii:1:004:1 0:1 7 = 00000000 000000 ffffa25a53558780 40192705 S Ii:1:004:1 -115:1 7 < ffffa25a53558780 40193717 C Ii:1:004:1 0:1 7 = 00000000 000000

There's nothing to indicate why the mouse is misbehaving in this way. Maybe it just needs to be initialized twice before it will work right. Whatever the reason is, it certainly looks like the fault is in the mouse, not in the computer's software.

Have you tried using the mouse on a different computer or under a different operating system?

Also, can you try getting a trace equivalent to the failure one here, but with the standard memset implementation rather than your improved one?

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #24 from Marcus Seyfarth ([email protected]) --- Created attachment 308350
--> https://bugzilla.kernel.org/attachment.cgi?id=308350&action=edit
Trace working memset

The mouse works fine under Windows 11 without any issue so far.

I've attached v3 traces from a Kernel with another optimized memset present that works fine with the mouse.

I could also try to test the non-working memset with another Sharkoon mouse model attached to the same USB slot.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #25 from Marcus Seyfarth ([email protected]) --- Created attachment 308351
--> https://bugzilla.kernel.org/attachment.cgi?id=308351&action=edit
Trace v4 - Shark Force mouse / non-working memset

Here are the v4 traces from a different mouse (Sharkoon Shark Force) for the non-working memset implementation. This mouse shows a slightly different behavior, it also does not work initially but it did not come back successfully after the re-plug event (the USB LEDs were working though). There is no cursor movement on the desktop.

This deviates from the initial Sharkoon Light 2 100 mouse that did come back successfully after a re-plug event.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

Oliver Neukum ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |[email protected]

--- Comment #26 from Oliver Neukum ([email protected]) --- (In reply to Alan Stern from comment #23)

This is exactly what you'd expect to see if the CPU were operating on stale buffers. They are memset to zero before being used for IO. That is the whole point of the code which triggers this bug, isn't it?

This really looks like we are not invalidating a cache line we should invalidate.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #27 from Alan Stern ([email protected]) --- But if that's the explanation then why does the driver work properly some of the time?

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #28 from Oliver Neukum ([email protected]) --- (In reply to Alan Stern from comment #27)

Memory pressure on the cache. Sometimes cache lines will be invalidated. If you want to stay with the theory that this is a cache issue.

Your diagnosis in #23 is correct. The driver is operating on a zeroed buffer. If we are also taking #25 then we'd have to assume that two different mice fail in the same way, but inconsistently and only if a specific memset is used. Not really likely.

My first suspicion was that we are looking at an issue with HCD with short transfers, specifically that te buffer is not really used and the IO done to the rings, but I see no way how this would correlate with a change in memset.

Do we need to memset the buffers to 0x00? How about a diagnostic patch that uses another value?

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #29 from Alan Stern ([email protected]) ---
As far as I can tell, the buffer is not cleared each time the URB is submitted.
The hid_irq_in() routine in drivers/hid/usbhid/hid-core.c doesn't do anything
to the buffer.

Marcus, you could try modifying that routine to have it store some test data in urb->transfer_buffer immediately before the call to usb_submit_urb(). Maybe the test values will show up in the usbmon trace, but maybe not.

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.kernel.org/show_bug.cgi?id=220272

--- Comment #30 from Marcus Seyfarth ([email protected]) --- Created attachment 308369
--> https://bugzilla.kernel.org/attachment.cgi?id=308369&action=edit
Fixed memset_64.S

I've tried out a few different things which failed during the past week. But today, Grok 4 found some issues in my custom memset_64.S and its fixes indeed fixed the mouse issue for me. I've attached the new custom memset.

It claims:

* Corrected feature to X86_FEATURE_ERMS (not FSRM, which is for movs).
* Fixed return value corruption in ERMS path by properly saving/restoring
original dst pointer (root cause of issues like non-working mouse on boot).

You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.