[ Andre's Blog ] → [ Debugging game on MacOS via wine ]

I have experience. And patience. A man can do anything if he has those.

(Helmut Zemo)

Intro

We used to spend around half an hour in the evening by playing video games together with my son. He is a fan of both Lego and Marvel. That made LEGO Marvel game series the best candidate. Setup was rather simple: Boot Camp partition on macOS with Windows 8. We finished LEGO Marvel Super Heroes and sooner started to play the sequel. It worked until it is not. One day BSOD appeared on the screen with AppleSSD.sys error stated in it. Good luck to recover partition.

Recovery attempt

All following reboots into Boot Camp lead to Recovery menu. Ironically keyboard and touchpad drivers were not loaded at the moment making navigation impossible. With help of external keyboard and mouse I was able to navigate in recovery menu. And it led me nowhere.

What about backups? Good point. It was too old. I could probably use it, but then spend endless hours trying to restore the whole setup back again.

Alright. Okay, maybe recreate a new partition? I have made game backup and purged Boot Camp partition to realise that after all macOS upgrades I am no longer able to install Windows 8, only 11. I did not want to go down that road at all. Just give me back ability to set Windows 8 or, even better, 7.

Wine is not an emulator

Have you heard about Wine project? Wine is not an emulator. That one. The idea is simple:

Install wine,
configure underlying windows-like environment (prefix in terms of wine),
copy/install game inside the prefix
and launch it.

I have tried several attempts to use wine on different laptops in the past ten years. Most of them were unsuccessful. I had neither time nor courage or persistence to go further and understand how to debug app behaviour under wine.

This time was different. I know for sure that the game application itself was working fine on that same hardware. Speaking of which:

MacBook Pro 2016 year.
2,9 GHz Dual-Core Intel Core i5.
8 GB RAM.
Intel Iris Graphics 550 1536 MB.

How to install wine on macOS?

Homebrew.
Macports.
Source code.

Homebrew offers many options (with a few false-positive results unrelated to wine):

$ brew search wine
==> Formulae
gcenx/wine/cx-llvm                       twine
gcenx/wine/game-porting-toolkit          winetricks
gcenx/wine/libinotify-kqueue

==> Casks
gcenx/wine/game-porting-toolkit          twine
gcenx/wine/portingkit                    homebrew/cask-versions/wine-devel
gcenx/wine/wine-crossover                wine-stable
gcenx/wine/wineskin                      homebrew/cask-versions/wine-staging
gcenx/wine/wineskin-devel                wire

$ brew search wine-devel
==> Casks
homebrew/cask-versions/wine-devel        wine-stable

Please note gcenx/wine cask here. It has been maintained by @Gcenx from CodeWeavers who is working on CrossOver. I have heard about CrossOver before but have not really tried it because there was a certain chance that game will not run. It was not even present in WineHQ database. I want to emphasize that it is tremendous amount of work is being done by @Gcenx. Not only Wine fork maintenance but everything around it. It was truly helpful as you can see later. (@Gcenx, if you read it, please know: this is amazing!)

I have tried almost everything from the list above without any (or almost any) prior knowledge in the domain and connected all the dots in the process. I have chosen trial’n’error approach to break choice paralysis.

Wineskin adds an extra layer of complexity on top of unknown in wine. Too much for beginning.
game-porting-toolkit provided toolkit that could be applied on top of wine. Maybe later.
winetricks is a tool to install missing libraries/components inside wine prefix or to modify prefix environment (Windows registry) and so on. Later.
wine-stable, wine-staging and wine-devel are WineHQ wine builds for macOS. Worth starting with it.
wine-crossover is CodeWeavers wine build based on fork adopted specifically for CrossOver. Maybe later as a last resort.

In all cases wine is under the hood. Wineskin is for managing wine prefices. You can read more about it here.

(What about Proton? Well, Proton initially had support for MacOS but Valve dropped it in favour of Linux a long time ago as it was not clear how to maintain interaction with Apple’s proprietary ecosystem. Better focus on where the most impact could be made.)

Anyway, installation is quiet simple.

brew install wine-stable winetricks

Configuration

Now since wine has been installed, give it some permissions to access certain directories and configure its prefix for the first run.

WINEPREFIX="$HOME/lego" wine winecfg

It means:

With explicitly given wine prefix which will be mounted to given directory run winecfg.exe under wine.

Under WINEPREFIX will be created dosdevices and drive_c directories. First one is for mounting different disks (C:, .., Z:). Second one will become a C: drive with Program Files, Windows, Users directories and all rest stuff needed to run basic Windows programs. Consider it as a mutable storage. It means that you possibly could use it for multiple applications but better isolate for one main app and configure separate prefix for another one. Wineskin took this idea to extreme so you can wrap and unwrap your prefices and share them across devices.

You can alter your prefix with winetricks utility which is kind of a package manager (to install specific apps or drivers) and a list of common settings (to configure mappings between windows-like environment and host machine via registry (wine regedit)).

WINEPREFIX="$HOME/lego" winetricks list-all | less

Replace with your prefix and take a look. (Also you can run it without extra commands and arguments to display GUI).

DirectX renderers

Most games are using DirectX 9, 10, 11 or 12. Those does not work with wine. Instead wine team come up with approach to support that same interface but mapping all application API calls to one of existing solutions and display app content via it, or better say, render it. There are multiple renderers present in winetricks:

WINEPREFIX=$HOME/lego winetricks list-all | grep renderer
renderer=gdi             Set renderer to gdi
renderer=gl              Set renderer to gl
renderer=no3d            Set renderer to no3d
renderer=vulkan          Set renderer to vulkan

You can use winetricks to set a renderer of your choice or you can modify registry directly, if you know the key. There is a collection of useful registry keys described in Wine wiki.

DirectX	What to choose
9	OpenGL (mature choice), D9VK (Vulkan)
10	DXVK (Vulkan)
11	DXVK (Vulkan), D3DMetal
12	VKD3D (Vulkan), D3DMetal

Table 1. DirectX support.

This table could be found in many places, I add link to Wineskin as one of many sources.

Launch

At the moment when I was figuring out how to launch the game there were too many chaotic unconnected details about it so I have started with OpenGL even though the game required DirectX 11. :)

WINEPREFIX="$HOME/lego" winetricks renderer=gl
WINEPREFIX="$HOME/lego" winetricks win8

WINEPREFIX="$HOME/lego" wine 'C:\\Games\\LMSH2\\LEGOMARVEL2_DX11.exe' &> $HOME/LEGOMARVEL2_DX11.log

By the way, more on wine usage: Wine User’s Guide

OpenGL (Renderer=gl)

Almost immediately error appeared on my screen:

