Project

General

Profile

Actions

Emulator Issues #13284

closed

On Linux, sleep-wake with GC adapter enabled causes Dolphin and journalctl to burn a full CPU core

Added by nyanpasu64 11 months ago. Updated 9 months ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
% Done:

0%

Operating system:
N/A
Issue type:
Bug
Milestone:
Regression:
No
Relates to usability:
No
Relates to performance:
No
Easy:
No
Relates to maintainability:
No
Regression start:
Fixed in:
5.0-19815

Description

  • Enable "GameCube Adapter for Wii U" input, with a GC adapter plugged in (I have a Mayflash).
  • Sleep and wake Linux.

journalctl will be flooded with "usb 1-7: usbfs: process 216494 (GCAdapter Read ) did not claim interface 0 before use" messages, and Dolphin's ReadThreadFunc() thread will spin burning a full CPU core.

I think this is because the thread loops forever on libusb_interrupt_transfer(), and after a sleep-wake cycle this function returns immediately, and we try again right away (after ProcessInputPayload(input_buffer.data(), payload_size) and Common::YieldCPU()), rather than checking for a broken connection to the GC controller adapter (invalid s_handle or s_endpoint_in) and restarting the thread.

I don't know USB well enough to know how to fix the error handling. Perhaps I could research it if necessary.

I'm running Dolphin dadbeb4bae7e7fa23af2b46e0add4143094dc107 with some unrelated build/feature patches on top (D-Bus sleep inhibition when emulation is started, whereas this bug can occur without even starting a game).

Operating System: Arch Linux
KDE Plasma Version: 5.27.5
KDE Frameworks Version: 5.107.0
Qt Version: 5.15.10
Kernel Version: 6.3.7-zen1-1-zen (64-bit)
Graphics Platform: X11
Processors: 12 × AMD Ryzen 5 5600X 6-Core Processor
Memory: 15.5 GiB of RAM
Graphics Processor: AMD Radeon RX 570 Series
Manufacturer: Gigabyte Technology Co., Ltd.
Product Name: B550M DS3H

Actions #1

Updated by nyanpasu64 11 months ago

oops submitted to Infrastructure

Actions #2

Updated by JosJuice 11 months ago

  • Tracker changed from Issue to Emulator Issues
  • Project changed from Infrastructure to Emulator
  • Issue type set to Bug
  • Regression set to No
  • Relates to usability set to No
  • Relates to performance set to No
  • Easy set to No
  • Relates to maintainability set to No
  • Operating system N/A added
Actions #3

Updated by nyanpasu64 11 months ago

If I increase the log level to Error (apparently Notice silences all errors and only prints state-change events?), I see the following messages:

35:18:717 InputCommon/GCAdapter.cpp:211 E[CI]: Read: libusb_interrupt_transfer failed: Input/Output Error (-1: LIBUSB_ERROR_IO)
35:18:717 InputCommon/GCAdapter.cpp:775 E[CI]: error reading payload (size: 0, type: 21)
35:18:717 InputCommon/GCAdapter.cpp:211 E[CI]: Read: libusb_interrupt_transfer failed: Input/Output Error (-1: LIBUSB_ERROR_IO)
35:18:717 InputCommon/GCAdapter.cpp:775 E[CI]: error reading payload (size: 0, type: 21)
...

If I instead unplug the adapter, I see the following:

37:46:466 InputCommon/GCAdapter.cpp:211 E[CI]: Read: libusb_interrupt_transfer failed: No such device (it may have been disconnected) (-4: LIBUSB_ERROR_NO_DEVICE)
37:46:466 InputCommon/GCAdapter.cpp:775 E[CI]: error reading payload (size: 0, type: 21)
37:46:466 InputCommon/GCAdapter.cpp:211 E[CI]: Read: libusb_interrupt_transfer failed: No such device (it may have been disconnected) (-4: LIBUSB_ERROR_NO_DEVICE)
37:46:466 InputCommon/GCAdapter.cpp:775 E[CI]: error reading payload (size: 0, type: 21)
37:46:467 InputCommon/GCAdapter.cpp:211 E[CI]: Read: libusb_interrupt_transfer failed: No such device (it may have been disconnected) (-4: LIBUSB_ERROR_NO_DEVICE)
37:46:467 InputCommon/GCAdapter.cpp:775 E[CI]: error reading payload (size: 0, type: 21)
37:46:467 InputCommon/GCAdapter.cpp:297 N[CI]: GCAdapter write thread stopped
37:46:467 InputCommon/GCAdapter.cpp:249 N[CI]: GCAdapter read thread stopped
37:46:467 InputCommon/GCAdapter.cpp:724 N[CI]: GC Adapter detached

