Program hangs in spinlocks under Wine but not on Windows

[John Nagle]

My metaverse client, Sharpview, is written in safe Rust, and cross-compiled from Linux (22.04.2 LTS) to a Windows executable using MinGW. It's built with

Code: Select all

cargo build --release --target x86_64-pc-windows-gnu

When run natively on LInux, it runs fine.

When run on real Windows, it runs fine.

When run under Wine, almost all of the 18 asset loading threads go compute-bound in a Windows spinlock. All 12 CPUs go compute-bound. The program runs very slowly, with but doesn't fail. Eventually, it finishes loading all the assets from disk cache and starts working normally.

So I ran it under winedbg. Waited until it hung, pressed cntl-C, and looked at the situation. Here's what a stuck thread looks like:

Code: Select all

Wine-dbg>bt
Backtrace:
=>0 0x0000017000eba4 in ntdll (+0xeba4) (0x000000003400e0)
  1 0x00000170063994 _InterlockedCompareExchange(addr=00000000003400E0, cmp=0000000170082D68, size=0x4, timeout=0000000006EDE638) [Z
:\usr\src\packages\BUILD\include\winnt.h:6630] in ntdll (0x000000003400e0)
  2 0x00000170063994 spin_lock(addr=<register RBP not accessible in this frame>, cmp=<register R13 not accessible in this frame>, si
ze=<register RSI not accessible in this frame>, timeout=<register R12 not accessible in this frame>) [Z:\usr\src\packages\BUILD\dlls
\ntdll\sync.c:937] in ntdll (0x000000003400e0)
  3 0x00000170063994 RtlWaitOnAddress+0x164(addr=<register RBP not accessible in this frame>, cmp=<register R13 not accessible in th
is frame>, size=<register RSI not accessible in this frame>, timeout=<register R12 not accessible in this frame>) [Z:\usr\src\packag
es\BUILD\dlls\ntdll\sync.c:937] in ntdll (0x000000003400e0)
  4 0x00000170063c53 wait_semaphore+0x43(timeout=<internal error>, crit=<internal error>) [Z:\usr\src\packages\BUILD\dlls\ntdll\sync
.c:197] in ntdll (0x00000006ede638)
  5 0x00000170063c53 RtlpWaitForCriticalSection+0xa3(crit=<register RBX not accessible in this frame>) [Z:\usr\src\packages\BUILD\dl
ls\ntdll\sync.c:303] in ntdll (0x00000006ede638)
  6 0x00000170064761 RtlEnterCriticalSection+0x91(crit=<register RBX not accessible in this frame>) [Z:\usr\src\packages\BUILD\dlls\
ntdll\sync.c:412] in ntdll (0x000000183301b0)
  7 0x0000017002bf84 heap_lock+0x15(flags=<internal error>, heap=<internal error>) [Z:\usr\src\packages\BUILD\dlls\ntdll\heap.c:506]
 in ntdll (0x000000183301b0)
  8 0x0000017002bf84 RtlFreeHeap+0x40c(handle=<register RDI not accessible in this frame>, flags=<register R12 not accessible in thi
s frame>, ptr=<register RBX not accessible in this frame>) [Z:\usr\src\packages\BUILD\dlls\ntdll\heap.c:512] in ntdll (0x00000018330
1b0)
  9 0x0000017002d763 RtlFreeHeap+0xe(ptr=<internal error>, flags=<internal error>, handle=<internal error>) [Z:\usr\src\packages\BUI
LD\dlls\ntdll\heap.c:1573] in ntdll (0x000000183301b0)
  10 0x0000017002d763 RtlReAllocateHeap+0x423(handle=<register RDI not accessible in this frame>, flags=<register R13 not accessible
 in this frame>, ptr=<register RBX not accessible in this frame>, size=<register RSI not accessible in this frame>) [Z:\usr\src\pack
ages\BUILD\dlls\ntdll\heap.c:1700] in ntdll (0x000000183301b0)
 11 0x0000014048c115 in sharpview (+0x48c115) (0x00000000000045)
 12 0x0000014048d721 in sharpview (+0x48d721) (0x00000000000045)
  ...

