USB audio causes USB mouse to freeze

alan1world · 2023-05-10 17:58:47

Context

Setup

The USB subsystem normally works fine.
The USB mouse works fine.
Audio via lineout from the motherboard works fine.
Plugging in a USB soundcard is fine.
USB audio via a Bluetooth controller works*
Same behaviour under MATE, XFCE, LXQT and Qtile

* Once I get the Bluetooth working. It can be a little cranky. That's Bluetooth though, not the audio.

Issue

Playing any audio from the USB soundcard causes the mouse to lock up.
When the audio finishes playing, after a few moments the mouse functions again.
(The audio itself plays perfectly through the soundcard.)
No mouse issues exist when playing audio out of the motherboard's line out.

USB keyboard is attached to the same USB hub and still functions when the mouse is frozen - it only affects the mouse, no other systems.
I've tried using a second USB hub and directly in the motherboard USB ports.

Same outcome occurs with both my regular wireless USB mouse (Logitech) and my wired USB mouse (Microsoft).

The Bluetooth headset doesn't cause the same lockup.

Attempted resolutions

In order:

Different ports on the motherboard
Different usb hubs (including powered)
2 different USB soundcards
Testing a USB bluetooth headset
Removing pulseaudio and replacing with pipewire

System

Kernel

My kernel is normally 6.3.1-arch1, I have rebooted and tried with LTS and fallback. No change

Mouse

lsmod | grep mouse
mousedev

USB

lsmod | grep usb 
snd_usb_audio         442368  1
snd_usbmidi_lib        53248  1 snd_usb_audio
snd_rawmidi            53248  1 snd_usbmidi_lib
mc                     90112  1 snd_usb_audio
usbhid                 77824  0
snd_hwdep              20480  2 snd_usb_audio,snd_hda_codec
snd_pcm               200704  5 snd_hda_codec_hdmi,snd_hda_intel,snd_usb_audio,snd_hda_codec,snd_hda_core
snd                   151552  21 snd_hda_codec_generic,snd_seq,snd_seq_device,snd_hda_codec_hdmi,snd_hwdep,snd_hda_intel,snd_usb_audio,snd_usbmidi_lib,snd_hda_codec,snd_hda_codec_realtek,snd_timer,snd_pcm,snd_rawmidi

HID

lsmod | grep hid -> usbhid, mac_hid
usbhid                 77824  0
mac_hid                16384  0

xinput

lsusb; xinput
Bus 001 Device 002: ID 8087:8000 Intel Corp. Integrated Rate Matching Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 006 Device 002: ID 05e3:0626 Genesys Logic, Inc. Hub
Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 005 Device 009: ID 0835:8502 Action Star Enterprise Co., Ltd USB HID
Bus 005 Device 008: ID 0835:8500 Action Star Enterprise Co., Ltd USB2.0 Hub
Bus 005 Device 006: ID 0835:8501 Action Star Enterprise Co., Ltd USB HID
Bus 005 Device 004: ID 0835:8500 Action Star Enterprise Co., Ltd USB2.0 Hub
Bus 005 Device 007: ID 320f:500c SONiX USB DEVICE
Bus 005 Device 005: ID 046d:c542 Logitech, Inc. M185 compact wireless mouse
Bus 005 Device 003: ID 05e3:0610 Genesys Logic, Inc. Hub
Bus 005 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 002: ID 8087:8008 Intel Corp. Integrated Rate Matching Hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
⎡ Virtual core pointer                    	id=2	[master pointer  (3)]
⎜   ↳ Virtual core XTEST pointer              	id=4	[slave  pointer  (2)]
⎜   ↳ Logitech Wireless Receiver Mouse        	id=8	[slave  pointer  (2)]
⎜   ↳ SONiX USB DEVICE Keyboard               	id=10	[slave  pointer  (2)]
⎜   ↳ SONiX USB DEVICE Mouse                  	id=12	[slave  pointer  (2)]
⎣ Virtual core keyboard                   	id=3	[master keyboard (2)]
    ↳ Virtual core XTEST keyboard             	id=5	[slave  keyboard (3)]
    ↳ Power Button                            	id=6	[slave  keyboard (3)]
    ↳ Power Button                            	id=7	[slave  keyboard (3)]
    ↳ SONiX USB DEVICE                        	id=9	[slave  keyboard (3)]
    ↳ SONiX USB DEVICE Wireless Radio Control 	id=11	[slave  keyboard (3)]
    ↳ SONiX USB DEVICE Keyboard               	id=13	[slave  keyboard (3)]

journalctl

journalctl -b

