Bisected slowness in 2.30.0 when initializing gamepads

[cspiegel]

Bisected slowness in 2.30.0 when initializing gamepads

[twhitehead]

Thanks for the very thorough report. I am having a look at this.

[parkerlreed]

This same bug affects WINE. Every fresh prefix start (Not already running) takes 4-8 seconds to load due to SDL init hanging the process.

DEBUG: Failed loading udev_device_get_action: /usr/lib/libSDL2-2.0.so.0: undefined symbol: _udev_device_get_action

[slouken]

@twhitehead, I merged your patch, thanks!

Can you create a PR against SDL main?

[radgeRayden]

@twhitehead I am not well versed enough in how to use gprof to test with that at the moment. What exactly do I compile with -pg? I tried adding it to the CFLAGS when building SDL2 (perhaps incorrectly) but did not get a gmon.out file when running my test program, and adding it to the program instead seems to get me empty profiling info.

Either way, I noticed there's a difference when running with or without my DualShock 4 controller. Re-tested with and without the controller connected, after restarting the computer (previous slow times were due to a rogue background process):

2.28.5:
disconnected: 820ms
connected: 1.22s

2.30.1:
disconnected: 4.14s
connected: 5.26s

walking:
disconnected: 1.65s
connected: 2.08s

[slouken]

Are you able to reproduce this with the SDL2 testgamecontroller program? There's a bunch of work that wine is doing in there that seems unrelated.

[slouken]

Start in LINUX_JoystickDetect() and sprinkle them throughout the functions being called there.

[slouken]

It seems odd that an open() call would take a long time. Did you add a print immediately afterwards to get the timing on that?

[slouken]

That is a neat tool.

It looks like you're not running the latest code with @twhitehead's changes. Inside SDL_UDEV_GetProductInfo() there is a call to udev_device_new_from_devnum() instead of udev_enumerate_scan_devices().

Can you try updating to the latest code from git and trying again?

[radgeRayden]

Removing all my USB peripherals takes me to an initialization time of ~1.15s.

[twhitehead]

Right. I reversed those when I cut and pasted into the comment. I changed it to SDL_TRUE. There was a routine that conditionally ets it to SDL_FALSE, so that may be triggering for you and not me.

[parkerlreed]

Holy crap this is kernel. I had used this kernel before as it's a 6.1 with Valve's patches included. Just tried it and it completely solves the issue

https://github.com/rog-ally-gaming/linux-chimeraos/releases/tag/6.1.81.nrflx3-2