So it's stuck in a spinlock in [Z:\usr\src\packages\BUILD\dlls\ntdll\sync.c:937] in ntdll
See the attachment for the full backtrace.

This seems to be in a heap re-allocation.

This is safe Rust, and the program runs normally except for this stall. So it's probably not heap corruption. It's some kind of locking stall, due to a spinlock being used on something that sometimes is slow. What I suspect here is that Wine has to block when expanding the heap, and RtlFreeHeap assumes that frees are fast and uses spinlocks.

The program is doing extensive graphics using Vulkan, which might somehow be involved.

Wine questions:

- Anyone seen this before?

- How can I get winedbg to find my program's debugger symbols? When the stack backtrace gets back into the Rust code, it doesn't provide any info. The executable does have debugger symbols. I even tried using a debug build, which is even slower, and winedbg didn't find debugging information.

- Where is the source for "Z:\usr\src\packages\BUILD\include\winnt.h:6630". It's not there on my system. I have no \usr\src\packages\BUILD. That seems to refer to a Wine-provided DLL.

[John Nagle]

Usual requested info:

wine --version : wine-8.0.1
rustc --version : rustc 1.69.0 (84c898d65 2023-04-16)
lsb_release -d : Description: Ubuntu 22.04.2 LTS

Used winetricks: No.
Overrides in winecfg: No.
Non-default registry settings: No.

[jkfloris]

- Where is the source for "Z:\usr\src\packages\BUILD\include\winnt.h:6630". It's not there on my system. I have no \usr\src\packages\BUILD. That seems to refer to a Wine-provided DLL.

Sorry I can't answer your other questions, but you can find the files on source.winehq.org:
Z:\usr\src\packages\BUILD\dlls\ntdll\sync.c:937
Z:\usr\src\packages\BUILD\include\winnt.h:6630

[John Nagle]

That's a step forward. The line numbers don't quite match, but we have function names for the DLL.