From log I was able to trace message to ./dlls/wined3d/context_gl.c:

    if (!(d3d_info->wined3d_creation_flags & WINED3D_NO_PRIMITIVE_RESTART))
    {
        if (gl_info->supported[ARB_ES3_COMPATIBILITY])
        {
            gl_info->gl_ops.gl.p_glEnable(GL_PRIMITIVE_RESTART_FIXED_INDEX);
            checkGLcall("enable GL_PRIMITIVE_RESTART_FIXED_INDEX");
        }
        else
        {
            FIXME("OpenGL implementation does not support GL_PRIMITIVE_RESTART_FIXED_INDEX.\n");
        }

GL_PRIMITIVE_RESTART_FIXED_INDEX was introduced in OpenGL 4.3. Yet according to video chip spec, it supports only OpenGL 4.1.

Moreover, with trace log level there was one more interesting insight. context_gl during initialisation encountered GL_FRAMEBUFFER_UNDEFINED while calling p_glClear function in this code:

    /* Initialise all rectangles to avoid resetting unused ones later. */
    gl_info->gl_ops.gl.p_glScissor(0, 0, 0, 0);
    checkGLcall("glScissor");

    if (new_drawable)
    {
        gl_info->gl_ops.gl.p_glClearColor(0.0f, 0.0f, 0.0f, 0.0f);
        gl_info->gl_ops.gl.p_glClearDepth(1.0f);
        gl_info->gl_ops.gl.p_glClearStencil(0);
        gl_info->gl_ops.gl.p_glClear(GL_COLOR_BUFFER_BIT | GL_DEPTH_BUFFER_BIT | GL_STENCIL_BUFFER_BIT);
        checkGLcall("glClear");
    }
    return WINED3D_OK;

That was so exciting. So many work to do. I was asking myself “did anyone really not deal with it?”. Sooner I have realised that OpenGL is not really suitable for DirectX 10 or 11.

Next steps for OpenGL (if I decide to go down that rabbit hole):

go read changelog from 4.1 to 4.3 on
- what was changed,
- what was added on top of 4.1,
- what does everything mean,
- how to bring missing parts to Wine,
write some tests that will fail,
add/modify some code,
re-test over and over again.

D3DMetal

Do you remember game-porting-toolkit from gcenx/wine cask? I have tried Apple’s official one in combination with wine from Homebrew cask.

Game Porting Toolkit 1.1 offers a few binaries which triggers closed-source wine64 under the hood, few builtin and native dlls and libd3dshared.dylib which provides D3DMetal Apple’s implementation of DirectX for Wine. That means that Apple are well aware about Wine and situation around it on MacOS and trying to solve it from within as they can. Anyway, their intents are great! Let’s try.

0024:trace:module:build_module loaded L"\\??\\C:\\windows\\system32\\d3d11.dll" 0000000104040CD0 0000000067D90000
0024:trace:module:load_dll Loaded module L"\\??\\C:\\windows\\system32\\d3d11.dll" at 0000000067D90000
0024:trace:module:process_attach (L"d3d11.dll",0000000000000000) - START
0024:trace:module:MODULE_InitDLL (0000000067D90000 L"d3d11.dll",PROCESS_ATTACH,0000000000000000) 0000000067D91270 - CALL
0024:trace:module:load_dll looking for L"d3d11.dll" in L"C:\\Games\\LMSH2;C:\\windows\\system32;C:\\windows\\system;C:\\windows;.;C:\\windows\\system32;C:\\windows;C:\\windows\\system32\\wbem;C:\\windows\\system32\\WindowsPowershell\\v1.0"
0024:trace:module:load_dll Found L"C:\\windows\\system32\\d3d11.dll" for L"d3d11.dll" at 0000000067D90000, count=2
0024:trace:module:LdrGetDllHandleEx flags 0x1, load_path 0000000000000000, dll_characteristics 0000000000000000, name 000000000011EE50, base 000000000011EE48.
0024:trace:module:LdrGetDllHandleEx L"ntdll.dll" -> 0000000170000000 (load path (null))

Assertion failed: (GFXTHandle && "Failed to dlopen D3DMetal"), function D3DRMDispatch_Init_block_invoke, file shared.mm, line 699.

Next steps (if I decide to go down that road):

go to Apple forums,
submit logs,
wait.

DXVK + renderer=vulkan

winetricks offers all dxvk builds from GitHub. And few alternatives.

WINEPREFIX="$HOME/lego" winetricks | grep dxvk
dxvk                     Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (latest) (Philip Rebohle, 2023) [downloadable]
...
dxvk1094                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (1.9.4) (Philip Rebohle, 2017) [downloadable]
dxvk1100                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (1.10) (Philip Rebohle, 2017) [downloadable]
dxvk1101                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (1.10.1) (Philip Rebohle, 2017) [downloadable]
dxvk1102                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (1.10.2) (Philip Rebohle, 2017) [downloadable]
dxvk1103                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (1.10.3) (Philip Rebohle, 2022) [downloadable,cached]
dxvk2000                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (2.0) (Philip Rebohle, 2022) [downloadable]
dxvk2010                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (2.1) (Philip Rebohle, 2023) [downloadable]
dxvk2020                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (2.2) (Philip Rebohle, 2023) [downloadable]
dxvk2030                 Vulkan-based D3D9/D3D10/D3D11 implementation for Linux / Wine (2.3) (Philip Rebohle, 2023) [downloadable]
dxvk_nvapi0061           Alternative NVAPI Vulkan implementation on top of DXVK for Linux / Wine (0.6.1) (Jens Peters, 2023) [downloadable]

Alright, install it and run the game.

WINEPREFIX="$HOME/lego" winetricks dxvk

WINEPREFIX="$HOME/lego" wine 'C:\\Games\\LMSH2\\LEGOMARVEL2_DX11.exe' &> $HOME/LEGOMARVEL2_DX11.log

And receive the same modal window with fatal error and following log entry:

err:D3D11CoreCreateDevice: Requested feature level not supported D3D_FEATURE_LEVEL_9_1

Why is it not supported? At this point I need more info from wine/DXVK logs.

wine_vkCreateDevice Device name: "Intel(R) Iris(TM) Graphics 550".
wine_vkCreateDevice Vendor ID: 0x8086, Device ID: 0x1927.
wine_vkCreateDevice Driver version: 0x277a.

Well, it turned out that video chip does not support Vulkan 1.3, yet the most recent version of DXVK obtained from winetricks supports only Vulkan 1.3 and dropped Vulkan 1.2 according to their Release notes. After downgrading DXVK to 1.10.3 (the last version that supported Vulkan 1.2) I messed up with wine prefix.

At this point I have decided to create a new prefix and try again but building DXVK from sources.

Building DXVK from sources

# prerequisites
$ brew install bison mingw-w64 glslang

# building
$ git clone --recursive https://github.com/doitsujin/dxvk.git
$ cd dxvk
$ ./package-release.sh master $(pwd)/target --dev-build

Oh, wait. I am building HEAD instead of 1.10.3. Now I need to trace 1.10.3 back, create a branch and start again. Fortunately, @Gcenx is rescuing me again! He followed that same route and is still maintaining 1.10.x branch which was exactly what I needed.

Purging dxvk directory and trying again.

Building:

$ git clone --recursive https://github.com/Gcenx/DXVK-macOS.git
cd DXVK-macOS
$ ./package-release.sh 1.10.x $(pwd)/target --dev-build

Installing:

cp $(pwd)/target/dxvk-macOS-async-1.10.x/x64/*.dll $WINEPREFIX/drive_c/windows/syswow64
cp $(pwd)/target/dxvk-macOS-async-1.10.x/x32/*.dll $WINEPREFIX/drive_c/windows/system32

Manually add overrides as on screenshot:

Running:

WINEPREFIX=$HOME/lego2 wine 'C:\\Games\\LMSH2\\LEGOMARVEL2_DX11.exe' > $HOME/LEGOMARVEL2_DX11.log

And getting 014c error of incompatible architectures. Game expected x64 dlls in C:\Windows\system32. Fine, feed x64 dlls to it.

cp $(pwd)/target/dxvk-macOS-async-1.10.x/x64/*.dll $WINEPREFIX/drive_c/windows/syswow64
cp $(pwd)/target/dxvk-macOS-async-1.10.x/x64/*.dll $WINEPREFIX/drive_c/windows/system32

After restart game eventually made quiet a progress: - Tray icon was rendered! - Black rectangle was displayed!!! - And that was it. Application just stuck.

err:sync:RtlpWaitForCriticalSection section 000000010055F670 (null) wait timed out in thread 0174, blocked by 0170, retrying (60 sec)

How to debug such issues?

`apitrace`

In DXVK wiki and Wine documentation too there is mentioned apitrace utility.

Unfortunately, there is no MacOS binary distribution. Anyway, let’s try Windows one with wine. After copying tracing libraries in directory with game and reproducing black rectangle. I have collected .apitrace file in $WINEPREFIX/drive_c/users/crossover/Desktop directory.

WINEPREFIX=lego2 wine $HOME/Downloads/apitrace-11.1-win64/bin/qapitrace.exe

It did not give me much insights. I saw 6 swap-chains, a lot of information that I did not undertand.

`dxvk.conf`

After looking at those swap-chain long enough, I have noticed that the last one was incomplete. What if this behaviour could be overcomed via some configuration tweaks?

# Create the VkSurface on the first call to IDXGISwapChain::Present,
# rather than when creating the swap chain. Some games that start
# rendering with a different graphics API may require this option,
# or otherwise the window may stay black.
# 
# Supported values: True, False

# dxgi.deferSurfaceCreation = False
# d3d9.deferSurfaceCreation = False

combination of SwapChain, rendering and window may stay black lead me to give it a try.

I have set

dxgi.deferSurfaceCreation = True

and added few other best practices just in case.

export DXVK_LOG_LEVEL=debug
export DXVK_LOG_PATH=$HOME
export DXVK_HUD=all

With all of that I have received following picture.

Figure 4. DXVK debug info on top of black rectangle

`winedbg`

After retrying error remained the same but thread ids were changed. Most of the times they were identical around 0180.

0184:err:sync:RtlpWaitForCriticalSection section 00000001006269B0 (null) wait timed out in thread 0184, blocked by 0180, retrying (60 sec)

Another approach is to analyse application runtime is to attach debugger to it and examine memory with debugger.

WINEPREFIX=$HOME/lego2 wine winedbg.exe
Wine-dbg>info process
 pid      threads  executable (all id:s are in hex)
 000001a8 1        'start.exe'
=000001b8 1        \_ 'winedbg.exe'
 000001b0 2        \_ 'conhost.exe'
 00000030 9        'services.exe'
 000000d8 6        \_ 'rpcss.exe'
 000000a4 3        \_ 'svchost.exe'
 0000008c 6        \_ 'plugplay.exe'
 00000060 8        \_ 'winedevice.exe'
 0000003c 7        \_ 'winedevice.exe'
 00000020 30       'LEGOMARVEL2_DX11.exe'
 000000c4 3        \_ 'explorer.exe'
Wine-dbg>attach 0x20
0x006fffffca5e21 ntdll+0x55e21: ret
Wine-dbg>bt 0x0180
Backtrace:
=>0 0x006fffffca5a64 in ntdll (+0x55a64) (0x000000fffffff4)
  1 0x006fffff4d3f70 in kernelbase (0x000000fffffff4)
  2 0x006fffff4d480e in kernelbase (0000000000000000)
  3 0x0000014054c46d in legomarvel2_dx11 (+0x54c46d) (0000000000000000)
  4 0x000001405527ab in legomarvel2_dx11 (+0x5527ab) (0000000000000000)
  5 0x000001403033dc in legomarvel2_dx11 (+0x3033dc) (0000000000000000)
  6 0x006fffffaa8c79 in kernel32 (0000000000000000)
  7 0x006fffffca5deb in ntdll (+0x55deb) (0000000000000000)
Wine-dbg>bt 0x184
Backtrace:
=>0 0x006fffffca5a04 in ntdll (+0x55a04) (0x0000011c0bf9d0)
  1 0x006fffffcacda8 in ntdll (0x0000011c0bf9d0)
  2 0x006fffffcacda8 in ntdll (0x0000011c0bf9d0)
  3 0x006fffffcacda8 in ntdll (0x0000011c0bf9d0)
  4 0x006fffffcacf46 in ntdll (0x000001006269b0)
  5 0x006fffffcacf46 in ntdll (0x000001006269b0)
  6 0x006fffffcad1b1 in ntdll (0000000000000000)
  7 0x000001402dc48d in legomarvel2_dx11 (+0x2dc48d) (0000000000000000)
  8 0x0000014054c45b in legomarvel2_dx11 (+0x54c45b) (0000000000000000)
  9 0x000001405527ab in legomarvel2_dx11 (+0x5527ab) (0000000000000000)
  10 0x000001403033dc in legomarvel2_dx11 (+0x3033dc) (0000000000000000)
  11 0x006fffffaa8c79 in kernel32 (0000000000000000)
  12 0x006fffffca5deb in ntdll (+0x55deb) (0000000000000000)

Yes, it was wine-stable compiled without debug symbols. To enable debug symbols I need to install wine-devel.

Building Wine from sources

At this point maybe better compile wine from sources? But which one? After taking a look at multiple repos, I have chosen wine-crossover (winecx) as there was written very clear installation procedure.

Although the compilation process is very famous (./configure && make && make install) the devil is hiding in many tiny details. The whole compilation pipeline lasts for more than four hours. make phase was taking the most time. While trying different options I was executing this command before going to sleep. When I was iterating over some hypotheses, I would stick to recompilation only particular DLLs instead of rebuilding everything from scratch. But in some cases I have corrupted wine prefix and it was necessary to make clean install of everything.

Few prerequisites to enable Vulkan support in Wine:

brew install bison mingw-w64 lcms2 FAudio sdl2 gstreamer gst-plugins-base gst-plugins-good vulkan-headers molten-vk

Next step is ./configure:

export SDL2_CFLAGS="-I/usr/local/Cellar/sdl2/2.30.0/include/SDL2 -D_THREAD_SAFE"
export SDL2_LIBS="-L/usr/local/Cellar/sdl2/2.30.0/lib -lSDL2"
export DYLD_LIBRARY_PATH="/usr/local/lib:/usr/local/Cellar/molten-vk/1.2.7/lib:$DYLD_LIBRARY_PATH"
export PCAP_CFLAGS="-I/usr/local/opt/libpcap/include"
export PCAP_LIBS="-L/usr/local/Cellar/libpcap/1.10.4/lib -lpcap"

./configure --disable-option-checking \
--disable-tests \
--enable-archs=i386,x86_64 \
--without-alsa \
--without-capi \
--with-coreaudio \
--with-cups \
--without-dbus \
--without-fontconfig \
--with-freetype \
--with-gettext \
--without-gettextpo \
--without-gphoto \
--with-gnutls \
--without-gssapi \
--with-gstreamer \
--without-inotify \
--without-krb5 \
--with-mingw \
--without-netapi \
--with-opencl \
--with-opengl \
--without-oss \
--with-pcap \
--with-pcsclite \
--with-pthread \
--without-pulse \
--without-sane \
--with-sdl \
--without-udev \
--with-unwind \
--without-usb \
--without-v4l2 \
--with-vulkan \
--without-wayland \
--without-x

Then comes make. First run will probably fail with following error:

distversion.h: No such file or directory

To fix it we’ll provide distversion.h from here:

cat distversion.patch
diff -uNr sources.orig/wine/include/distversion.h sources/wine/include/distversion.h
--- sources.orig/wine/include/distversion.h	1970-01-01 09:00:00.000000000 +0900
+++ sources/wine/include/distversion.h	2021-02-07 17:03:44.000000000 +0900
@@ -0,0 +1,12 @@
+/* ---------------------------------------------------------------
+*   distversion.c
+*
+* Copyright 2013, CodeWeavers, Inc.
+*
+* Information from DISTVERSION which needs to find
+* its way into the wine tree.
+* --------------------------------------------------------------- */
+
+#define WINDEBUG_WHAT_HAPPENED_MESSAGE "This can be caused by a problem in the program or a deficiency in Wine. You may want to check <a href=\"http://www.codeweavers.com/compatibility/\">http://www.codeweavers.com/compatibility/</a> for tips about running this application."
+
+#define WINDEBUG_USER_SUGGESTION_MESSAGE "If this problem is not present under Windows and has not been reported yet, you can save the detailed information to a file using the \"Save As\" button, then <a href=\"http://www.codeweavers.com/support/tickets/enter/\">file a bug report</a> and attach that file to the report."

patch -u programs/winedbg/distversion.h -i distversion.patch

After few hours make succeeded.

sudo make install

It will take another half an hour. Then launch the game again to receive new error in the log:

err:vulkan:get_vulkan_driver Wine was built without Vulkan support.

Wait, what? I remember explicitly mentioning --with-vulkan option. Trace error back to source file:

#ifdef SONAME_LIBMOLTENVK

// ... hundreds lines later

static const struct vulkan_funcs *get_vulkan_driver(UINT version)
{
    static pthread_once_t init_once = PTHREAD_ONCE_INIT;

    if (version != WINE_VULKAN_DRIVER_VERSION)
    {
        ERR("version mismatch, vulkan wants %u but driver has %u\n", version, WINE_VULKAN_DRIVER_VERSION);
        return NULL;
    }

    pthread_once(&init_once, wine_vk_init);
    if (vulkan_handle)
        return &vulkan_funcs;

    return NULL;
}

#else /* No vulkan */

static const struct vulkan_funcs *get_vulkan_driver(UINT version)
{
    ERR("Wine was built without Vulkan support.\n");
    return NULL;
}

#endif /* SONAME_LIBMOLTENVK */

I did remember checking libVulkan during configuration. After tracing back SONAME_LIBMOLTENVK I found the following logic in configure.ac:

dnl *** Check for Vulkan ***
if test "x$with_vulkan" != "xno"
then
    WINE_CHECK_SONAME(vulkan, vkGetInstanceProcAddr)
    if test "x$ac_cv_lib_soname_vulkan" = "x"
    then
        WINE_CHECK_SONAME(MoltenVK, vkGetInstanceProcAddr)
    fi
fi
WINE_NOTICE_WITH(vulkan,[test "x$ac_cv_lib_soname_vulkan" = "x" -a "x$ac_cv_lib_soname_MoltenVK" = "x"],
                 [libvulkan and libMoltenVK ${notice_platform}development files not found, Vulkan won't be supported.])

In other words, “if libvulkan is not present check for libmoltenvk, otherwise, skip libmoltenvk”. I removed that condition and tried to recompile Wine again.

There were issues with symbolic links so I have removed vulkan-headers and molten-vk by brew and decided to build MoltenVK from sources.

brew uninstall vulkan-headers molten-vk
brew cleanup

Building MoltenVK from sources

Some prerequisites:

brew install cmake python3 ninja

Then clone repo and run installation process:

git clone https://github.com/KhronosGroup/MoltenVK.git
cd MoltenVK
./fetchDependencies --macos # this step takes a couple hours
make macos-debug
sudo make install

In the beginning I have built everything. It produced libraries not only for MacOS but for iOS too. After messing up with symlinks I have received following weird error during ./configure:

configure:19929: checking for -lMoltenVK
configure:19958: gcc -m64 -o conftest -g -O2 -DIS_WOW64_BUILD -I/usr/local/opt/libpcap/include -L/usr/local/opt/libpcap/lib conftest.c -lMoltenVK   >&5
ld: warning: ignoring file /usr/local/lib/libMoltenVK.dylib, building for macOS-x86_64 but attempting to link with file built for unknown-unsupported file format ( 0xCF 0xFA 0xED 0xFE 0x07 0x00 0x00 0x01 0x03 0x00 0x00 0x00 0x0A 0x00 0x00 0x00 )
Undefined symbols for architecture x86_64:
  "_vkGetInstanceProcAddr", referenced from:
      _main in conftest-86360e.o
ld: symbol(s) not found for architecture x86_64
clang: error: linker command failed with exit code 1 (use -v to see invocation)
configure:19958: $? = 1
configure: failed program was:
| /* confdefs.h */
| #define PACKAGE_NAME "Wine"
| #define PACKAGE_TARNAME "wine"
| #define PACKAGE_VERSION "9.0"
| #define PACKAGE_STRING "Wine 9.0"
| #define PACKAGE_BUGREPORT "wine-devel@winehq.org"
| #define PACKAGE_URL "https://www.winehq.org"
| #define EXEEXT ""
| #define HAVE_STDIO_H 1
| #define HAVE_STDLIB_H 1
| #define HAVE_STRING_H 1
| #define HAVE_INTTYPES_H 1
| #define HAVE_STDINT_H 1
| #define HAVE_STRINGS_H 1
| #define HAVE_SYS_STAT_H 1
| #define HAVE_SYS_TYPES_H 1
| #define HAVE_UNISTD_H 1
| #define STDC_HEADERS 1
| #define HAVE_IOKIT_USB_IOUSBLIB_H 1
| #define HAVE_OPENCL_OPENCL_H 1
| #define HAVE_ARPA_INET_H 1
| #define HAVE_ARPA_NAMESER_H 1
| #define HAVE_FLOAT_H 1
| #define HAVE_LIBPROC_H 1
| #define HAVE_MACH_O_LOADER_H 1
| #define HAVE_MACH_MACH_H 1
| #define HAVE_NETDB_H 1
| #define HAVE_NETINET_IN_H 1
| #define HAVE_NETINET_IN_SYSTM_H 1
| #define HAVE_NETINET_TCP_H 1
| #define HAVE_NETINET_TCP_FSM_H 1
| #define HAVE_PCAP_PCAP_H 1
| #define HAVE_PWD_H 1
| #define HAVE_SCHED_H 1
| #define HAVE_STDINT_H 1
| #define HAVE_SYS_ATTR_H 1
| #define HAVE_SYS_EVENT_H 1
| #define HAVE_SYS_FILIO_H 1
| #define HAVE_SYS_IPC_H 1
| #define HAVE_SYS_PARAM_H 1
| #define HAVE_SYS_PTRACE_H 1
| #define HAVE_SYS_QUEUE_H 1
| #define HAVE_SYS_RANDOM_H 1
| #define HAVE_SYS_RESOURCE_H 1
| #define HAVE_SYS_SHM_H 1
| #define HAVE_SYS_SIGNAL_H 1
| #define HAVE_SYS_SOCKETVAR_H 1
| #define HAVE_SYS_SOCKIO_H 1
| #define HAVE_SYS_STATVFS_H 1
| #define HAVE_SYS_SYSCALL_H 1
| #define HAVE_SYS_TIMES_H 1
| #define HAVE_SYS_UIO_H 1
| #define HAVE_SYS_USER_H 1
| #define HAVE_SYS_UTSNAME_H 1
| #define HAVE_SYS_VNODE_H 1
| #define HAVE_SYS_XATTR_H 1
| #define HAVE_UTIME_H 1
| #define HAVE_SYS_CONF_H 1
| #define HAVE_SYS_MOUNT_H 1
| #define HAVE_SYS_USER_H 1
| #define HAVE_SYS_SYSCTL_H 1
| #define HAVE_NETINET_IP_H 1
| #define HAVE_NET_IF_H 1
| #define HAVE_NET_IF_ARP_H 1
| #define HAVE_NET_IF_DL_H 1
| #define HAVE_NET_IF_TYPES_H 1
| #define HAVE_NET_ROUTE_H 1
| #define HAVE_NETINET_IF_ETHER_H 1
| #define HAVE_NETINET_IN_PCB_H 1
| #define HAVE_NETINET_IP_ICMP_H 1
| #define HAVE_NETINET_IP_VAR_H 1
| #define HAVE_NETINET_UDP_H 1
| #define HAVE_SYS_UN_H 1
| #define HAVE_NETINET_UDP_VAR_H 1
| #define HAVE_NETINET_ICMP_VAR_H 1
| #define HAVE_NETINET_ICMP6_H 1
| #define HAVE_NETINET_TCP_VAR_H 1
| #define HAVE_RESOLV_H 1
| #define HAVE_IFADDRS_H 1
| #define HAVE_SYS_UCONTEXT_H 1
| #define XATTR_ADDITIONAL_OPTIONS 1
| #define HAVE_AVFOUNDATION_AVFOUNDATION_H 1
| #define HAVE_IOSERVICEMATCHING 1
| #define HAVE_MTLDEVICE_REGISTRYID 1
| #define X_DISPLAY_MISSING 1
| #define SONAME_LIBGNUTLS "libgnutls.30.dylib"
| #define HAVE_GNUTLS_CIPHER_INIT 1
| #define HAVE_RESOLV 1
| #define HAVE_RES_GETSERVERS 1
| #define HAVE_FT2BUILD_H 1
| #define SONAME_LIBFREETYPE "libfreetype.6.dylib"
| #define HAVE_FREETYPE 1
| #define HAVE_FT_TRUETYPEENGINETYPE 1
| #define HAVE_LIBUNWIND 1
| #define HAVE_SDL_H 1
| #define SONAME_LIBSDL2 "libSDL2-2.0.0.dylib"
| #define HAVE_CUPS_CUPS_H 1
| #define HAVE_CUPS_PPD_H 1
| #define SONAME_LIBCUPS "libcups.2.dylib"
| #define SONAME_LIBODBC "libodbc.2.dylib"
| /* end confdefs.h.  */
| 
| /* Override any GCC internal prototype to avoid an error.
|    Use char because int might match the return type of a GCC
|    builtin and then its argument prototype would still apply.

Of course, macOS build was expected, not iOS one. Pointing out location to proper debug library $(pwd)/MoltenVK/dylib/macOS/libMoltenVK.dylib helped.

After Wine recompilation I got following error:

_mtlValidateStrideTextureParameters:1824: failed assertion `Texture Descriptor Validation

It was a known MoltenVK issue from upstream. On the very next day I discovered that PR #2169 is merged. So I pulled changes, recompiled MoltenVK and tried again. But the issue persisted. I took a look at GitHub:

People were working hard on a feature called native texture atomics.
It supposed to be merged in next MotlenVK release v.1.2.8.
Feature introduced a regression which I had encountered.
I’ve checked out 37361ccd that was related to v.1.2.7 release and rebuilt everything again one more time.

After that I have recompiled Wine again (just in case) and finally reproduced CriticalSection error!

0180:err:sync:RtlpWaitForCriticalSection section 0000000100626FF0 (null) wait timed out in thread 0180, blocked by 017c, retrying (60 sec)

Root cause analysis

Let’s revisit back traces again.

Wine-dbg>bt 0x0180
Backtrace:
=>0 0x006fffffca5a04 in ntdll (+0x55a04) (0x0000011c0bf9d0)
  1 0x006fffffcacda8 _InterlockedCompareExchange(addr=0000000100627008, cmp=00006FFFFFCCBEB0, size=<internal error>, timeout=000000011C0BF9D0) [$WINECX/include/winnt.h:7005] in ntdll (0
x0000011c0bf9d0)
  2 0x006fffffcacda8 spin_lock(addr=<register R12 not accessible in this frame>, cmp=<register R13 not accessible in this frame>, size=<internal error>, timeout=<register RBP not accessible in this frame>
) [$WINECX/dlls/ntdll/sync.c:912] in ntdll (0x0000011c0bf9d0)
  3 0x006fffffcacda8 RtlWaitOnAddress+0x168(addr=<register R12 not accessible in this frame>, cmp=<register R13 not accessible in this frame>, size=<internal error>, timeout=<register RBP not accessible i
n this frame>) [$WINECX/dlls/ntdll/sync.c:912] in ntdll (0x0000011c0bf9d0)
  4 0x006fffffcacf46 wait_semaphore+0x65(timeout=<internal error>, crit=<internal error>) [$WINECX/dlls/ntdll/sync.c:196] in ntdll (0x00000100626ff0)
  5 0x006fffffcacf46 RtlpWaitForCriticalSection+0x76(crit=<register RBP not accessible in this frame>) [$WINECX/dlls/ntdll/sync.c:305] in ntdll (0x00000100626ff0)
  6 0x006fffffcad1b1 RtlEnterCriticalSection+0x91(crit=<register RBX not accessible in this frame>) [$WINECX/dlls/ntdll/sync.c:383] in ntdll (0000000000000000)
  7 0x000001402dc48d in legomarvel2_dx11 (+0x2dc48d) (0000000000000000)
  8 0x0000014054c45b in legomarvel2_dx11 (+0x54c45b) (0000000000000000)
  9 0x000001405527ab in legomarvel2_dx11 (+0x5527ab) (0000000000000000)
  10 0x000001403033dc in legomarvel2_dx11 (+0x3033dc) (0000000000000000)
  11 0x006fffffaa8c79 BaseThreadInitThunk+0x9(unknown=<internal error>, entry=<internal error>, arg=<internal error>) [$WINECX/dlls/kernel32/thread.c:61] in kernel32 (0000000000000000)
  12 0x006fffffca5deb in ntdll (+0x55deb) (0000000000000000)
Wine-dbg>bt 0x017c
Backtrace:
=>0 0x006fffffca5a64 in ntdll (+0x55a64) (0x000000fffffff4)
  1 0x006fffff4d3f70 WaitForMultipleObjectsEx+0xc8(count=0x1, handles=000000011BEBFA80, wait_all=0, timeout=<internal error>, alertable=0) [$WINECX/dlls/kernelbase/sync.c:383] in kernel
base (0x000000fffffff4)
  2 0x006fffff4d480e WaitForSingleObject+0x26(handle=<is not available>, timeout=<internal error>) [$WINECX/dlls/kernelbase/sync.c:339] in kernelbase (0000000000000000)
  3 0x0000014054c46d in legomarvel2_dx11 (+0x54c46d) (0000000000000000)
  4 0x000001405527ab in legomarvel2_dx11 (+0x5527ab) (0000000000000000)
  5 0x000001403033dc in legomarvel2_dx11 (+0x3033dc) (0000000000000000)
  6 0x006fffffaa8c79 BaseThreadInitThunk+0x9(unknown=<internal error>, entry=<internal error>, arg=<internal error>) [$WINECX/dlls/kernel32/thread.c:61] in kernel32 (0000000000000000)
  7 0x006fffffca5deb in ntdll (+0x55deb) (0000000000000000)

Thread 0180 is waiting for 017c, thread 017c is waiting for something else. I definitely needed more info. So decided to look at the logging levels more closely. Debug Logging wiki article contains more on how to configure logging. I have enabled trace+all and restarted again. Wine produced 1.6 GB of logs.

compstui.dll

While navigating inside log file I’ve focused on thread that was both locked by something else and locking some other thread.

1220316.497:0180:trace:module:alloc_thread_tls slot 0: 327716/0 bytes at 000000010078F2A0
1220316.497:0180:trace:module:alloc_thread_tls slot 1: 8/0 bytes at 000000010037BA00
1220316.497:0180:trace:module:alloc_thread_tls slot 2: 8/0 bytes at 000000010037BA30
1220316.497:0180:Call PE DLL (proc=00006FFFFF02CC30,module=00006FFFFEFC0000 L"msvcrt.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.497:0180:trace:msvcrt:DllMain (00006FFFFEFC0000, DLL_THREAD_ATTACH, 0000000000000000) pid(20), tid(180), tls(64)
1220316.497:0180:Ret  PE DLL (proc=00006FFFFF02CC30,module=00006FFFFEFC0000 L"msvcrt.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.497:0180:Call PE DLL (proc=00006FFFFEB76510,module=00006FFFFEAF0000 L"ucrtbase.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.497:0180:trace:msvcrt:DllMain (00006FFFFEAF0000, DLL_THREAD_ATTACH, 0000000000000000) pid(20), tid(180), tls(65)
1220316.497:0180:Call ntdll.RtlFlsSetValue(00000001,fffffffffffffffe) ret=6fffff4daa63
1220316.497:0180:Ret  ntdll.RtlFlsSetValue() retval=00000000 ret=6fffff4daa63
1220316.497:0180:Ret  PE DLL (proc=00006FFFFEB76510,module=00006FFFFEAF0000 L"ucrtbase.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.497:0180:Call PE DLL (proc=00006FFFFDD1B020,module=00006FFFFDC90000 L"user32.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.497:0180:Ret  PE DLL (proc=00006FFFFDD1B020,module=00006FFFFDC90000 L"user32.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.497:0180:Call PE DLL (proc=00006FFFFD8DD410,module=00006FFFFD8D0000 L"imm32.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.497:0180:trace:imm:DllMain instance 00006FFFFD8D0000, reason 2, reserved 0000000000000000
1220316.497:0180:Ret  PE DLL (proc=00006FFFFD8DD410,module=00006FFFFD8D0000 L"imm32.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.497:0180:Call PE DLL (proc=00006FFFFEA432D0,module=00006FFFFEA30000 L"WS2_32.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.497:0180:Ret  PE DLL (proc=00006FFFFEA432D0,module=00006FFFFEA30000 L"WS2_32.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.497:0180:Call PE DLL (proc=00006FFFFE7DADC0,module=00006FFFFE790000 L"rpcrt4.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.497:0180:Ret  PE DLL (proc=00006FFFFE7DADC0,module=00006FFFFE790000 L"rpcrt4.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.498:0180:Call PE DLL (proc=00006FFFFBC65F10,module=00006FFFFBC40000 L"combase.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.498:0180:trace:ole:DllMain 00006FFFFBC40000, 0x2, 0000000000000000
1220316.498:0180:Ret  PE DLL (proc=00006FFFFBC65F10,module=00006FFFFBC40000 L"combase.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.498:0180:Call PE DLL (proc=00006FFFFBE95900,module=00006FFFFBDF0000 L"ole32.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.498:0180:trace:ole:DllMain 00006FFFFBDF0000, 0x2, 0000000000000000.
1220316.498:0180:Ret  PE DLL (proc=00006FFFFBE95900,module=00006FFFFBDF0000 L"ole32.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.498:0180:Call PE DLL (proc=00006FFFFA930610,module=00006FFFFA8F0000 L"WININET.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.498:0180:Ret  PE DLL (proc=00006FFFFA930610,module=00006FFFFA8F0000 L"WININET.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.498:0180:Call TLS callback (proc=00006FFFF83E3130,module=00006FFFF8350000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Ret  TLS callback (proc=00006FFFF83E3130,module=00006FFFF8350000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Call TLS callback (proc=00006FFFF83E3100,module=00006FFFF8350000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Ret  TLS callback (proc=00006FFFF83E3100,module=00006FFFF8350000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Call TLS callback (proc=00006FFFF83F0270,module=00006FFFF8350000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Ret  TLS callback (proc=00006FFFF83F0270,module=00006FFFF8350000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Call PE DLL (proc=00006FFFF8351330,module=00006FFFF8350000 L"dxgi.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.498:0180:Ret  PE DLL (proc=00006FFFF8351330,module=00006FFFF8350000 L"dxgi.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.498:0180:Call TLS callback (proc=00006FFFF90C9C20,module=00006FFFF8FA0000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Ret  TLS callback (proc=00006FFFF90C9C20,module=00006FFFF8FA0000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Call TLS callback (proc=00006FFFF90C9BF0,module=00006FFFF8FA0000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Ret  TLS callback (proc=00006FFFF90C9BF0,module=00006FFFF8FA0000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Call TLS callback (proc=00006FFFF90D6C40,module=00006FFFF8FA0000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Ret  TLS callback (proc=00006FFFF90D6C40,module=00006FFFF8FA0000,reason=THREAD_ATTACH,reserved=0)
1220316.498:0180:Call PE DLL (proc=00006FFFF8FA1330,module=00006FFFF8FA0000 L"d3d11.dll",reason=THREAD_ATTACH,res=0000000000000000)
1220316.498:0180:Ret  PE DLL (proc=00006FFFF8FA1330,module=00006FFFF8FA0000 L"d3d11.dll",reason=THREAD_ATTACH,res=0000000000000000) retval=1
1220316.498:0180:Call PE DLL (proc=00006FFFF7F22270,module=00006FFFF7F20000 L"compstui.dll",reason=THREAD_ATTACH,res=0000000000000000)

It has called compstui.dll (message started with Call) but never received anything back (no Ret). In ./dlls/compstui/comsptui_main.c there was an extra log channel called compstui:

WINE_DEFAULT_DEBUG_CHANNEL(compstui);

I have added it to WINEDEBUG, restarted the game to realise that log was corrupted.

It turned out that winecx (CrossOver fork of Wine) has missed to port MR !1174 back from upstream.

After cherry-picking it and back-porting to winecx compstui did not throw more errors but it did not solve CriticalSection issue.

Hypothesis: thread renaming

I have noticed that Critical Section locks were happening around thread renaming:

After wine context initialisation game Main thread 0024 started.
It started to create more worker threads for game specific reasons.
Those threads were having names, i.e. game main thread renamed its child threads.
It turned out that unlike in Windows it is not possible to rename one thread from another one in MacOS.
In order to ensure that this renaming event happening, wine is raising renaming event via structured exception handler (SEH).
Child thread is receiving that event and performs renaming by itself.
Moreover, thread name was truncated to 31 characters due to Apple limitations on thread name length.
The more I looked into it, the more I suspected that renaming is somehow related to the problem if not causing it.
And game got stuck on shader worker threads.

Here is excerpt from logs (warn log level, threadname log channel):

1220306.025:0038:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_server"
1220306.119:0044:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220306.122:0048:warn:threadname:NtSetInformationThread Thread renamed to L"wine_threadpool_worker"
1220306.138:0050:warn:threadname:NtSetInformationThread Thread renamed to L"wine_sechost_service"
1220306.248:0068:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220306.264:0070:warn:threadname:NtSetInformationThread Thread renamed to L"wine_sechost_service"
1220307.101:0090:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220307.115:0098:warn:threadname:NtSetInformationThread Thread renamed to L"wine_sechost_service"
1220307.117:009c:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_server"
1220307.173:00a8:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220307.188:00b0:warn:threadname:NtSetInformationThread Thread renamed to L"wine_sechost_service"
1220310.943:00cc:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_server"
1220310.955:00d0:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220311.014:00dc:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220311.018:00e0:warn:threadname:NtSetInformationThread Thread renamed to L"wine_threadpool_worker"
1220311.030:00e8:warn:threadname:NtSetInformationThread Thread renamed to L"wine_sechost_service"
1220311.033:00ec:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_server"
1220311.034:00f0:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_server"
1220311.049:00f4:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220311.052:00f8:warn:threadname:NtSetInformationThread Thread renamed to L"wine_threadpool_worker"
1220313.291:0024:warn:threadname:dispatch_exception Thread ID 0000 renamed to ""
1220313.292:0024:warn:threadname:dispatch_exception Thread ID 0000 renamed to "Main"
1220313.354:0024:warn:threadname:dispatch_exception Thread ID 0000 renamed to ""
1220313.355:0024:warn:threadname:dispatch_exception Thread ID 0000 renamed to "Main"
1220314.714:0104:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220314.714:010c:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-submit"
1220314.714:0108:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220314.714:00fc:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220314.714:0100:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220314.715:0110:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-queue"
1220314.728:0114:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-cs"
1220315.160:0118:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.162:011c:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.164:0120:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.165:0124:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.167:0128:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-submit"
1220315.169:012c:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-queue"
1220315.174:0130:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-cs"
1220315.797:0134:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.798:0140:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.800:013c:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.801:0138:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-pcompiler"
1220315.808:0144:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-submit"
1220315.809:0148:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-queue"
1220315.817:014c:warn:threadname:NtSetInformationThread Thread renamed to L"dxvk-cs"
1220316.227:0024:warn:threadname:dispatch_exception Thread ID 0150 renamed to "NuBgProc-ET-Sequential"
1220316.228:0024:warn:threadname:dispatch_exception Thread ID 0154 renamed to "NuBgProc-ET-Long"
1220316.229:0024:warn:threadname:dispatch_exception Thread ID 0158 renamed to "NuBgProc-ET-Long"
1220316.229:0150:warn:threadname:dispatch_exception Thread renamed to "NuBgProc-ET-Sequential"
1220316.230:0024:warn:threadname:dispatch_exception Thread ID 015c renamed to "NuBgProc-ET-Long"
1220316.230:0024:warn:threadname:dispatch_exception Thread ID 0160 renamed to "NuBgProc-ET-Short"
1220316.230:0154:warn:threadname:dispatch_exception Thread renamed to "NuBgProc-ET-Long"
1220316.231:0024:warn:threadname:dispatch_exception Thread ID 0164 renamed to "NuBgProc-ET-Short"
1220316.231:0024:warn:threadname:dispatch_exception Thread ID 0168 renamed to "NuBgProc-ET-Short"
1220316.231:0158:warn:threadname:dispatch_exception Thread renamed to "NuBgProc-ET-Long"
1220316.232:015c:warn:threadname:dispatch_exception Thread renamed to "NuBgProc-ET-Long"
1220316.233:0160:warn:threadname:dispatch_exception Thread renamed to "NuBgProc-ET-Short"
1220316.234:0164:warn:threadname:dispatch_exception Thread renamed to "NuBgProc-ET-Short"
1220316.235:0168:warn:threadname:dispatch_exception Thread renamed to "NuBgProc-ET-Short"
1220316.236:0024:warn:threadname:dispatch_exception Thread ID 016c renamed to "USBHID_THREAD"
1220316.238:016c:warn:threadname:dispatch_exception Thread renamed to "USBHID_THREAD"
1220316.245:0024:warn:threadname:dispatch_exception Thread ID 0170 renamed to "m_readThread"
1220316.246:0024:warn:threadname:dispatch_exception Thread ID 0174 renamed to "m_decodeThread"
1220316.247:0170:warn:threadname:dispatch_exception Thread renamed to "m_readThread"
1220316.248:0174:warn:threadname:dispatch_exception Thread renamed to "m_decodeThread"
1220316.492:017c:warn:threadname:NtSetInformationThread Thread renamed to L"wine_xinput_hid_update"
1220316.499:0180:warn:threadname:NtSetInformationThread Thread renamed to L"wine_sechost_device_notify"
1220316.506:0184:warn:threadname:NtSetInformationThread Thread renamed to L"wine_rpcrt4_io"
1220316.514:0188:warn:threadname:NtSetInformationThread Thread renamed to L"wine_threadpool_worker"
1220316.666:0024:warn:threadname:dispatch_exception Thread ID 018c renamed to "Render"
1220316.667:018c:warn:threadname:dispatch_exception Thread renamed to "Render"
1220316.887:0024:warn:threadname:dispatch_exception Thread ID 0190 renamed to "TEXDECODE"
1220316.890:0190:warn:threadname:dispatch_exception Thread renamed to "TEXDECODE"
1220316.894:0024:warn:threadname:dispatch_exception Thread ID 0194 renamed to "NuUbershaderBytecodeCache::WorkerThreadFunc"
1220316.894:0024:warn:threadname:dispatch_exception Thread ID 0198 renamed to "NuUbershaderBytecodeCache::WorkerThreadFunc"
1220316.895:0024:warn:threadname:dispatch_exception Thread ID 019c renamed to "NuUbershaderBytecodeCache::WorkerThreadFunc"
1220316.897:0194:warn:threadname:dispatch_exception Thread renamed to "NuUbershaderBytecodeCache::Work"
1220316.897:0024:warn:threadname:dispatch_exception Thread ID 01a0 renamed to "NuUbershaderBytecodeCache::WorkerThreadFunc"
1220316.899:0024:warn:threadname:dispatch_exception Thread ID 01a4 renamed to "NuShaderManagerGen::WorkerThreadFunc"
1220316.900:0198:warn:threadname:dispatch_exception Thread renamed to "NuUbershaderBytecodeCache::Work"
1220316.902:019c:warn:threadname:dispatch_exception Thread renamed to "NuUbershaderBytecodeCache::Work"
1220316.903:01a0:warn:threadname:dispatch_exception Thread renamed to "NuUbershaderBytecodeCache::Work"
1220316.904:01a4:warn:threadname:dispatch_exception Thread renamed to "NuShaderManagerGen::WorkerThrea"

I’ve created block list as an array of thread names and decided to force skipping thread renamings from block list. After that I’ve recompiled nt.dll:

make dlls/ntdll/all
sudo make install

Nothing changed.

Hypothesis: avoid locking at all

Then I re-used the same block list again but decided to prevent locking on critical section in the first place.


/******************************************************************
 *		NtWaitForMultipleObjects (NTDLL.@)
 */
NTSTATUS WINAPI NtWaitForMultipleObjects( DWORD count, const HANDLE *handles, BOOLEAN wait_any,
                                          BOOLEAN alertable, const LARGE_INTEGER *timeout )
{
    select_op_t select_op;
    UINT i, flags = SELECT_INTERRUPTIBLE;

#ifdef __APPLE__
    // My ugly hack to work around exception around shader workers
    // I moved it here to make diff smaller for this post
    const char *expectedThreadNames[2];
    expectedThreadNames[0] = "NuUbershaderBytecodeCache::Work";
    expectedThreadNames[1] = "NuShaderManagerGen::WorkerThrea" ;
    int THREADNAME_LENGTH = 32;
    char threadName[THREADNAME_LENGTH];
    pthread_getname_np(pthread_self(), threadName, THREADNAME_LENGTH);
    TRACE("Thread name check pid=%p name=%s (%u) \n", pthread_self(), threadName, THREADNAME_LENGTH);
    for (size_t i = 0; i < 2; i++)
    {
        if (strcmp(threadName, expectedThreadNames[i]) == 0)
        {
            TRACE("Dirty hack has been applied\n");
            return 0;
        }
    }
#endif

This time the game entered endless loop. As a side effect, less started encountering segmentation faults.

Log analysis

The whole experience of digging through huge logs and jumping between grep and less was really awful. When less started failing, I became angry. Of course, I have picked the tool that I am using on a daily basis: Haskell.

{- build-depends:     base ^>=4.17.2.1
                    , bytestring
                    , conduit
                    , directory
                    , filepath
                    , optparse-applicative
-}
{-# LANGUAGE LambdaCase #-}
{-# LANGUAGE OverloadedStrings #-}
{-# LANGUAGE TypeApplications #-}
module Main where

import Conduit
import Control.Monad (join, when)
import Data.ByteString (ByteString)
import Data.Maybe (isJust)
import Options.Applicative
import System.Directory
import System.FilePath
import Text.Read (readMaybe)

import qualified Data.ByteString.Char8 as BSC
import qualified Data.Conduit.Combinators as CC

main :: IO ()
main = join $ execParser (info opts idm)

-- * CLI

opts :: Parser (IO ())
opts = subparser
  ( command "clean" (info clean (progDesc "Clean log output, if present"))
 <> command "run" (info start (progDesc "Run log analyzer"))
  )

inputArg :: Parser FilePath
inputArg = strOption (metavar "FILE" <> long "input" <> short 'i')

outArg :: Parser FilePath
outArg = strOption (metavar "DIR" <> long "output" <> short 'o')

clean :: Parser (IO ())
clean = runClean <$> outArg

start :: Parser (IO ())
start = run <$> inputArg <*> outArg

-- * File system helpers

withDirectory :: FilePath -> IO () -> IO ()
withDirectory dir continue = do
  doesDirectoryExist dir >>= \case
    False -> createDirectoryIfMissing True dir >> continue
    True -> continue

withFile :: FilePath -> IO () -> IO ()
withFile file continue =  do
  doesFileExist file >>= \case
    False -> error $ "File does not exist: " <> file
    True -> continue

-- * Logic

runClean :: FilePath -> IO ()
runClean out = withDirectory out $ removeDirectoryRecursive out

run :: FilePath -> FilePath -> IO ()
run inputFile outputDir = withDirectory outputDir $ withFile inputFile $ do
  runResourceT $ runConduit $
    sourceFile inputFile
    .| CC.linesUnboundedAscii
    .| CC.mapM (liftIO . lineBS outputDir)
    .| CC.sinkNull

lineBS :: FilePath -> ByteString -> IO ()
lineBS out l = case BSC.split ':' l of
  [] -> pure ()
  _ : [] -> pure ()
  t : tid : rest -> processLineMaybe out t tid rest

processLineMaybe :: FilePath -> ByteString -> ByteString -> [ByteString] -> IO ()
processLineMaybe out bt btid = \case
  [] -> pure ()
  bs@(b:_)
    | not (isTimestamp bt && isThreadId btid) -> pure ()
    | "Call " `BSC.isPrefixOf` b || "Ret " `BSC.isPrefixOf` b ->
        appendThreadLog out bt btid bs
    | otherwise -> case bs of
        _ : [] -> pure ()
        _ : _ : [] -> pure ()
        lvl : logsrc : _rest -> do
          appendThreadLog out bt btid bs
          appendLogSource out bt btid logsrc bs
          when (lvl `elem` ["warn", "err"]) $ appendLogLevel out bt btid lvl bs

appendThreadLog :: FilePath -> ByteString -> ByteString -> [ByteString] -> IO ()
appendThreadLog out bt btid bs = do
  let file = out </> BSC.unpack btid <.> "log"
  BSC.appendFile file $ (BSC.intercalate ":" (bt : btid : bs)) <> "\n"

appendLogSource
  :: FilePath -> ByteString -> ByteString -> ByteString -> [ByteString] -> IO ()
appendLogSource out bt btid logsrc bs = do
  let file = out </> BSC.unpack logsrc <.> "log"
  BSC.appendFile file $ (BSC.intercalate ":" (bt : btid : bs)) <> "\n"
  
appendLogLevel
  :: FilePath -> ByteString -> ByteString -> ByteString -> [ByteString] -> IO ()
appendLogLevel out bt btid lvl bs = do
  let file = out </> BSC.unpack lvl <.> "log"
  BSC.appendFile file $ (BSC.intercalate ":" (bt : btid : bs)) <> "\n"
  
-- * Parsers

isTimestamp :: ByteString -> Bool
isTimestamp = isJust . readMaybe @Double . BSC.unpack

isThreadId :: ByteString -> Bool
isThreadId = isJust . readMaybe @Int . BSC.unpack . ("0x" <>)

The whole log was split onto many small log files: - by threads, - by channels, - and by log levels.

That was a game changer (pun intended).

CWD

I have started to read all log files separately, thread by thread, channel by channel. And stumbled upon interesting finding. Game was trying to read STUFF all the time!

Some threads tried to access files from stuff directory.

1220316.237:0150:trace:file:CreateFileW L"\\?\\stuff\\ttbmetadata.xml" GENERIC_READ FILE_SHARE_READ  creation 3 attributes 0x0
1220316.237:0190:trace:file:CreateFileW L"\\?\\stuff\\LENSFLARECORONA_DX11.TEX" GENERIC_READ FILE_SHARE_READ  creation 3 attributes 0x0

It could not find files but it tried to access root (/) and home ($HOME) directories of host system and my user. Those files were something new to me. It is not following naming convention of directories on file system. It was a game itself!

All that time I was launching the game from $HOME. I have modified runner script to navigate into game directory and tried again.

export WINEDEBUG="+timestamp,+dxgi,+d3d,+loadall,+module,+winediag,+warn,+debug,+vulkan,+thread,+sync,+msg,+key,+threadname,+file,+debugstr,+mmsys,+msync,+graphics,+message,+msvcrt,+setupapi,+rpc,+advapi,+imm,+gdi,+ole,+trace,+relay,trace+seh,+unwind,+virtual,+heap"
export WINEPREFIX="$HOME/lego7"

cd $WINEPREFIX/drive_c/Games/LMSH2
wine 'LEGOMARVEL2_DX11.exe' &> /dev/null # ~/LEGOMARVEL2_DX11.log

And I saw this:

It was such a relief to be able to see those logos and trademarks!

Debug loop

Use log produced by wine as main entry point of debug loop.

For each impacted thread: examine thread log entries for clues.
Analyse behaviour navigating by source files.
Check for missing debug channels in source code of DLLs that raised a clue.
If no clues left, examine THREAD_ATTACH calls to get the idea what libraries were involved.
Add missing debug channels, re-run.
Read until you find a clue. Repeat.

There is an excellent guide on how to debug application under Wine: Debugging Wine.

Timeline

From the explanation it could be seen that some talent needed to do any of that. Or that it was a matter of days to fix it. No, I am not that smart. In a nutshell it took me three months just to change the directory! Just think about it. Moreover, 6 wine prefices were corrupted beyond repair.

I have just had enough patience to go slowly through all the details. Here is the whole timeline:

Jan 29: BSOD, attempts to ressurect BootCamp partition
Feb 12: brew install wine-stable
Feb 13: switch from renderer=gl to renderer=vulkan
Feb 14: different versions of DXVK.
Feb 22: D3DMetal attempt.
Feb 29: managed to build DXVK from sources.
Mar 01: first black screen, Critical Section.
Mar 03: started to build MoltenVK from sources,
Mar 05: failed assertion Texture Descriptor Validation issue, native atomics regression.
Mar 06: re-test after MR being merged.
Mar 07: Downgrading MoltenVK to 1.2.7.
Mar 09: reproduced black screen the second time, Critical Section issue.
Mar 13: patching wine with ugly hack for the first time.
Mar 17: patching wine with even more ugly hack for the second time.
Apr 21: had idea about splitting logs.
Apr 28: split logs for the first time.
May 04: finished reading logs, found missing files.
May 05: changed entry point in the game, success!

Epilogue

In this brief blogpost I have briefly described:

the story on how to solve the issue with the game being restored after a sudden corruption of BootCamp partition,
Wine overview, tooling, installation, configuration and game app launch,
debug loop.

I hope you enjoyed reading it.

Thank you!

Posted on 2024-05-12 by agr . Powered by Hakyll. Inspired by Yann Esposito.

Andrey Prokopenko's Blog

Debugging game on MacOS via wine