and the errors do not continue forever.

(hard) Changing control flow

During setup, you call libusb_hotplug_register_callback and pass in function HotplugCallback. When the adapter is unplugged, HotplugCallback is called which tears down the adapter.

When you sleep-wake, HotplugCallback is never called and libusb_interrupt_transfer instead fails with -1 LIBUSB_ERROR_IO. How should we handle this?

https://libusb.sourceforge.io/api-1.0/group__libusb__syncio.html#ga0f171a72904a552fc43e6e6564d108a3 mentions:

You should also check the transferred parameter for interrupt writes. Not all of the data may have been written.

Also check transferred when dealing with a timeout error code. libusb may have to split your transfer into a number of chunks to satisfy underlying O/S requirements, meaning that the timeout may expire after the first few chunks have completed. libusb is careful not to lose any data that may have been transferred; do not assume that timeout conditions indicate a complete lack of I/O. See Timeouts for more details.

We don't seem to check the "actual length" of the transfer. Is that a problem? Who knows, but it's not the cause of the sleep-wake issue. And we still need to properly handle LIBUSB_ERROR_IO.

Logically it would make sense to call Reset() when ReadThreadFunc() fails. But Reset() joins the s_read_adapter_thread handle, which is nonsensical to do on the thread itself. If we don't want to rewrite the relevant subset of Reset() to be callable on ReadThreadFunc() itself, we'd have to do something like make Context::Impl::EventThread() check not only libusb_handle_events_timeout_completed() (which ignores devices going invalid), but polling on a dup of a "should reset" eventfd signalled by ReadThreadFunc() when it's exiting prematurely... oh god this code needs to work on Windows too...

(easier) Fixing the existing libusb_device_handle

If you don't want to reset the whole thing, I noticed that libusb_kernel_driver_active() is once again set to 1 after sleep-wake and libusb_interrupt_transfer() == LIBUSB_ERROR_IO. So we could factor out the "libusb_detach_kernel_driver() if needed" code into a separate function, and call it upon LIBUSB_ERROR_IO, and if it fails kill the GC thread (no GC input is better than burning a CPU core and flooding the Linux kernel log). I've mocked up an implementation at https://github.com/nyanpasu64/dolphin/commits/gc-adapter-sleep-detach (the diffs are correct, but this branch is based on an older revision and has other unrelated changes as well).

Actions #4

Updated by nyanpasu64 11 months ago

I've talked to someone who suggested calling libusb_reset_device() whenever we received an IO error, to trigger a replug event. In practice I found that it seems to succeed (return 0), not trigger a hotplug event, and make the GC adapter work again in-game. https://github.com/nyanpasu64/dolphin/commits/gc-adapter-sleep-reset

The person also said that to reliably reconnect to "zombie devices" which don't return LIBUSB_ERROR_IO on access, you should watch a monotonic clock and drop/reload all devices if it jumps forward in time (a heuristic for guessing when a sleep wake occurred). This is difficult to slot into the current Context::Impl::EventThread() code, and doesn't seem necessary on my system, so I have not tried implementing it.

Additionally my code changes do not fix ReadThreadFunc() still entering an infinite loop if the device is not detected as unplugged, and throws an error other than LIBUSB_ERROR_IO. I don't know whether and how to fix this.

Actions #5

Updated by JosJuice 9 months ago

  • Status changed from New to Fixed
  • Fixed in set to 5.0-19815
Actions

Also available in: Atom PDF