What seems to have happened is that the memory allocator is doing a "realloc" by calling [RtlReallocateHeap](https://source.winehq.org/git/wine.git/ ... ap.c#l2239) . That's what happens when you grow an array in Rust. If the current memory buffer can be expanded in place, that's done, and this is a cheap operation. Otherwise, a new buffer is allocated, the contents are copied, and the old buffer is freed.

The stack shows this taking the long path. The allocation went OK, and it's freeing the old buffer b calling [RtlFreeHeap](https://source.winehq.org/git/wine.git/ ... ap.c#l2089)

That calls [heap_lock](https://source.winehq.org/git/wine.git/ ... ap.c#l2089), which, reasonably enough calls [RtlEnterCriticalSection](), which calls [RtlpWaitForCriticalSection](https://source.winehq.org/git/wine.git/ ... ync.c#l385),

And there's the first spin lock:

Code: Select all

 392         for (count = crit->SpinCount; count > 0; count--)
 393         {
 394             if (crit->LockCount > 0) break;  /* more than one waiter, don't bother spinning */
 395             if (crit->LockCount == -1)       /* try again */
 396             {
 397                 if (InterlockedCompareExchange( &crit->LockCount, 0, -1 ) == -1) goto done;
 398             }
 399             YieldProcessor();
 400         }
 

But it looks like that runs out, and control proceeds to the place where it's supposed to really wait, not just spin. More to follow.

[John Nagle]

One more step down the call chain: [RtlpWaitForCriticalSection](https://source.winehq.org/git/wine.git/ ... ync.c#l301). This function has much Wine-specific code. Here, there's another wait loop. Note the

Code: Select all

for (;;)

. That wraps around a call to [wait_semaphore](https://source.winehq.org/git/wine.git/ ... ync.c#l180) with a 5 second timeout, with backoffs to 60 seconds and 5 minutes. I've seen some of those log messages.

In wait_semaphore, we have yet another wait loop:

Code: Select all

 193        while (!InterlockedCompareExchange( lock, 0, 1 ))
 194         {
 195             static const LONG zero;
 196             /* this may wait longer than specified in case of multiple wake-ups */
 197             if (RtlWaitOnAddress( lock, &zero, sizeof(LONG), &time ) == STATUS_TIMEOUT)
 198                 return STATUS_TIMEOUT;
 199         }

So it's doing a compare and swap, usually an atomic operation, and if the lock was locked, it calls [RtlWaitOnAddress](https://source.winehq.org/git/wine.git/ ... ync.c#l906). Reasonable.

Note what's going on here. Each level of the locking system is trying to avoid actually putting a thread to sleep, so there are all these "fast" mutexes where first you check for the lock being set, then you spin a bit, then you put the thread to sleep. But there's several levels of such logic, nested.

So let's see what RtlWaitOnAddress does.

It calls [spin_lock](https://source.winehq.org/git/wine.git/ ... ync.c#l906):

Code: Select all

 875 static void spin_lock( LONG *lock )
 876 {
 877     while (InterlockedCompareExchange( lock, -1, 0 ))
 878         YieldProcessor();
 879 }

OK, that looks like a spin lock. Atomic compare and swap, and if that doesn't work, let the CPU do something else.
This is just protecting the list of threads waiting on a lock. There should never be much time spent here.
But that's where the backtrace says the time is going.

[InterlockedCompareExchange](https://source.winehq.org/git/wine.git/ ... nt.h#l6977)

Which just calls __sync_val_compare_and_swap. Which is where it's spending time.

That's supposed to be an atomic operation. GCC documentation:

Built-in Function: type __sync_val_compare_and_swap (type *ptr, type oldval, type newval, ...)
These built-in functions perform an atomic compare and swap. That is, if the current value of *ptr is oldval, then write newval into *ptr.

Now this is strange. If that loop is iterating, it's supposed to be calling YieldProcessor on each try.

Turns out that [YieldProcessor](https://source.winehq.org/git/wine.git/ ... nt.h#l7178) is a no-op in Wine for x86_64 platforms.

Code: Select all

7178 static FORCEINLINE void YieldProcessor(void)
7179 {
7180 #ifdef __GNUC__
7181 #if defined(__i386__) || defined(__x86_64__)
7182     __asm__ __volatile__( "rep; nop" : : : "memory" );
7183 #elif defined(__arm__) || defined(__aarch64__)
7184     __asm__ __volatile__( "dmb ishst\n\tyield" : : : "memory" );
7185 #else
7186     __asm__ __volatile__( "" : : : "memory" );
7187 #endif
7188 #endif
7189 }

So we're in a spinlock that should never take long, but is using up most of the CPU time for 12 processors. Yet it eventually unlocks.

[jkfloris]

The Wine developers can probably tell you more about this. The easiest way is to file a bug report.

[John Nagle]

I'm still looking into this. The above code isn't broken. It just has poor performance when many threads are requesting memory. The locking around memory allocation bottlenecks the whole system. They're going compute-bound in those spinlocks around the allocation and wait primitives.

My program is making lots of little allocations as it grows Rust vectors. There are 16 threads doing this. Worst case for the above code. They tried hard to make the fast no-lock path fast, but the slow path when there's lock contention is not only slow, but compute-bound.

Doesn't happen in Linux, which uses a different memory allocator.

I have to do something different. Pre-allocate, or something.

[John Nagle]

If I file a bug report, they'll want a simple test case. I may have to generate one. Some patterns of memory allocation, especially growing arrays from multiple threads simultaneously, seem to drive the allocator into a pathological state where everybody is spin-locking.

[John Nagle]

Ah. This turns out to be a known class of problem. Search Google for "futex congestion". New to Wine, but not a new problem.

[John Nagle]

Reported as bug: https://bugs.winehq.org/show_bug.cgi?id=54979