[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m0.703s
user    0m0.062s
sys     0m0.070s

Samply https://share.firefox.dev/49dPNqc

[slouken]

@twhitehead, apparently using udev does hurt performance on some systems, can you take a look?

[twhitehead]

Looks like there might be an O(devices^2) issue in that

1. MaybeAddDevice gets called for every device at startup (I presume),
2. MaybeAddDevice calls IsJoystick
3. IsJoystick calls SDL_UDEV_GetProductInfo
4. SDL_UDEV_GetProductInfo calls udev_enumerate_scan_devices
5. udev_enumerate_scan_devices walks all the devices (I presume)

SDL_UDEV_GetProductInfo also walks the device enumeration list returned by udev_enumerate_scan_devices to try and match the original device. I presume this walk is a lot faster than udev_enumerate_scan_devices takes to build this list though.

So, ideally, we could query udev about a specific device instead of getting it to walk all of them and then find the one we are interested from that list. Or, failing that, we would need to cache the walk and reuse a single udev enumeration object on startup instead of building a new one for every call.

[slouken]

@twhitehead, do you have a PR to address this?

[twhitehead]

Not yet. It is on my TODO list. Just been super busy. Need to have a look at the uvdev functions to see if there is a better way to find a single device then enumerating them all. If not, will have to add a cache during startup,

[radgeRayden]

Was about to open an issue related to this. About 3 seconds to open an application when the gamepad subsystem is initialized (on 2.30 or 3.x), and if it's of any use, my DS4 controller also changes to a red light.

[twhitehead]

Problem is that udev does not track devices by the /dev/* paths, but this is what is plumed through SDL.

So we go udev_device -> /dev/* paths in the device_event call back -> through SDL -> /dev/* path -> udev_device in SDL_UDEV_GetProductInfo, where the final conversion it done by enumerating and looping over every udev_device and looking for a matching /dev/* path property for each call.

There are a few other ways you can get a udev_device other than enumerating them all. This doesn't directly include a /dev/* path, but it does include looking them up by character or block number. So I think we can stat the /dev/* path to get the character or block number and look that directly up with udev_device_new_from_devnum or udev_device_new_from_device_id.

I still have to find some time to do this though. Hopefully in the next week or two.

[twhitehead]

Was thinking more about this and was wondering if you could do a quick test to verify that the problem is indeed what I think it is.

If you strace the process, what is it doing during the 3 second pause? Is it busy poking around in /dev and /sys? Or is it stuck waiting for something to time out?

[radgeRayden]

I do happen to have poked around this already :)
Here's a run of love-11.5 built with SDL 2.30-1 (from arch repos), the good log is from a run of the default nogame screen which doesn't initialize SDL_INIT_GAMECONTROLLER, the bad log is from a run that does.
I then used sort bad.log | uniq -dc | sort -n | tail -n 100 > bad_count.txt to get the 100 most common lines in the strace, which can give you a feel for what's happening.

Unfortunately I can't upload the logs here because the bad log is 260MB. The good log is about 1.5. But here's a gist of the filtered version: https://gist.github.com/radgeRayden/07deaaa6ddab034dd439268282f90fc9

PS: to reproduce locally, this is the code for the bad demo:

love.event.quit()

This just quits the application immediately after initialization. For the good demo I ran love without arguments and then held Escape to quit as soon as possible.
Then:
strace love . 2&> bad.log
strace love 2&> good.log

Demoed with love because it was easier, but I can confirm the results are the same for my own application that uses SDL3.

[twhitehead]

Thanks. That definitely looks like a lot of poking around in /sys. 👍

[parkerlreed]

Applying this manual patch flathub/com.moonlight_stream.Moonlight@5f56948

Against Arch's SDL2 2.30 results in the same delay as far as WINE is concerned.

[parker@rogally sdl2]$ SDL_LOGGING=1 winecfg
DEBUG: Using udev for HIDAPI joystick device discovery
DEBUG: Failed loading udev_device_get_action: /usr/lib/libSDL2-2.0.so.0: undefined symbol: _udev_device_get_action
0070:err:ole:start_rpcss Failed to start RpcSs service
DEBUG: Using udev for joystick device discovery
DEBUG: Haptic: Unable to get device's features: Invalid argument

7 seconds to get to UI. Maybe a different SDL2 issue?

[slouken]

@twhitehead, I'll go ahead and revert your patch next week if you don't have a fix by then. The performance issue is critical here.

[parkerlreed]

I double checked installing the patch against lib32-sdl2 and see the same delay on startup

[parker@rogally ~]$ SDL_LOGGING=1 wine64 winecfg
DEBUG: Using udev for HIDAPI joystick device discovery
DEBUG: Failed loading udev_device_get_action: /usr/lib/libSDL2-2.0.so.0: undefined symbol: _udev_device_get_action
DEBUG: Using udev for joystick device discovery
006c:err:ole:start_rpcss Failed to start RpcSs service
DEBUG: Haptic: Unable to get device's features: Invalid argument
[parker@rogally ~]$ wineserver -k
[parker@rogally ~]$ SDL_LOGGING=1 wine winecfg
DEBUG: Using udev for HIDAPI joystick device discovery
DEBUG: Failed loading udev_device_get_action: /usr/lib/libSDL2-2.0.so.0: undefined symbol: _udev_device_get_action
DEBUG: Using udev for joystick device discovery
0074:err:ole:start_rpcss Failed to start RpcSs service
DEBUG: Haptic: Unable to get device's features: Invalid argument

[twhitehead]

Here is a patch that looks up devices in udev by type, major, and minor number instead of enumerating everything each time.

I can't fully test it as I am on the road and just have my laptop that just has keyboard and trackpad inputs, but it does compile and nothing seems to crash or otherwise go bad when I run the tests.

[slouken]

Thank you! @parkerlreed, @radgeRayden, @cspiegel, can you confirm this fixes the issue for you?

[cgutman]

A couple comments on the patch:

• We probably don't want to depend on statx() since that is only present starting with Linux 4.11 and glibc 2.28.
• It also looks like there's a typo where you mean S_IFCHR instead of S_IFBLK (should we use S_ISBLK()/S_ISCHR() instead?)

[parkerlreed]

I'm not at my usual setup that had as many devices to enumerate over so I can't tell if it's quicker because of that or from the patch.

I'm still seeing the get device action undefined symbol, so I'm not entirely sure what's going on there.

I won't be able to test the exact same hardware setup until Monday.

Thanks!

[twhitehead]

Yes that should have been S_IFCHR. Thanks @cgutman. I used statx as the regular stat didn't seem to give the major and minor numbers. Do you know a more backwards compatible way to get this info? Thanks!.

[sezero]

My stat(2) man page lists st_rdev as one of struct stat fields ?
dev_t st_rdev; /* device ID (if special file) */

[twhitehead]

@sezero I believe you are correct! It certainly has the correct type. So no need for statx at all, just me being brain dead. ll update the patch tonight for both of these items. Thanks!

[radgeRayden]

During my testing initializing with the 2.28.5 version took on average 1.85s, and the version from @twhitehead "walking" branch took an average of 3 seconds, down from 7 in the 2.30 release.

PS: not sure why all my numbers are so high, I have to re-check my setup. But hopefully the relative values are still indicative.

[twhitehead]

@radgeRayden sound's like thing are better then, but still not back to before. Any chance you can compile with -pg and use gprof to see where it is spending the time?

It is interesting the original took nearly 2s. On my machine, when I wrote the initial patch, I hadn't noticed any pauses at all. But then, I don't have a gamepad, so I only checked joysticks.

Wonder if there could be a specific device with long delays when probed for some reason? Perhaps stracing with one of the timestamp options (e.g., -r -t) might reveal on what most of that 3s is being spent too?

[cspiegel]

I just tried commit 3fbad6d from @twhitehead's repository, and compared to 857e5b0, which was the commit right before 3b1e0e1, it looks like there's no difference, i.e. this fixes it entirely for me:

$ ministat ORIG NEW
x ORIG
+ NEW
+-----------------------------------------------------------------------------+
|                                              +  x  *x    +  +               |
|   + x  xxx  ++    +   x   x x+     x  +    x *  x  *x   ++  +               |
|+ ++xx  xxxxx**+ x +***x x * *++ ++**+x++++ x+* *x x** ++**  + *   * x      x|
|              |___|_______________AM_A_M______________|_|                    |
+-----------------------------------------------------------------------------+
    N           Min           Max        Median           Avg        Stddev
x  50      0.520328      0.699575      0.598526    0.59526892   0.049579479
+  50      0.510248      0.677506      0.607219    0.60247724    0.04621728
No difference proven at 95.0% confidence

That's without a gamepad. With a gamepad (Xbox wireless), the initialization is ever so slightly slower for both commits, but they are still basically identical:

$ ministat ORIG-GAMEPAD NEW-GAMEPAD
x ORIG-GAMEPAD
+ NEW-GAMEPAD
+-----------------------------------------------------------------------------+
|                         +                                                   |
|                   +     +                             x                     |
|                  ++     +                 +     +     x                     |
|      +    x  * + ++ x x +       x+  x   xx+    x+     x                     |
|x x+xx+++ xx++* +x** x*x**xx x x x** xx+ x**x *xx+ +x+x**  *++ +x++x+   +   +|
|              |_|____________M___AA________________|___|                     |
+-----------------------------------------------------------------------------+
    N           Min           Max        Median           Avg        Stddev
x  50      0.551988      0.727843      0.639531    0.63843678   0.045489175
+  50      0.560849      0.750242     0.6289105    0.64195284   0.053395748
No difference proven at 95.0% confidence

[radgeRayden]

results of strace -r, sorted by time (with controller connected, walking branch):
timing.log

[parkerlreed]

Should I poke the WINE guys?

[parker@rogally ~]$ pacman -Q sdl2-git 
sdl2-git prerelease.2.29.2.r109.geb185e8d8-1
[parker@rogally ~]$ SDL_LOGGING=1 wine winecfg
DEBUG: Using udev for HIDAPI joystick device discovery
DEBUG: Failed loading udev_device_get_action: /usr/lib/libSDL2-2.0.so.0: undefined symbol: _udev_device_get_action
DEBUG: Using udev for joystick device discovery
0074:err:ole:start_rpcss Failed to start RpcSs service
DEBUG: Haptic: Unable to get device's features: Invalid argument

Video showing the delay

out.mp4

Input and hidraw devices

[parker@rogally ~]$ ls -lah /dev/hidraw*
crw------- 1 root root 245,  0 Mar 25 11:12 /dev/hidraw0
crw------- 1 root root 245,  1 Mar 25 11:12 /dev/hidraw1
crw------- 1 root root 245, 10 Mar 25 11:12 /dev/hidraw10
crw------- 1 root root 245, 11 Mar 25 11:12 /dev/hidraw11
crw------- 1 root root 245, 12 Mar 25 11:12 /dev/hidraw12
crw------- 1 root root 245, 13 Mar 25 11:12 /dev/hidraw13
crw------- 1 root root 245, 14 Mar 25 11:12 /dev/hidraw14
crw------- 1 root root 245,  2 Mar 25 11:12 /dev/hidraw2
crw------- 1 root root 245,  3 Mar 25 11:12 /dev/hidraw3
crw------- 1 root root 245,  4 Mar 25 11:12 /dev/hidraw4
crw------- 1 root root 245,  5 Mar 25 11:12 /dev/hidraw5
crw------- 1 root root 245,  6 Mar 25 11:12 /dev/hidraw6
crw------- 1 root root 245,  7 Mar 25 11:12 /dev/hidraw7
crw------- 1 root root 245,  8 Mar 25 11:12 /dev/hidraw8
crw------- 1 root root 245,  9 Mar 25 11:12 /dev/hidraw9
[parker@rogally ~]$ ls -lah /dev/input/
total 0
drwxr-xr-x   4 root root     820 Mar 25 11:12 .
drwxr-xr-x  19 root root    4.9K Mar 25 11:12 ..
drwxr-xr-x   2 root root     280 Mar 25 11:12 by-id
drwxr-xr-x   2 root root     600 Mar 25 11:12 by-path
crw-rw----   1 root input 13, 64 Mar 25 11:12 event0
crw-rw----   1 root input 13, 65 Mar 25 11:12 event1
crw-rw----   1 root input 13, 74 Mar 25 11:12 event10
crw-rw----+  1 root input 13, 75 Mar 25 11:12 event11
crw-rw----   1 root input 13, 76 Mar 25 11:12 event12
crw-rw----   1 root input 13, 77 Mar 25 11:12 event13
crw-rw----   1 root input 13, 78 Mar 25 11:12 event14
crw-rw----   1 root input 13, 79 Mar 25 11:12 event15
crw-rw----   1 root input 13, 80 Mar 25 11:12 event16
crw-rw----   1 root input 13, 81 Mar 25 11:12 event17
crw-rw----   1 root input 13, 82 Mar 25 11:12 event18
crw-rw----   1 root input 13, 83 Mar 25 11:12 event19
crw-rw----   1 root input 13, 66 Mar 25 11:12 event2
crw-rw----   1 root input 13, 84 Mar 25 11:12 event20
crw-rw----   1 root input 13, 85 Mar 25 11:12 event21
crw-rw----   1 root input 13, 86 Mar 25 11:12 event22
crw-rw----   1 root input 13, 87 Mar 25 11:12 event23
crw-rw----   1 root input 13, 88 Mar 25 11:12 event24
crw-rw----   1 root input 13, 89 Mar 25 11:12 event25
crw-rw----   1 root input 13, 90 Mar 25 11:12 event26
crw-rw----   1 root input 13, 91 Mar 25 11:12 event27
crw-rw----   1 root input 13, 92 Mar 25 11:12 event28
crw-rw----   1 root input 13, 67 Mar 25 11:12 event3
crw-rw----   1 root input 13, 68 Mar 25 11:12 event4
crw-rw----   1 root input 13, 69 Mar 25 11:12 event5
crw-rw----   1 root input 13, 70 Mar 25 11:12 event6
crw-rw----   1 root input 13, 71 Mar 25 11:12 event7
crw-rw----   1 root input 13, 72 Mar 25 11:12 event8
crw-rw----   1 root input 13, 73 Mar 25 11:12 event9
crw-rw-r--+  1 root input 13,  0 Mar 25 11:12 js0
crw-rw----   1 root input 13, 63 Mar 25 11:12 mice
crw-rw----   1 root input 13, 32 Mar 25 11:12 mouse0
crw-rw----   1 root input 13, 33 Mar 25 11:12 mouse1
crw-rw----   1 root input 13, 34 Mar 25 11:12 mouse2
crw-rw----   1 root input 13, 35 Mar 25 11:12 mouse3
crw-rw----   1 root input 13, 36 Mar 25 11:12 mouse4
crw-rw----   1 root input 13, 37 Mar 25 11:12 mouse5

[parkerlreed]

Oh I compiled SDL2 branch instead of Main. Retesting

EDIT: Oh wait that wont work anyways since Main is SDL3, woops.

EDIT2: I'm blind. SDL2 branch already got the patch. So yeah WINE is still having an issue.

[parkerlreed]

Currently bisecting this and an interesting note. 2.28.5 doesn't exhibit the undefined reference but still takes 4 seconds to load the UI.

sdl2-git-2.28.5.r0.g15ead9a40-1

[parker@rogally ~]$ SDL_LOGGING=1 winecfg
# UI pops up after 4 seconds

Strace log wine-sdl2.txt

[parkerlreed]

The strace seems to point out that since it can't load udev, the fallback is scanning the entirety of sysfs... Who is responsible I'm not sure.

openat(AT_FDCWD, "/sys/devices/system/cpu/cpu4/cache/index3/shared_cpu_map", O_RDONLY|O_LARGEFILE) = 10

Might not be related. I'll let smarter people than I parse that. :/

[slouken]

@parkerlreed, it looks like when udev fails joystick initialization also fails. I'm fixing that, but I'm guessing the time you're seeing is in LINUX_JoystickDetect(), can you confirm?

[parkerlreed]

Looks like it

strace with file access makes it obvious. The sys USB and hidraw enumeration is 4 seconds

115603 14:18:42 readlinkat(AT_FDCWD, "/sys/devices/pci0000:00/0000:00:08.1/0000:09:00.6/sound/card1/subsystem", "../../../../../../class/sound", 4096) = 29

to about

115611 14:18:46 openat(AT_FDCWD, "/dev/hidraw3", O_RDWR) = -1 EACCES (Permission denied)

wine-sdl2.txt

[parkerlreed]

That seems to come up within right around 2 seconds (Which is maybe still a tad long?)

File strace
testgamepad-sdl2.txt

Regular strace
testgamepad-strace-sdl2.txt

Yeah seems to still be doing the long enumeration

[parkerlreed]

(I realized I was still on 2.28 from wine testing but retested against SDL2 current branch and see the same)

testgamepad-sdl2.txt

[parkerlreed]

LD_DEBUG=all for testgamecontroller shows the same undefined references I was seeing earlier

    136429:     /usr/lib/libSDL2-2.0.so.0: error: symbol lookup error: undefined symbol: _udev_device_get_action (fatal)

[parkerlreed]

Does the underscore there mean anything? udev itself doesn't export a function starting with that

[parker@rogally test]$ nm -D /usr/lib/libudev.so| grep udev_device
000000000000ac80 T udev_device_get_action@@LIBUDEV_183
000000000000b7f0 T udev_device_get_current_tags_list_entry@@LIBUDEV_247
000000000000a8b0 T udev_device_get_devlinks_list_entry@@LIBUDEV_183
000000000000a7c0 T udev_device_get_devnode@@LIBUDEV_183
0000000000009a20 T udev_device_get_devnum@@LIBUDEV_183
000000000000a4d0 T udev_device_get_devpath@@LIBUDEV_183
0000000000009ba0 T udev_device_get_devtype@@LIBUDEV_183
0000000000009af0 T udev_device_get_driver@@LIBUDEV_183
000000000000b640 T udev_device_get_is_initialized@@LIBUDEV_183
0000000000009f90 T udev_device_get_parent@@LIBUDEV_183
000000000000a060 T udev_device_get_parent_with_subsystem_devtype@@LIBUDEV_183
000000000000ab00 T udev_device_get_properties_list_entry@@LIBUDEV_183
0000000000009d00 T udev_device_get_property_value@@LIBUDEV_183
0000000000009990 T udev_device_get_seqnum@@LIBUDEV_183
0000000000009c50 T udev_device_get_subsystem@@LIBUDEV_183
000000000000b370 T udev_device_get_sysattr_list_entry@@LIBUDEV_183
000000000000ae20 T udev_device_get_sysattr_value@@LIBUDEV_183
000000000000a660 T udev_device_get_sysname@@LIBUDEV_183
000000000000a710 T udev_device_get_sysnum@@LIBUDEV_183
000000000000a5a0 T udev_device_get_syspath@@LIBUDEV_183
000000000000b6e0 T udev_device_get_tags_list_entry@@LIBUDEV_183
000000000000a280 T udev_device_get_udev@@LIBUDEV_183
000000000000ad20 T udev_device_get_usec_since_initialized@@LIBUDEV_183
000000000000bae0 T udev_device_has_current_tag@@LIBUDEV_247
000000000000ba90 T udev_device_has_tag@@LIBUDEV_183
0000000000009ea0 T udev_device_new_from_device_id@@LIBUDEV_189
00000000000101c0 T udev_device_new_from_devnum@@LIBUDEV_183
0000000000011bb0 T udev_device_new_from_environment@@LIBUDEV_183
0000000000010850 T udev_device_new_from_subsystem_sysname@@LIBUDEV_183
0000000000009dc0 T udev_device_new_from_syspath@@LIBUDEV_183
000000000000a2d0 T udev_device_ref@@LIBUDEV_183
000000000000aed0 T udev_device_set_sysattr_value@@LIBUDEV_199
000000000000a350 T udev_device_unref@@LIBUDEV_183

[parkerlreed]

Oh it tries the underscore first but then appears to find it afterwards

   136429:     /usr/lib/libSDL2-2.0.so.0: error: symbol lookup error: undefined symbol: _udev_device_get_action (fatal)
    136429:     symbol=udev_device_get_action;  lookup in file=/usr/lib/libudev.so.1 [0]
    136429:     binding file /usr/lib/libudev.so.1 [0] to /usr/lib/libudev.so.1 [0]: normal symbol `udev_device_get_action'

So UDEV should be working? Wonder what's causing that to fail

[slouken]

Oh, it may not be failing. I just observed from code inspection that if udev fails, the joystick init will fail (when it doesn't need to)

[slouken]

Can you add print statements to the SDL code to find out what's taking the most time in the enumeration? The enumeration itself is just listing files in /dev/input, so it should be fairly quick. I'm guessing it's one of the udev calls that's taking a crazy amount of time on your system.

[parkerlreed]

Can you add print statements to the SDL code to find out what's taking the most time in the enumeration? The enumeration itself is just listing files in /dev/input, so it should be fairly quick. I'm guessing it's one of the udev calls that's taking a crazy amount of time on your system.

Where should I start throwing some prints in? SDL_udev.c?

[parkerlreed]

Starting with SDL_UDEV_Poll this only starts being called after the delay is over

[parker@rogally sdl2-git]$ ./src/SDL/test/testgamecontroller 
<delay here>
INFO: Rumble supported
INFO: XBox 360 Controller 0: X360 Controller, /dev/input/event11 (guid 030081b85e0400008e02000014010000, VID 0x045e, PID 0x028e, player index = 0)
INFO: There are 1 game controller(s) attached (1 joystick(s))
INFO: First
INFO: Second
INFO: Game controller device 0 added.
INFO: First
INFO: Second
INFO: First
INFO: Second

Moving onto the next function: LINUX_FallbackJoystickDetect

This IS being called

[parker@rogally sdl2-git]$ ./src/SDL/test/testgamecontroller 
INFO: FALLBACK
INFO: Rumble supported

Adding some more prints

[parker@rogally sdl2-git]$ ./src/SDL/test/testgamecontroller 
INFO: FALLBACK
INFO: FALLBACK ScanSteamVirtual
INFO: FALLBACK ScanInputDevices
<delay here>
INFO: FALLBACK last_input_dir_mtime
INFO: FALLBACK last_joy_detect_time
INFO: Rumble supported

Continuing with some timestamps. MaybeAddDevice seems to be the timesink

[parker@rogally sdl2-git]$ ./src/SDL/test/testgamecontroller 2>&1 | ts '[%Y-%m-%d %H:%M:%.S]'
[2024-03-25 16:34:31.746499] INFO: FALLBACK
[2024-03-25 16:34:31.746587] INFO: FALLBACK ScanSteamVirtual
[2024-03-25 16:34:32.810218] INFO: FALLBACK ScanInputDevices
[2024-03-25 16:34:32.810336] INFO: FALLBACK ScanInputDevices Begin
[2024-03-25 16:34:32.810352] INFO: FALLBACK ScanInputDevices Count Declare
[2024-03-25 16:34:32.810371] INFO: FALLBACK ScanInputDevices SDL_qsort
[2024-03-25 16:34:32.812050] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:32.812083] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:32.859504] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:32.859618] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:32.859631] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:32.886924] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:32.887042] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:32.887058] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:32.915771] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:32.915849] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:32.915865] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:32.945601] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:32.945687] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:32.945703] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:32.985634] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:32.985710] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:32.985723] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.025775] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.025842] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.025851] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.045601] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.045675] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.045690] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.119298] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.119375] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.119389] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.145802] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.145880] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.145896] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.195850] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.195973] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.195986] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.252309] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.252385] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.252399] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.318915] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.318999] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.319012] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.345601] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.345679] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.345698] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.385618] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.385756] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.385766] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.438960] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.439027] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.439036] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.507109] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.507228] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.507242] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.562434] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.562512] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.562528] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.626212] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.626331] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.626350] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.652258] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.652327] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.652336] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.682279] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.682356] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.682371] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.712739] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.712855] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.712870] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.789036] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.789155] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.789178] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.832447] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.832523] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.832537] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.882509] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.882618] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.882628] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.915780] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.915856] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.915870] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.945850] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.945967] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.945983] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:33.985672] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:33.985778] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:33.985789] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:34.012462] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:34.012587] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:34:34.012605] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:34:34.042717] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:34:34.042835] INFO: FALLBACK ScanInputDevices free 2
[2024-03-25 16:34:34.042849] INFO: FALLBACK last_input_dir_mtime
[2024-03-25 16:34:34.042860] INFO: FALLBACK last_joy_detect_time
[2024-03-25 16:34:34.074665] INFO: Rumble supported
[2024-03-25 16:34:34.074746] INFO: XBox 360 Controller 0: X360 Controller, /dev/input/event11 (guid 030081b85e0400008e02000014010000, VID 0x045e, PID 0x028e, player index = 0)
[2024-03-25 16:34:34.074762] INFO: There are 1 game controller(s) attached (1 joystick(s))
[2024-03-25 16:34:34.165381] INFO: Game controller device 0 added.

[parkerlreed]

Adding some prints to MaybeAddDevice now

[parkerlreed]

[parker@rogally sdl2-git]$ ./src/SDL/test/testgamecontroller 2>&1 | ts '[%Y-%m-%d %H:%M:%.S]'
[2024-03-25 16:42:43.610067] INFO: FALLBACK
[2024-03-25 16:42:43.610142] INFO: FALLBACK ScanSteamVirtual
[2024-03-25 16:42:44.737731] INFO: FALLBACK ScanInputDevices
[2024-03-25 16:42:44.737851] INFO: FALLBACK ScanInputDevices Begin
[2024-03-25 16:42:44.737866] INFO: FALLBACK ScanInputDevices Count Declare
[2024-03-25 16:42:44.737883] INFO: FALLBACK ScanInputDevices SDL_qsort
[2024-03-25 16:42:44.739495] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.739514] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.739523] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.739530] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.739537] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.739544] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.739551] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:44.796196] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:44.796315] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.796328] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.796339] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.796355] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.796366] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.796377] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.796387] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:44.815715] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:44.815793] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.815809] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.815827] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.815839] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.815851] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.815863] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.815875] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:44.856656] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:44.856778] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.856792] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.856803] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.856821] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.856832] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.856842] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.856853] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:44.875538] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:44.875654] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.875671] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.875685] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.875700] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.875713] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.875725] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.875738] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:44.915819] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:44.915898] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.915914] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.915931] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.915943] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.915955] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.915967] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.915980] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:44.946202] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:44.946321] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.946334] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.946348] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.946359] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.946370] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.946380] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.946391] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:44.969051] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:44.969127] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:44.969140] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:44.969152] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:44.969163] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:44.969174] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:44.969184] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:44.969195] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.019062] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.019138] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.019151] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.019164] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.019175] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.019186] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.019199] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.019210] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.036109] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.036187] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.036203] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.036216] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.036229] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.036241] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.036253] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.036265] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.088919] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.088998] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.089012] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.089024] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.089035] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.089046] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.089056] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.089067] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.162740] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.162862] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.162880] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.162893] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.162904] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.162915] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.162926] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.162937] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.212463] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.212585] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.212599] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.212612] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.212624] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.212635] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.212645] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.212657] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.229108] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.229345] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.229432] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.229500] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.229540] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.229570] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.229593] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.229610] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.262978] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.263098] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.263113] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.263129] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.263141] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.263153] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.263169] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.263181] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.326723] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.326843] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.326858] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.326871] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.326882] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.326893] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.326904] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.326915] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.382990] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.383110] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.383123] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.383137] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.383148] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.383159] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.383170] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.383182] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.442931] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.443049] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.443062] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.443073] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.443089] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.443099] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.443110] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.443121] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.499446] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.499567] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.499582] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.499595] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.499607] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.499618] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.499629] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.499640] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.516311] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.516430] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.516449] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.516464] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.516476] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.516489] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.516501] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.516513] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.542458] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.542575] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.542590] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.542603] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.542614] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.542625] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.542636] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.542646] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.582240] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.582318] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.582331] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.582345] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.582359] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.582373] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.582386] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.582398] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.662956] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.663079] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.663095] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.663110] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.663124] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.663140] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.663157] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.663171] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.732663] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.732741] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.732754] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.732766] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.732779] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.732793] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.732806] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.732819] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.798988] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.799112] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.799127] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.799140] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.799153] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.799167] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.799180] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.799193] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.849062] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.849139] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.849153] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.849166] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.849179] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.849192] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.849205] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.849218] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.875732] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.875810] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.875824] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.875838] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.875851] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.875865] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.875878] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.875890] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.905585] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.905662] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.905675] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.905688] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.905701] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.905714] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.905728] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.905740] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.932640] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.932764] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 16:42:45.932781] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 16:42:45.932803] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.932816] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.932828] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.932843] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 16:42:45.932856] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:42:45.972400] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 16:42:45.972477] INFO: FALLBACK ScanInputDevices free 2
[2024-03-25 16:42:45.972490] INFO: FALLBACK last_input_dir_mtime
[2024-03-25 16:42:45.972503] INFO: FALLBACK last_joy_detect_time
[2024-03-25 16:42:45.997425] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 16:42:45.997547] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 16:42:45.997563] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 16:42:45.997579] INFO: FALLBACK MaybeAddDevice Already Have This One
[2024-03-25 16:42:46.004906] INFO: Rumble supported
[2024-03-25 16:42:46.004989] INFO: XBox 360 Controller 0: X360 Controller, /dev/input/event11 (guid 030081b85e0400008e02000014010000, VID 0x045e, PID 0x028e, player index = 0)
[2024-03-25 16:42:46.005005] INFO: There are 1 game controller(s) attached (1 joystick(s))
[2024-03-25 16:42:46.092975] INFO: Game controller device 0 added.

[parkerlreed]

Most of the time seems tied up here

    SDL_Log("FALLBACK MaybeAddDevice fd open");
    fd = open(path, O_RDONLY | O_CLOEXEC, 0);

[parkerlreed]

I added a print to UnlockJosyticks but the time is still on the fd open/close side

[2024-03-25 16:52:33.702632] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 16:52:33.765755] INFO: FALLBACK SDL_UnlockJoysticks

[parkerlreed]

Good idea!

You guessed it. Not the fd

[2024-03-25 17:13:36.249487] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 17:13:36.249498] INFO: FALLBACK MaybeAddDevice fd close
[2024-03-25 17:13:36.305538] INFO: FALLBACK SDL_UnlockJoysticks
[2024-03-25 17:13:36.305616] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 17:13:36.305630] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 17:13:36.305643] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 17:13:36.305654] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 17:13:36.305665] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 17:13:36.305675] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 17:13:36.305686] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 17:13:36.305697] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 17:13:36.305710] INFO: FALLBACK MaybeAddDevice fd close
[2024-03-25 17:13:36.376831] INFO: FALLBACK SDL_UnlockJoysticks
[2024-03-25 17:13:36.376947] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 17:13:36.376961] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 17:13:36.376972] INFO: FALLBACK ScanInputDevices MaybeAddDevice

[parkerlreed]

I realized I was looking at the goto done immediately below the fd close not realizing it doesnt get called. Ill add some more more prints below this.

EDIT: So it doesnt hit the goto because doesnt print FALLBACK MaybeAddDevice fd lt 0 done but doesnt hit the rest? I added a bunch more prints but they never got hit

[2024-03-25 17:29:01.363295] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 17:29:01.363305] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 17:29:01.363316] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 17:29:01.363327] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 17:29:01.363338] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 17:29:01.363352] INFO: FALLBACK MaybeAddDevice fd close
[2024-03-25 17:29:01.432286] INFO: FALLBACK SDL_UnlockJoysticks

    SDL_Log("FALLBACK MaybeAddDevice fd open");
    fd = open(path, O_RDONLY | O_CLOEXEC, 0);
    SDL_Log("FALLBACK MaybeAddDevice fd close");
    if (fd < 0) {
        SDL_Log("FALLBACK MaybeAddDevice fd lt 0 done");
        goto done;
    }

#ifdef DEBUG_INPUT_EVENTS
    SDL_Log("Checking %s\n", path);
#endif

    if (IsJoystick(path, fd, &name, &vendor, &product, &guid)) {
#ifdef DEBUG_INPUT_EVENTS
        SDL_Log("found joystick: %s\n", path);
#endif
        SDL_Log("FALLBACK MaybeAddDevice item eq SDL_joylist_item");
        item = (SDL_joylist_item *)SDL_calloc(1, sizeof(SDL_joylist_item));
        SDL_Log("FALLBACK MaybeAddDevice item ne");
        if (!item) {
            SDL_Log("FALLBACK MaybeAddDevice item SDL_free");
            SDL_free(name);
            goto done;
        }


        item->devnum = sb.st_rdev;
        item->steam_virtual_gamepad_slot = -1;
        item->path = SDL_strdup(path);
        item->name = name;
        item->guid = guid;

        SDL_Log("FALLBACK MaybeAddDevice Valve Virtual Check");
        if (vendor == USB_VENDOR_VALVE &&
            product == USB_PRODUCT_STEAM_VIRTUAL_GAMEPAD) {
            GetSteamVirtualGamepadSlot(fd, &item->steam_virtual_gamepad_slot);
        }

        SDL_Log("FALLBACK MaybeAddDevice not item path or not item name");
        if ((!item->path) || (!item->name)) {
            SDL_Log("FALLBACK MaybeAddDevice FreeJoylistItem");
            FreeJoylistItem(item);
            goto done;
        }

        SDL_Log("FALLBACK MaybeAddDevice not SDL joylist tail");
        item->device_instance = SDL_GetNextJoystickInstanceID();
        if (!SDL_joylist_tail) {
            SDL_joylist = SDL_joylist_tail = item;
        } else {
            SDL_Log("FALLBACK MaybeAddDevice tail next");
            SDL_joylist_tail->next = item;
            SDL_joylist_tail = item;
        }

        /* Need to increment the joystick count before we post the event */
        SDL_Log("FALLBACK MaybeAddDevice Increment Joystick");
        ++numjoysticks;

        SDL_Log("FALLBACK MaybeAddDevice PrivateJoystickAdded");
        SDL_PrivateJoystickAdded(item->device_instance);
        goto done;
    }

[parkerlreed]

It's the second close???

    SDL_Log("FALLBACK MaybeAddDevice fd gt o eq 0 close");
    if (fd >= 0) {
        close(fd);
    }
    SDL_Log("FALLBACK MaybeAddDevice Close done");
    SDL_Log("FALLBACK SDL_UnlockJoysticks");
    SDL_UnlockJoysticks();
}

[2024-03-25 17:36:42.888811] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 17:36:42.888826] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 17:36:42.888839] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 17:36:42.888851] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 17:36:42.888863] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 17:36:42.888875] INFO: FALLBACK MaybeAddDevice fd close
[2024-03-25 17:36:42.889008] INFO: FALLBACK MaybeAddDevice fd gt o eq 0 close
[2024-03-25 17:36:42.928744] INFO: FALLBACK MaybeAddDevice Close done
[2024-03-25 17:36:42.928821] INFO: FALLBACK SDL_UnlockJoysticks

[parkerlreed]

For shits I removed that second close and it seems FINE

[2024-03-25 17:40:26.543610] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 17:40:26.543617] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 17:40:26.543625] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 17:40:26.543632] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 17:40:26.543640] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 17:40:26.543648] INFO: FALLBACK MaybeAddDevice fd close
[2024-03-25 17:40:26.543681] INFO: FALLBACK MaybeAddDevice fd gt o eq 0 close
[2024-03-25 17:40:26.543690] INFO: FALLBACK MaybeAddDevice Close done
[2024-03-25 17:40:26.543698] INFO: FALLBACK SDL_UnlockJoysticks
[2024-03-25 17:40:26.543705] INFO: FALLBACK ScanInputDevices free 1
[2024-03-25 17:40:26.543712] INFO: FALLBACK ScanInputDevices SDL_snprint
[2024-03-25 17:40:26.543720] INFO: FALLBACK ScanInputDevices MaybeAddDevice
[2024-03-25 17:40:26.543727] INFO: FALLBACK MaybeAddDevice Begin
[2024-03-25 17:40:26.543734] INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
[2024-03-25 17:40:26.543741] INFO: FALLBACK MaybeAddDevice SDL_joylist check
[2024-03-25 17:40:26.543749] INFO: FALLBACK MaybeAddDevice Sensor List
[2024-03-25 17:40:26.543757] INFO: FALLBACK MaybeAddDevice fd open
[2024-03-25 17:40:26.543764] INFO: FALLBACK MaybeAddDevice fd close
[2024-03-25 17:40:26.543797] INFO: FALLBACK MaybeAddDevice fd gt o eq 0 close
[2024-03-25 17:40:26.543806] INFO: FALLBACK MaybeAddDevice Close done
[2024-03-25 17:40:26.543813] INFO: FALLBACK SDL_UnlockJoysticks

[parkerlreed]

For reference this speedup was just removing this single close https://github.com/libsdl-org/SDL/blob/main/src/joystick/linux/SDL_sysjoystick.c#L511

[parkerlreed]

I told testgamecontroller to exit right before window creation.

Removing the close is not as big of a time sink as I thought.

INFO: FALLBACK MaybeAddDevice Begin
INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
INFO: FALLBACK MaybeAddDevice SDL_joylist check
INFO: FALLBACK MaybeAddDevice Already Have This One
INFO: FALLBACK MaybeAddDevice fd gt o eq 0 close
INFO: FALLBACK MaybeAddDevice Close done
INFO: FALLBACK SDL_UnlockJoysticks
INFO: Rumble supported
INFO: XBox 360 Controller 0: X360 Controller, /dev/input/event11 (guid 030081b85e0400008e02000014010000, VID 0x045e, PID 0x028e, player index = 0)
INFO: There are 1 game controller(s) attached (1 joystick(s))

real    0m2.534s
user    0m0.024s
sys     0m0.062s

Adding it back

INFO: FALLBACK MaybeAddDevice Begin
INFO: FALLBACK MaybeAddDevice SDL_LockJoysticks
INFO: FALLBACK MaybeAddDevice SDL_joylist check
INFO: FALLBACK MaybeAddDevice Already Have This One
INFO: FALLBACK MaybeAddDevice fd gt o eq 0 close
INFO: FALLBACK MaybeAddDevice Close done
INFO: FALLBACK SDL_UnlockJoysticks
INFO: Rumble supported
INFO: XBox 360 Controller 0: X360 Controller, /dev/input/event11 (guid 030081b85e0400008e02000014010000, VID 0x045e, PID 0x028e, player index = 0)
INFO: There are 1 game controller(s) attached (1 joystick(s))

real    0m2.639s
user    0m0.031s
sys     0m0.063s

[parkerlreed]

Sorry for the comment spam! Just an oddball of what could be causing the delay.

[twhitehead]

No problem from my end. I would like more to know what is going on.

With regard to the earlier questions at gprof and the -pg option. You need to provide it for compiling and linking.

I looked through the SDL2 autoconf build system, and my take was you need to set CFLAGS and LDFLAGS before running configure.

Running the program should produce a profile file you can then run gprof on. I'll mess around more with it once I get back.

[parkerlreed]

Today I learned about samply

Here's a profile link for running the testgamecontroller that I made exit before GUI

https://share.firefox.dev/496L8X3

[parkerlreed]

Each bump in the graph is a device being scanned... slowly hah.

Here's wine's profile. Same deal https://share.firefox.dev/3IRiM8v

Might be choking in systemd/udev itself

[parkerlreed]

Oh woops yeah. So we're flat with latest SDL2 branch but still taking a second or two to load

https://share.firefox.dev/3Pyex5J

EDIT: This is commit 5fff9bc

[parkerlreed]

perf might be capturing the controller test better

Happy to delve into anything there

[slouken]

Oh woops yeah. So we're flat with latest SDL2 branch but still taking a second or two to load

So we're basically back where we started. Great!

It still seems unusual that it would take 2 seconds on your system. Note that the CPU sampling is basically blank for most of that time, which means it's stuck in some IO call. Do you have any old devices connected to your system that might be having USB timeouts or anything?

[parkerlreed]

Unplugging my mess of a USB hub setup, 1.6s

https://share.firefox.dev/49dsIEj

Unloading xpad (ROG Ally built in controller is Xbox), 1.4s

https://share.firefox.dev/3TQhb9j

All I really have left is the built in ASUS keyboard buttons and the non functional fingerprint reader and Bluetooth

[parker@rogally sdl2-git]$ lsusb
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 045e:028e Microsoft Corp. Xbox360 Controller
Bus 001 Device 003: ID 0b05:1abe ASUSTek Computer, Inc. N-KEY Device
Bus 001 Device 004: ID 0489:e0f5 Foxconn / Hon Hai Wireless_Device
Bus 001 Device 005: ID 1c7a:0588 LighTuning Technology Inc. ETU905A86-E
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 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 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 007 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 008 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub

[parkerlreed]

Yeah I JUST saw the same. After running unbind on the ASUS, Xbox and fingerprint I'm just over a second

https://share.firefox.dev/4cyeoZE

[radgeRayden]

Tested adding the peripherals one by one, but only got a steady increase in loading time until I hit a result that varied between 1.85s-2s. Anecdotally I felt the steepest increases when adding the DS4 controller and my razer pro click mouse. Also adding my own results from samply: https://share.firefox.dev/3xcy859

[twhitehead]

Thanks for the nice profile info. From poking around on it (looking at the flame graphs, zooming in on the blank areas), I get the feeling this may be related to udev in general. For example, it looks to me like

• the first long delay may be the udev library loading
• there are a couple of times that udev_enumerate_scan_devices get called (although no nested ones as before the patch when people where getting really long delays)

Could there be some range of udev versions that suffer from very long IO waits? Maybe if we need to know what version of udev people that are experiencing the issue are running we would see a pattern. And maybe the distro too just in case
there is something distro specific about it.

[twhitehead]

For reference, if I change (edit: this is backwards)

static SDL_bool done = SDL_TRUE;

to SDL_FALSE in test/testgamecontroller.c so it exits right away, my runitime on my laptop (a very old Intel Core m5) is

[tyson@manny:~/SDL/SDL2/test]$ time ../outputs/out/libexec/installed-tests/SDL2/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real	0m0.068s
user	0m0.019s

which is so quick I don't get any useful profile information via grof as it is using a 0.01s sample interval.

I am running NixOS 23.11 with the systemd 254.6 udev.

[parkerlreed]

Arch Linux

systemd 255.4-2 (udev)

What testgamecontroller.c are you looking at? The file without any modifications as it stands has

static SDL_bool done = SDL_FALSE;

So that seems to have no affect on if it exits as that's the default value.

(Setting it to TRUE also doesn't exit...)

EDIT: Oh you dont have a gamepad connected. Let me test that.

Yeah the default is FALSE anyways so with no gamepad it exits and I see the delay

[parker@rogally test]$ time ./testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m2.134s
user    0m0.064s
sys     0m0.072s

[parkerlreed]

Attempted a downgrade to 254 and while I think the downgrade worked, still seeing the delay.

Kernel version for good measure

$ uname -a
Linux rogally 6.8.1-arch1-1 #1 SMP PREEMPT_DYNAMIC Sat, 16 Mar 2024 17:15:35 +0000 x86_64 GNU/Linux

[parkerlreed]

Ahh thanks. Yeah no gamepads and true same deal

[parker@rogally test]$ time ./testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m2.330s
user    0m0.061s
sys     0m0.080s

Going to test some older kernel versions and see how it fares.

[parkerlreed]

Interesting. 6.4 has a lower average

[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m1.985s
user    0m0.045s
sys     0m0.064s
[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m1.730s
user    0m0.058s
sys     0m0.058s
[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m1.617s
user    0m0.060s
sys     0m0.048s
[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m2.003s
user    0m0.087s
sys     0m0.061s

[parkerlreed]

Ok following a random hunch, back on 6.8.1, I saw in perf a bit of time was spent in CPU idle states.

Added cpuidle.off=1 to the kernel and this actually dropped it quite a bit

[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m1.682s
user    0m0.045s
sys     0m0.081s
[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m1.724s
user    0m0.050s
sys     0m0.071s
[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m1.734s
user    0m0.046s
sys     0m0.079s
[parker@rogally sdl2-git]$ time ./src/SDL/test/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m1.682s
user    0m0.037s
sys     0m0.088s

[parkerlreed]

Without cpuidle.off=1 (and making sure I was on latest amd-ucode) its back up to 2.0-25 seconds.

Been messing with CPU idle settings with cpupower but haven't had any meaningful effect.

[parkerlreed]

If I stress all 16 threads powertop looks like

Do nothing? This thing is idling as hard as it can

Could this be some CPU bug where it's not waking very fast from idle?

Z1 Extreme with the amd-pstate-epp driver

processor       : 15
vendor_id       : AuthenticAMD
cpu family      : 25
model           : 116
model name      : AMD Ryzen Z1 Extreme
stepping        : 1
microcode       : 0xa704104
cpu MHz         : 400.000
cache size      : 1024 KB
physical id     : 0
siblings        : 16
core id         : 7
cpu cores       : 8
apicid          : 15
initial apicid  : 15
fpu             : yes
fpu_exception   : yes
cpuid level     : 16
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_tsc rep_good amd_lbr_v2 nopl nonstop_tsc cpuid extd_apicid aperfmperf rapl pni pclmulqdq monitor ssse3 fma cx16 sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt tce topoext perfctr_core perfctr_nb bpext perfctr_llc mwaitx cpb cat_l3 cdp_l3 hw_pstate ssbd mba perfmon_v2 ibrs ibpb stibp ibrs_enhanced vmmcall fsgsbase bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local user_shstk avx512_bf16 clzero irperf xsaveerptr rdpru wbnoinvd cppc arat npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold v_vmsave_vmload vgif x2avic v_spec_ctrl vnmi avx512vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq rdpid overflow_recov succor smca flush_l1d
bugs            : sysret_ss_attrs spectre_v1 spectre_v2 spec_store_bypass srso
bogomips        : 6590.83
TLB size        : 3584 4K pages
clflush size    : 64
cache_alignment : 64
address sizes   : 48 bits physical, 48 bits virtual
power management: ts ttp tm hwpstate cpb eff_freq_ro [13] [14] [15]

Here's why I was looking at idle

[parkerlreed]

Taking the kernel work out here's just testgamecontroller

[parkerlreed]

For reference, if I change

static SDL_bool done = SDL_TRUE;

to SDL_FALSE in test/testgamecontroller.c so it exits right away, my runitime on my laptop (a very old Intel Core m5) is

[tyson@manny:~/SDL/SDL2/test]$ time ../outputs/out/libexec/installed-tests/SDL2/testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real	0m0.068s
user	0m0.019s

which is so quick I don't get any useful profile information via grof as it is using a 0.01s sample interval.

I am running NixOS 23.11 with the systemd 254.6 udev.

Still not quite as quick as this but damn close.

[parkerlreed]

And it's 0.7 regardless of how much USB I have hooked up so scanning seems completely solved.

Still curious as to why it's still 10x slower overall.

[twhitehead]

Just checked. I am running the stock NixOS Linux kernel 6.1.68. So that is in agreement with your observation of no slow down in 6.1.81. Wonder if I would see the issue if I switched to a 6.4 or 6.8 like you...

[twhitehead]

Seems NixOS won't let me use 6.4 as it has reached end of life. I did try with 6.5 though, and it seems to be fine

[tyson@manny:~/SDL/SDL2]$ uname -ar
Linux manny 6.5.13 #1-NixOS SMP PREEMPT_DYNAMIC Tue Nov 28 17:15:19 UTC 2023 x86_64 GNU/Linux

[tyson@manny:~/SDL/SDL2]$ time ./outputs/out/libexec/installed-tests/SDL2/testgamecontroller
INFO: There are 0 game controller(s) attached (0 joystick(s))

real	0m0.086s
user	0m0.030s
sys	0m0.033s

What if you use ebf-trace to do an off-cpu trace and flame graph to get an idea of what is happening at the IO level during the hangup?

[twhitehead]

I believe this works pretty good (using my distros bcc and flamegraph packages and running as root)

( sleep 10; exec ./outputs/out/libexec/installed-tests/SDL2/testgamecontroller; ) & offcputime -f 20 -p $! > testgamecontroller.log; flamegraph.pl testgamecontroller.log > testgamecontroller.svg

and then just view the svg file using your browser. Here is the one from my laptop running the 6.5.13 kernel.

[parkerlreed]

So even on the good kernel running with root is as slow as newer kernel?? (Getting the bpf stuff setup just noticed this in preparation)

[parker@rogally test]$ time ./testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m0.699s
user    0m0.061s
sys     0m0.076s
[parker@rogally test]$ time sudo ./testgamecontroller 
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m2.362s
user    0m0.006s
sys     0m0.004s

[parkerlreed]

Running under root (sudo su)

[parkerlreed]

Oh wow I didnt realize what you meant at first.... I've never seen an interactive SVG O.o

And Github just converts it... How did you upload yours?

I try attaching it a as file and it seems to do the same as yours but it wont let me interact with the result

[twhitehead]

I believe I may have uploaded it as an image, realized it was breaking the interaction, and cut and pasted the url into a markdown link instead of uploading it again. Or I may have just uploaded it again as a file and then cut and pasted that link into my markdown link. Can't recall.

[parkerlreed]

Here

Yep reformat into regular link works

So that's WITH sudo slowing it down. I tried unpriviledged bpf but can't get it working (to see the 0.7 second result)

[parkerlreed]

Running as user but offcputime with sudo worked

testgamecontroller

libusb maybe suspect?

[parkerlreed]

My best uneducated guess from looking at my svg is:

Most of my time is spent pre testgamecontorller init in early USB. If you just look at testgamecontroller, the execution time there is what is expected. So what could be causing a libsub hangup so early?

[twhitehead]

Yeah. It does seem like there is something USB related going on. Not sure if it is early or not though as the order is by function name and not time. The [unknown] entries lump everything together so you can't tell what is where.

With some googling and experimenting, it seems there are two items you need to fully resolve the stack traces

• everything compiled with -fno-omit-frame-pointer
• the program still running when bpftrace (i.e., offcputime) quits

The later isn't too bad as you can just add a sleep before main returns. The former is more tricky as you have to do all the dependencies too (a missing frame pointer higher up in the stack entirely obscures everything below it regardless of whether they have frame pointers or not).

I get the feeling this may be the default it Fedora and Ubuntu now though. It currently isn't the default in NixOS, but NixOS does give the ability to override everything, so I have done that and am rebuilding. It is a lot of packages though, so it will take a long time.

I think I can then package that as an RPM or DEB that you can install to test it and them remove to get rid of it. Assuming your system supports one of these formats?

[parkerlreed]

Arch I THINK defaults to omit (at least the local makepkg does I dont know how to confirm for official packages)

But I can easily compile official packages with the local makepkg so this should be doable.

CFLAGS="-march=x86-64 -mtune=generic -O2 -pipe -fno-plt -fexceptions \
        -Wp,-D_FORTIFY_SOURCE=3 -Wformat -Werror=format-security \
        -fstack-clash-protection -fcf-protection \
        -fno-omit-frame-pointer -mno-omit-leaf-frame-pointer"

[parkerlreed]

libsub recompiled (sdl2-git was already using the omit) still seeing a bunch of unknown. I'll see if I can figure out what those are supposed to be.

[twhitehead]

Good to hear that you can rebuild with -fno-omit-frame-pointer and -mno-omit-leaf-pointer.

With regard to running as root being slower on 6.1 as well, I wonder if you have a /dev or /sys file that is slow when probed and switched form being root accessible only under 6.1 to user accessible under 6.4?

Maybe doing

find /dev /sys -printf '%p %m %u %g\n' | sort

under both and diffing them might reveal something?

[parkerlreed]

So I just did that find for 6.1 on both user and root and I can visibly notice it taking longer to run for root... Going to add the timestamps to execution and see if anything pops out.

[twhitehead]

Look at /proc//maps to see what so files it sucks in while it is sleeping before exiting (some are dynamically loaded, so they won't show up with ldd).

[parkerlreed]

6.1 root taking longer may be due to the fact it exposes /sys/kernel/tracing/ which is a doozy

6.1 to 6.8 is oddly 2.2 MB smaller

6.1-user.txt
6.8-user.txt

[twhitehead]

In @radgeRayden's earlier strace -r log, I noticed some of the /dev/input/eventXX stats were taking between 1/10th and 1/100th of a second compared to the others which where 2/10,000th to 4/10,000th of a second.

To quote the output, which is sorted by time, we have a bunch in 0.000028 to 0.000061

     0.000028 newfstatat(AT_FDCWD, "/dev/input/event21", {st_mode=S_IFCHR|0660, st_rdev=makedev(0xd, 0x55), ...}, 0) = 0
...
     0.000061 newfstatat(AT_FDCWD, "/dev/input/event19", {st_mode=S_IFCHR|0660, st_rdev=makedev(0xd, 0x53), ...}, 0) = 0

and then, with nothing in between, a bunch more between 0.010 and 0.111

     0.010093 newfstatat(AT_FDCWD, "/dev/input/event21", {st_mode=S_IFCHR|0660, st_rdev=makedev(0xd, 0x55), ...}, 0) = 0
...
     0.105205 newfstatat(AT_FDCWD, "/dev/input/event14", {st_mode=S_IFCHR|0660, st_rdev=makedev(0xd, 0x4e), ...}, 0) = 0

[parkerlreed]

Ok we can safely narrow it down to /dev most likely. I mount overbinded a blank folder to /dev and 6.8 execution is quick

Only /sys being blank had no effect

[parker@rogally test]$ time ./testgamecontroller
INFO: There are 0 game controller(s) attached (0 joystick(s))

real    0m0.226s
user    0m0.057s
sys     0m0.071s