May 10 17:40:12 BASE1 systemd-xdg-autostart-generator[655]: Exec binary 'start-pulseaudio-x11' does not exist: No such file or directory
May 10 17:40:12 BASE1 systemd-xdg-autostart-generator[655]: .config/autostart/pulseaudio.desktop: not generating unit, error parsing Exec= line: No such file or directory
May 10 17:40:13 BASE1 systemd[650]: Queued start job for default target Main User Target.
May 10 17:40:13 BASE1 systemd[650]: Created slice User Application Slice.
May 10 17:40:14 BASE1 gnome-keyring-daemon[661]: GNOME_KEYRING_CONTROL=/run/user/1000/keyring
May 10 17:40:13 BASE1 systemd[650]: Reached target Paths.
May 10 17:40:13 BASE1 systemd[650]: Reached target Timers.
May 10 17:40:13 BASE1 systemd[650]: Starting D-Bus User Message Bus Socket...
May 10 17:40:13 BASE1 systemd[650]: Listening on GnuPG network certificate management daemon.
May 10 17:40:13 BASE1 systemd[650]: Listening on GCR ssh-agent wrapper.
May 10 17:40:13 BASE1 systemd[650]: Listening on GNOME Keyring daemon.
May 10 17:40:13 BASE1 systemd[650]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
May 10 17:40:13 BASE1 systemd[650]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
May 10 17:40:13 BASE1 systemd[650]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
May 10 17:40:13 BASE1 systemd[650]: Listening on GnuPG cryptographic agent and passphrase cache.
May 10 17:40:13 BASE1 systemd[650]: Listening on p11-kit server.
May 10 17:40:13 BASE1 systemd[650]: Listening on PipeWire PulseAudio.
May 10 17:40:13 BASE1 systemd[650]: Listening on PipeWire Multimedia System Socket.
May 10 17:40:13 BASE1 systemd[650]: Listening on D-Bus User Message Bus Socket.
May 10 17:40:13 BASE1 systemd[650]: Reached target Sockets.
May 10 17:40:13 BASE1 systemd[650]: Reached target Basic System.
May 10 17:40:13 BASE1 systemd[650]: Starting Update XDG user dir configuration...
May 10 17:40:13 BASE1 systemd[650]: Started GNOME Keyring daemon.
May 10 17:40:13 BASE1 systemd[650]: Finished Update XDG user dir configuration.
May 10 17:40:13 BASE1 systemd[650]: Reached target Main User Target.
May 10 17:40:13 BASE1 systemd[650]: Startup finished in 1.628s.
May 10 17:40:14 BASE1 systemd[650]: Created slice User Core Session Slice.
May 10 17:40:14 BASE1 systemd[650]: Starting D-Bus User Message Bus...
May 10 17:40:14 BASE1 systemd[650]: Started D-Bus User Message Bus.
May 10 17:40:14 BASE1 sddm-helper[668]: Adding cookie to [Redacted]
May 10 17:40:15 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating via systemd: service name='org.gtk.vfs.Daemon' unit='gvfs-daemon.service' requested by ':1.3' (uid=1000 pid=668 comm="mate-session")
May 10 17:40:15 BASE1 systemd[650]: Starting Virtual filesystem service...
May 10 17:40:15 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.gtk.vfs.Daemon'
May 10 17:40:15 BASE1 systemd[650]: Started Virtual filesystem service.
May 10 17:40:16 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating via systemd: service name='org.a11y.Bus' unit='at-spi-dbus-bus.service' requested by ':1.6' (uid=1000 pid=668 comm="mate-session")
May 10 17:40:16 BASE1 systemd[650]: Starting Accessibility services bus...
May 10 17:40:16 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.a11y.Bus'
May 10 17:40:16 BASE1 systemd[650]: Started Accessibility services bus.
May 10 17:40:16 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating via systemd: service name='ca.desrt.dconf' unit='dconf.service' requested by ':1.3' (uid=1000 pid=668 comm="mate-session")
May 10 17:40:16 BASE1 systemd[650]: Starting User preferences database...
May 10 17:40:16 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'ca.desrt.dconf'
May 10 17:40:16 BASE1 systemd[650]: Started User preferences database.
May 10 17:40:16 BASE1 mate-session[668]: WARNING: Could not parse desktop file .config/autostart/gnome-keyring-pkcs11.desktop: Key file does not have key “Name” in group “Desktop Entry”
May 10 17:40:16 BASE1 mate-session[668]: GLib-GObject-CRITICAL: Custom constructor for class GsmAutostartApp returned NULL (which is invalid). Please use GInitable instead.
May 10 17:40:16 BASE1 mate-session[668]: WARNING: could not read /home/human1/.config/autostart/gnome-keyring-pkcs11.desktop
May 10 17:40:16 BASE1 mate-session[668]: WARNING: Could not parse desktop file /home/human1/.config/autostart/geoclue-demo-agent.desktop: Key file does not have key “Name” in group “Desktop Entry”
May 10 17:40:16 BASE1 mate-session[668]: GLib-GObject-CRITICAL: Custom constructor for class GsmAutostartApp returned NULL (which is invalid). Please use GInitable instead.
May 10 17:40:16 BASE1 mate-session[668]: WARNING: could not read /home/human1/.config/autostart/geoclue-demo-agent.desktop
May 10 17:40:16 BASE1 mate-session[668]: WARNING: Unable to find provider '' of required component 'dock'
May 10 17:40:16 BASE1 at-spi-bus-launcher[705]: dbus-daemon[705]: Activating service name='org.a11y.atspi.Registry' requested by ':1.0' (uid=1000 pid=668 comm="mate-session")
May 10 17:40:16 BASE1 gnome-keyring-daemon[661]: The Secret Service was already initialized
May 10 17:40:16 BASE1 gnome-keyring-daemon[661]: The PKCS#11 component was already initialized
May 10 17:40:16 BASE1 gnome-keyring-d[661]: The Secret Service was already initialized
May 10 17:40:16 BASE1 gnome-keyring-daemon[719]: discover_other_daemon: 1
May 10 17:40:16 BASE1 gnome-keyring-d[661]: The PKCS#11 component was already initialized
May 10 17:40:16 BASE1 at-spi-bus-launcher[705]: dbus-daemon[705]: Successfully activated service 'org.a11y.atspi.Registry'
May 10 17:40:16 BASE1 at-spi-bus-launcher[722]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry
May 10 17:40:18 BASE1 systemd[650]: Started PipeWire Multimedia Service.
May 10 17:40:18 BASE1 systemd[650]: Started Multimedia Service Session Manager.
May 10 17:40:19 BASE1 systemd[650]: Started PipeWire PulseAudio.
May 10 17:40:24 BASE1 wireplumber[737]: [0:02:32.779243861] [737]  INFO Camera camera_manager.cpp:298 libcamera v0.0.5
May 10 17:40:24 BASE1 wireplumber[737]: GetManagedObjects() failed: org.freedesktop.DBus.Error.NameHasNoOwner
May 10 17:40:24 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating via systemd: service name='org.gtk.vfs.UDisks2VolumeMonitor' unit='gvfs-udisks2-volume-monitor.service' requested by ':1.11' (uid=1000 pid=720 comm="/usr/lib/mate-settings-daemon/mate-settings-daemon")
May 10 17:40:24 BASE1 systemd[650]: Starting Virtual filesystem service - disk device monitor...
May 10 17:40:25 BASE1 gnome-keyring-daemon[661]: The PKCS#11 component was already initialized
May 10 17:40:25 BASE1 gnome-keyring-d[661]: The PKCS#11 component was already initialized
May 10 17:40:25 BASE1 gnome-keyring-daemon[793]: discover_other_daemon: 1
May 10 17:40:25 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating service name='org.mate.panel.applet.WnckletFactory' requested by ':1.15' (uid=1000 pid=752 comm="mate-panel")
May 10 17:40:26 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.mate.panel.applet.WnckletFactory'
May 10 17:40:28 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.gtk.vfs.UDisks2VolumeMonitor'
May 10 17:40:28 BASE1 systemd[650]: Started Virtual filesystem service - disk device monitor.
May 10 17:40:28 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating via systemd: service name='org.gtk.vfs.MTPVolumeMonitor' unit='gvfs-mtp-volume-monitor.service' requested by ':1.11' (uid=1000 pid=720 comm="/usr/lib/mate-settings-daemon/mate-settings-daemon")
May 10 17:40:28 BASE1 systemd[650]: Starting Virtual filesystem service - Media Transfer Protocol monitor...
May 10 17:40:28 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.gtk.vfs.MTPVolumeMonitor'
May 10 17:40:28 BASE1 systemd[650]: Started Virtual filesystem service - Media Transfer Protocol monitor.
May 10 17:40:29 BASE1 mate-session[668]: WARNING: Could not launch application 'pulseaudio.desktop': Unable to start application: Failed to execute child process “start-pulseaudio-x11” (No such file or directory)
May 10 17:40:29 BASE1 gnome-keyring-daemon[661]: The SSH agent was already initialized
May 10 17:40:29 BASE1 gnome-keyring-d[661]: The SSH agent was already initialized
May 10 17:40:29 BASE1 gnome-keyring-daemon[854]: discover_other_daemon: 1
May 10 17:40:29 BASE1 gnome-keyring-daemon[661]: The Secret Service was already initialized
May 10 17:40:29 BASE1 gnome-keyring-d[661]: The Secret Service was already initialized
May 10 17:40:29 BASE1 gnome-keyring-daemon[857]: discover_other_daemon: 1
May 10 17:40:41 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating service name='org.fedoraproject.Config.Printing' requested by ':1.35' (uid=1000 pid=917 comm="/usr/bin/python3 /usr/share/system-config-printer/")
May 10 17:40:44 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.fedoraproject.Config.Printing'
May 10 17:40:45 BASE1 org.fedoraproject.Config.Printing[936]: /usr/share/system-config-printer/scp-dbus-service.py:602: DeprecationWarning: Gdk.threads_enter is deprecated
May 10 17:40:45 BASE1 org.fedoraproject.Config.Printing[936]:   Gdk.threads_enter ()
May 10 17:40:45 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating service name='org.freedesktop.Notifications' requested by ':1.36' (uid=1000 pid=936 comm="/usr/bin/python3 /usr/share/system-config-printer/")
May 10 17:40:45 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.freedesktop.Notifications'
May 10 17:40:53 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating via systemd: service name='org.gtk.vfs.Metadata' unit='gvfs-metadata.service' requested by ':1.18' (uid=1000 pid=783 comm="/usr/bin/caja")
May 10 17:40:53 BASE1 systemd[650]: Starting Virtual filesystem metadata service...
May 10 17:40:53 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.gtk.vfs.Metadata'
May 10 17:40:53 BASE1 systemd[650]: Started Virtual filesystem metadata service.
May 10 17:40:56 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating service name='org.mate.panel.applet.ClockAppletFactory' requested by ':1.15' (uid=1000 pid=752 comm="mate-panel")
May 10 17:40:56 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Activating service name='org.mate.panel.applet.NotificationAreaAppletFactory' requested by ':1.15' (uid=1000 pid=752 comm="mate-panel")
May 10 17:40:56 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.mate.panel.applet.NotificationAreaAppletFactory'
May 10 17:40:56 BASE1 dbus-daemon[667]: [session uid=1000 pid=667] Successfully activated service 'org.mate.panel.applet.ClockAppletFactory'
May 10 17:40:57 BASE1 scp-dbus-servic[936]: gtk_widget_size_allocate(): attempt to allocate widget with width -1 and height 1
May 10 17:40:57 BASE1 scp-dbus-servic[936]: gdk_window_thaw_toplevel_updates: assertion 'window->update_and_descendants_freeze_count > 0' failed
May 10 17:40:58 BASE1 clock-applet[1014]: Negative content width -7 (allocation 1, extents 4x4) while allocating gadget (node button, owner GtkToggleButton)
May 10 17:40:59 BASE1 synergy[915]: *** WARNING *** The program 'synergy' uses the Apple Bonjour compatibility layer of Avahi.
May 10 17:40:59 BASE1 synergy[915]: *** WARNING *** Please fix your application to use the native API of Avahi!
May 10 17:40:59 BASE1 synergy[915]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
May 10 17:40:59 BASE1 synergy[915]: *** WARNING *** The program 'synergy' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
May 10 17:40:59 BASE1 synergy[915]: *** WARNING *** Please fix your application to use the native API of Avahi!
May 10 17:41:00 BASE1 synergy[915]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
May 10 17:53:06 BASE1 systemd[650]: Reached target Sound Card.

