[Bug 60251] New: ~29s stall on ntdll loader_section during startup, tied to a Win32_LogicalDiskToPartition WMI query on the Z: drive
http://bugs.winehq.org/show_bug.cgi?id=60251 Bug ID: 60251 Summary: ~29s stall on ntdll loader_section during startup, tied to a Win32_LogicalDiskToPartition WMI query on the Z: drive Product: Wine Version: 11.16 Hardware: x86-64 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: wmi&wbemprox Assignee: wine-bugs@list.winehq.org Reporter: aktaskazimcan0@gmail.com Target Milestone: --- Distribution: --- Created attachment 81964 --> http://bugs.winehq.org/attachment.cgi?id=81964 WINEDEBUG=+loaddll,+wbemprox trace showing the loader_section stall Note on environment: I'm running this under a Vinegar-managed prefix with DXVK-Sarek installed (native d3d8/d3d9/d3d10core/d3d11/dxgi overrides) and a custom Wine build (see "Additional information" below). I'm flagging this upfront per the Wine bug-reporting guidelines around native DLL overrides/third-party builds. That said, the stall happens while loading comctl32/compstui/winspool/wbemprox - none of the DLLs DXVK overrides - so it's unlikely to be DXVK-related, but I wanted to be transparent about the setup rather than have that surface later. Description of problem: On startup, my application (Roblox Studio, running under a Vinegar-managed prefix on Linux/CachyOS, btrfs root) consistently stalls for ~29 seconds early in startup, blocking the whole process. With WINEDEBUG=+loaddll,+wbemprox, the trace shows wbemprox.dll being loaded, followed by a ~29 second gap with *no trace output at all* on either channel, during which four other threads time out waiting on the ntdll loader_section (held by the thread that loaded wbemprox.dll). Full trace excerpt attached (winedebug-loaddll-wbemprox-trace.log). After the gap, thread 00fc proceeds through WbemLocator_create -> ConnectServer(ROOT\CIMV2) -> ExecQuery with an ASSOCIATORS query against Win32_LogicalDisk.DeviceID='Z:' (AssocClass=Win32_LogicalDiskToPartition). This query then resolves within the same second (fill_logicaldisktopartition created 1 rows, etc.) - the ~29s delay appears to happen *before* the WMI call chain is even entered (DllGetClassObject itself is the first thing logged after the gap), not within WMI processing itself. I was not able to pin down the exact syscall/operation responsible for the gap via strace - the slowest filesystem-related syscalls captured were on the order of tens of milliseconds, nowhere near 29s, so it does not appear to be filesystem/disk I/O bound in any obvious way. Happy to gather additional traces (e.g. a specific WINEDEBUG channel, or strace focused on a narrower window) if that would help narrow it down further. This reproduces consistently (every launch) on this system. How reproducible: Always (on this system) Steps to reproduce: 1. Launch an application that performs a Win32_LogicalDiskToPartition ASSOCIATORS WMI query against a drive early in startup (observed with Roblox Studio; have not yet tried a minimal WMI-only reproducer). 2. Run with WINEDEBUG=+loaddll,+wbemprox and observe the gap between wbemprox.dll loading and the first wbemprox trace line. Actual results: ~29 second stall, with the whole process blocked (other threads time out on the loader lock). Expected results: No significant stall before the WMI query executes. Additional information: - Wine version: wine-11.16 (custom build via vinegarhq/kombucha, built from upstream Wine commit 8da89f8493b21ebfbe344a54dbef0cde23c7ea59). This build carries 14 local patches; two touch ntdll (one adjusts LFH heap block-group lifetime in dlls/ntdll/heap.c, one narrows known-DLL/ search-path handling specifically for ucrtbase.dll in dlls/ntdll/loader.c - both ported from Valve's Wine/Proton fork). The ucrtbase.dll one does touch find_dll_file/open_known_dll in loader.c, though its actual behavior change is gated on the DLL name being "ucrtbase.dll" specifically, not wbemprox.dll/comctl32.dll/winspool.drv (the DLLs involved in this stall) - so it looks unlikely to be the direct cause, but I can't fully rule out an indirect interaction given it's in the same loader path. Neither patch touches wmi/wbemprox code directly. Happy to attempt a repro against a clean upstream Wine build if that would help isolate this. - Distro: CachyOS (Arch-based), root filesystem is btrfs - The affected drive (Z:) maps to the Linux root filesystem -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 --- Comment #1 from Ken Sharp <imwellcushtymelike@gmail.com> --- DXVK and custom builds are not supported. Try again with real Wine. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 --- Comment #2 from Kazim <aktaskazimcan0@gmail.com> --- (In reply to Ken Sharp from comment #1)
DXVK and custom builds are not supported. Try again with real Wine.
Understood, thank you. I'll set up a clean environment without DXVK/local patches and retest to confirm whether this reproduces there too. Will follow up with results. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 --- Comment #3 from Kazim <aktaskazimcan0@gmail.com> --- Created attachment 81967 --> http://bugs.winehq.org/attachment.cgi?id=81967 Minimal reproducer, no DXVK/Roblox involved Update: I isolated this further and it is not DXVK/custom-build related - the actual trigger is a third-party VPN/proxy application (Throne, sing-box-based) running in TUN mode. I wrote a minimal reproducer that just does CoInitializeEx -> CoCreateInstance(CLSID_WbemLocator, CLSCTX_INPROC_SERVER) -> ConnectServer(ROOT\CIMV2) and prints a timestamp after each step (source attached, wmitest.c - compiled with MinGW, no DXVK/Direct3D/Roblox involved at all). Results, varying only Wine build and whether the VPN app's TUN interface is active: | VPN off | VPN on -------------------------------------------- custom Wine (this build) | 16 ms | 29830 ms stock Wine (fresh prefix,| 14 ms | 29821 ms distro package, never | | touched before) | | Same binary, same steps, same machine. The only variable that matters is whether the VPN app's TUN interface is up. Wine build (custom vs. a completely fresh prefix with the distro's stock wine package) makes no measurable difference - 2ms apart when the VPN is off (16 vs 14 ms), 9ms apart when it's on (29830 vs 29821 ms), both trivial next to the ~29.8s swing tied to the VPN toggle. So the local patches and DXVK-Sarek I mentioned in the original report can be ruled out; sorry for not catching this before the initial report. In both "VPN on" runs, CoCreateInstance(WbemLocator) itself is what takes the ~29.8s (ConnectServer then fails immediately after with WBEM_E_INVALID_NAMESPACE, likely because this particular VPN setup doesn't have a working RPC/WMI backend in the test prefix - that failure is expected and not the interesting part). Given CLSCTX_INPROC_SERVER is requested, CoCreateInstance shouldn't need to touch the network at all for a local in-proc COM server - my guess is something in Wine's COM/RPCSS local-server activation path performs a network-touching operation (hostname resolution, or opening some kind of loopback/network socket as part of RPC endpoint setup) that would normally resolve instantly, but this particular VPN app's TUN mode intercepts *all* traffic including what should be purely local/loopback, and that request ends up stuck behind the same kind of slow-path behavior I was tracking down in the original report (I don't have visibility into the VPN app's internals to say more precisely what happens to the request once it's intercepted). I want to be upfront that I have not identified the specific syscall or Wine source location responsible for the network touch inside CoCreateInstance - I can see that it happens and precisely what makes it fast vs. slow, but not the "why" at the Wine source level. Happy to gather more targeted traces (e.g. strace during just this reproducer, or a specific WINEDEBUG channel) if that would help pin it down further. I'm also going to file a separate report against the VPN application's own project, since it seems reasonable that a TUN interface should not intercept purely local/loopback traffic - but wanted to update this report first since it changes the diagnosis substantially from the original DXVK-adjacent framing. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 --- Comment #4 from Hans Leidekker <hans@meelstraat.net> --- (In reply to Kazim from comment #3)
In both "VPN on" runs, CoCreateInstance(WbemLocator) itself is what takes the ~29.8s (ConnectServer then fails immediately after with WBEM_E_INVALID_NAMESPACE, likely because this particular VPN setup
Are you sure about that? CoCreateInstance() is essentially a malloc() call but ConnectServer() taking a long time would explain it. It resolves the hostname which will time out if there's no response. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 --- Comment #5 from Kazim <aktaskazimcan0@gmail.com> ---
Are you sure about that? CoCreateInstance() is essentially a malloc() call but ConnectServer() taking a long time would explain it. It resolves the hostname which will time out if there's no response.
Good question — I can answer that from the same reproducer's per-step timestamps, though I only posted the summary table above, not the raw per-call breakdown. Across every run I did (both Wine builds, TUN on and off): the elapsed time printed right after ConnectServer() is always within 0-2ms of the value printed right after CoCreateInstance() — e.g. 29830ms then 29830ms, 29821ms then 29821ms, 14ms then 16ms, 17ms then 17ms. So ConnectServer() itself is consistently near-instant (it fails fast with WBEM_E_INVALID_NAMESPACE either way) — it's CoCreateInstance() that swings from ~15ms to ~29800ms depending on TUN state, a ~2000x difference that has nothing to do with ConnectServer()'s hostname resolution. That matches your point about CLSCTX_INPROC_SERVER not needing the network — which is why I flagged it as surprising rather than claiming to understand the mechanism. Happy to strace just the CoCreateInstance() window with TUN on to see which syscall it's blocked in, or paste the full per-run logs here if that's easier to review. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 --- Comment #6 from Kazim <aktaskazimcan0@gmail.com> --- I traced the exact syscall this reproducer blocks on — it's not WMI/ConnectServer's own logic. Wine's OLE/COM init also probes for a local CUPS server on startup, opening both an IPv6 (::1:631) and IPv4 (127.0.0.1:631) connection. The IPv4 probe returns ECONNREFUSED in ~15ms as expected. The IPv6 probe never completes — it hangs until a ~30s connect timeout. I isolated this further, with no Wine involved at all: a plain Python socket.connect(('::1', 631)) under the same VPN/TUN setup times out at 35s (my test ceiling), while ('127.0.0.1', 631) refuses instantly. With the VPN's TUN mode off, both return instantly. So this looks like a bug in the VPN's TUN implementation (it isn't excluding IPv6 loopback from the tunnel, while IPv4 loopback is excluded correctly) rather than anything in Wine. I'll file this upstream with the VPN project. Given that, I think this can likely be closed as not-a-Wine-bug, unless you'd still want Wine's CUPS probe to use a shorter timeout as a defensive measure regardless of the cause. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 --- Comment #7 from Hans Leidekker <hans@meelstraat.net> --- (In reply to Kazim from comment #6)
I'll file this upstream with the VPN project. Given that, I think this can likely be closed as not-a-Wine-bug, unless you'd still want Wine's CUPS probe to use a shorter timeout as a defensive measure regardless of the cause.
Let's close this. I think the CUPS issue has already been reported. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 Kazim <aktaskazimcan0@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|UNCONFIRMED |RESOLVED Resolution|--- |NOTOURBUG --- Comment #8 from Kazim <aktaskazimcan0@gmail.com> ---
Let's close this. I think the CUPS issue has already been reported.
Agreed, closing as NOTOURBUG. Thanks for the back-and-forth — the CLSCTX_INPROC_SERVER skepticism is what pointed me toward looking at the actual syscalls instead of assuming ConnectServer() itself. Filed against Throne (thronep/Throne#1814) for the IPv6 loopback handling. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=60251 Zeb Figura <z.figura12@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |z.figura12@gmail.com --- Comment #9 from Zeb Figura <z.figura12@gmail.com> --- (In reply to Ken Sharp from comment #1)
DXVK and custom builds are not supported. Try again with real Wine.
This is not as helpful as you think it is; yes, they're not supported, but in cases like this it's clear that it has nothing to do with the bug. I know people not familiar with the project (let alone AI) can misdiagnose, but that's better left up to a developer than always yelling at people for using unsupported components. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
participants (1)
-
WineHQ Bugzilla