V1del · 2023-05-10 20:15:47

That journal is just userspace and does not cover kernel messages that would give hints here, post

sudo journalctl -b

https://wiki.archlinux.org/title/List_o … n_services

FWIW general things to test when "testing a slot directly in the MB" ensure you are actually on a different bus, currently all your devices are on the hub and via that on bus 5 which doesn't exactly surprise me that it might get bandwith issues.

alan1world · 2023-05-10 21:59:01

I forgot to mention that I have also tried routing the audio via a VM, using Virtualbox to take ownership of the USB audio device and it played the audio without any mouse interruption.
There's enough throughput to handle audio, mouse and keyboard.

sudo journalctrl -b here:

https://gist.github.com/alan1world/19aa … 525240a84d

I switched from mb audio to the usb audio and used the MATE audio applet to play a test sound to show the registration and operation of the USB audio.

V1del · 2023-05-10 23:34:42

Is this fresh from boot or after producing the issue? Not seeing anything glaringly obvious, try disabling usb autosuspend: https://wiki.archlinux.org/title/Power_ … utosuspend I suggest the sledgehammer of usbcore.autosupend=-1 on the kernel parameter for a first test and if that was the problem trying to isolate whether you need to disable for the mouse/headset and/or hub after.

alan1world · 2023-05-15 16:56:15

TL;DR - yes, bus saturation.

Straight after boot and immediately reproducing the error.

I realised I'd never connected my front panel audio and usb.
I also got a PCIE usb card.

In both cases, there was no lock up. It is only when the usb mouse and the usb audio are connected to the same bus.

Thank you for your help.

Arch Linux

#1 2023-05-10 17:58:47