Long Wine init times since update to Proton 5.0

[magist3r]

Hi. I've noticed that Proton 5.0 take very long time to initialize. I wrote a small wrapper script to run different versions of Proton's Wine:

#!/bin/bash
_VERS="$1"
_GAME="$1test"
_STEAMDIR="/home/magist3r/.local/share/Steam/"
PATH="$_STEAMDIR/steamapps/common/Proton $_VERS/dist/bin/:$_STEAMDIR/ubuntu12_32/steam-runtime/amd64/bin:$_STEAMDIR/ubuntu12_32/steam-runtime/amd64/usr/bin:/home/magist3r/.cargo/bin:/home/magist3r/bin:/usr/local/bin:/usr/bin:/bin:/usr/lib/mit/sbin" \
    TERM="xterm" \
    WINEDEBUG="-all" \
    WINEDLLPATH="$_STEAMDIR/steamapps/common/Proton $_VERS/dist/lib64/wine:$_STEAMDIR/steamapps/common/Proton $_VERS/dist/lib/wine" \
    LD_LIBRARY_PATH="$_STEAMDIR/steamapps/common/Proton $_VERS/dist/lib64:$_STEAMDIR/steamapps/common/Proton $_VERS/dist/lib:$_STEAMDIR/ubuntu12_32/steam-runtime/pinned_libs_32:$_STEAMDIR/ubuntu12_32/steam-runtime/pinned_libs_64:/usr/local/lib64:/usr/local/lib:/usr/lib64/graphviz:/lib:/lib64:/usr/lib:/usr/lib64:/usr/lib/tls:/usr/lib64/tls:$_STEAMDIR/ubuntu12_32/steam-runtime/i386/lib/i386-linux-gnu:$_STEAMDIR/ubuntu12_32/steam-runtime/i386/lib:$_STEAMDIR/ubuntu12_32/steam-runtime/i386/usr/lib/i386-linux-gnu:$_STEAMDIR/ubuntu12_32/steam-runtime/i386/usr/lib:$_STEAMDIR/ubuntu12_32/steam-runtime/amd64/lib/x86_64-linux-gnu:$_STEAMDIR/ubuntu12_32/steam-runtime/amd64/lib:$_STEAMDIR/ubuntu12_32/steam-runtime/amd64/usr/lib/x86_64-linux-gnu:$_STEAMDIR/ubuntu12_32/steam-runtime/amd64/usr/lib:" \
    WINEPREFIX="$_STEAMDIR/steamapps/compatdata/$_GAME/" \
    WINEESYNC="1" \
    SteamGameId="$_GAME" \
    SteamAppId="$_GAME" \
    WINEDLLOVERRIDES="steam.exe=b;d3d11=n;d3d10=n;d3d10core=n;d3d10_1=n;dxgi=n" \
    STEAM_COMPAT_CLIENT_INSTALL_PATH="$_STEAMDIR" \
    WINE="$_STEAMDIR/steamapps/common/Proton $_VERS/dist/bin/wine" "$_STEAMDIR/steamapps/common/Proton $_VERS/dist/bin/wine" "$2"

And then issued two commands. For Proton 4.11:

time ./proton-wrapper.sh 4.11 wineboot
wine: created the configuration directory '/home/magist3r/.local/share/Steam//steamapps/compatdata/4.11test'
esync: up and running.
wine: configuration in '/home/magist3r/.local/share/Steam//steamapps/compatdata/4.11test' has been updated.

real    0m4,060s
user    0m0,011s
sys     0m0,009s

And for Proton 5.0:

time ./proton-wrapper.sh 5.0 wineboot
wine: created the configuration directory '/home/magist3r/.local/share/Steam//steamapps/compatdata/5.0test'
esync: up and running.
wine: configuration in L"/home/magist3r/.local/share/Steam//steamapps/compatdata/5.0test" has been updated.

real    0m27,873s
user    0m0,012s
sys     0m0,011s

As you can see, there is a huge difference. As a result I have to wait for minutes to launch a game with Proton 5.0.

[aeikum]

Hey @magist3r thanks for reporting. Can you give us information about your system (e.g. your distro and also the information from Help->System Information in Steam)? Also, what games do you see this with? I know it applies to all games, but humor me and list one or two, please.

It would also be helpful if you could do the same test you did above, but also gather logs with +pid,+seh,+process,+service,+steam,+plugplay,+explorer in WINEDEBUG and attach them here.

[magist3r]

Hi. I use OpenSUSE Tumbleweed. See systeminfo.txt. I mostly play RE7 and RE2 Remake.

Here are the logs with debug info (I added additional +timestamp key): 4.11.timestamp.log 5.0.timestamp.log

I've noticed that many calls like NtQueryInformationProcess (0xffffffffffffffff,0x0000001a takes 2s and more with wine 5.0. And I guess this is the main reason of the slowdown.

[aeikum]

Thanks again @magist3r . It could be that QueryInformationProcess call, that particular call invokes a server round trip. Can you get another 5.0 log with +server,+ntdll in addition to the other channels?

[magist3r]

This one is huge. Hope it helps. 5.0.zip

[rbernon]

Hi! I tried to reproduce the issue, and for me there's not much difference between Proton 4.11 and Proton 5.0. There's a big difference though if I use your wrapper script instead of the Proton debug script (with PROTON_DUMP_DEBUG_COMMANDS).

When using your wrapper I have a lot of fontconfig warnings being printed, and the initial prefix creation takes ~25s compared to ~5s when using the Proton debug script with no fontconfig warnings.

I pinpointed the root cause to missing /lib/i386-linux-gnu and /lib/x86_64-linux-gnu entries in your LD_LIBRARY_PATH, and I think it makes it load the steam runtime fontconfig instead of the system provided one. This might be distribution dependent though, as I'm on Debian.

Could you please see if you can make it try system fontconfig first? Usually I think steam runtime should come after system libraries, unless the library is "pinned" in $STEAMDIR/ubuntu12_32/steam-runtime/pinned_libs_32 or $STEAMDIR/ubuntu12_32/steam-runtime/pinned_libs_64.

[magist3r]

Hi @rbernon. Yes, my script was a bit outdated, so I updated it using PROTON_DUMP_DEBUG_COMMANDS. Here it is:

#!/bin/bash
#Run game or given command in environment

_VERS="$1"
_GAME="$1test"
_STEAMDIR="/home/magist3r/.local/share/Steam"
_PROTONDIR="$_STEAMDIR/steamapps/common/Proton $_VERS/dist"
_STEAMRUNTIMEDIR="$_STEAMDIR/ubuntu12_32/steam-runtime"
PATH="$_PROTONDIR/bin/:$_STEAMRUNTIMEDIR/amd64/bin:$_STEAMRUNTIMEDIR/amd64/usr/bin:$_STEAMRUNTIMEDIR/usr/bin:/home/magist3r/.cargo/bin:/home/magist3r/.local/bin:/home/magist3r/bin:/usr/local/bin:/usr/bin:/bin:/usr/lib/mit/sbin:/sbin" \
    TERM="xterm" \
    WINEDEBUG="-all" \
    WINEDLLPATH="$_PROTONDIR/lib64/wine:$_PROTONDIR/lib/wine" \
    LD_LIBRARY_PATH="$_PROTONDIR/lib64/:$_PROTONDIR/lib/:$_STEAMRUNTIMEDIR/pinned_libs_32:$_STEAMRUNTIMEDIR/pinned_libs_64:/usr/local/lib64:/usr/local/lib:/usr/lib64/graphviz:/lib:/lib64:/usr/lib:/usr/lib64:/usr/lib/tls:/usr/lib64/tls:$_STEAMRUNTIMEDIR/lib/i386-linux-gnu:$_STEAMRUNTIMEDIR/usr/lib/i386-linux-gnu:$_STEAMRUNTIMEDIR/lib/x86_64-linux-gnu:$_STEAMRUNTIMEDIR/usr/lib/x86_64-linux-gnu:$_STEAMRUNTIMEDIR/lib:$_STEAMRUNTIMEDIR/usr/lib:" \
    WINEPREFIX="$_STEAMDIR/steamapps/compatdata/$_GAME/" \
    WINEESYNC="1" \
        WINEFSYNC="1" \
    SteamGameId="$_GAME" \
    SteamAppId="$_GAME" \
    WINEDLLOVERRIDES="steam.exe=b;dxvk_config=n;d3d11=n;d3d10=n;d3d10core=n;d3d10_1=n;d3d9=n" \
    STEAM_COMPAT_CLIENT_INSTALL_PATH="$_STEAMDIR" \
    #WINEDEBUG="+pid,+seh,+process,+service,+steam,+plugplay,+explorer,+timestamp,+server,+ntdll" \
    WINE_LARGE_ADDRESS_AWARE="1" \
    WINE="$_PROTONDIR/bin/wine" "$_PROTONDIR/bin/wine" "$2"

But I don't see any differences. For me it takes about 30 seconds as before.

And I figured out that my system wine (actually wine-staging 5.9) has the same problem:

time WINEPREFIX=/home/magist3r/code/python-installcab/test wineboot > /dev/null 2>&1

real    0m39,620s
user    0m0,010s
sys     0m0,017s

[rbernon]

Could you please make a log of it with WINEDEBUG=+timestamp,+pid,+tid,+seh,+process,+service,+steam,+plugplay,+explorer,+font,+file? And possibly another with LD_DEBUG=libs to see if it's using steam runtime's fontconfig?

I think the NtQueryInformationProcess thing may be a red herring, there's many thing happening between these two calls.

[magist3r]

5.0_1.zip 5.0_2.zip

[rbernon]

Thanks! Sadly I still don't see much here, except that for every process, there's ~2s spent right after c_437.nls is loaded. Some more detailed traces could be useful, for instance adding +reg,+module to the previous WINEDEBUG.

However, doing that locally I can see that this is where COMPUTERNAME_Init is called, and this function has changed between Proton 4.11 and 5.0, now calling gethostname / gethostbyname_r every time where it was previously only conditionally doing it. I can imagine how these calls could induce some delay, so in order to check if it's the case, could you try saving this as gethostname.c:

#include <stdlib.h>
#include <string.h>
#include <netdb.h>

int gethostname(char *name, size_t size)
{
    name[0] = 0;
    return 0;
}

int gethostbyname_r(const char *name,
       struct hostent *ret, char *buf, size_t buflen,
       struct hostent **result, int *h_errnop)
{
    struct hostent *host = ret;
    host->h_name = buf + sizeof(*host);
    strcpy(host->h_name, name);
    *result = host;
    return 0;
}

Then build some shared objects with:

gcc -m32 -shared -o gethostname32.so gethostname.c
gcc -shared -o gethostname64.so gethostname.c

And then retry the prefix creation with an additional LD_PRELOAD=<dir>/gethostname64.so:<dir>/gethostname32.so environment (where <dir> is the absolute path where you built the shared objects), to override these functions?

Also, WINEDEBUG=+timestamp,+pid,+tid,+seh,+process,+service,+steam,+plugplay,+explorer,+font,+file,+reg,+module could be useful to see if it works and to get more detail.

[magist3r]

Yeah, it's much faster with LD_PRELOAD'ing dummy gethostname functions:

time ./proton-wrapper.sh 5.0 wineboot > 5.0.log 2>&1

real    0m6,349s
user    0m0,009s
sys     0m0,022s

Here is the complete log: 5.0_3.zip

[rbernon]

Alright, so I think the main issue comes from your network / DNS configuration. I'm not sure if we have to call these every time though, so there's maybe something that could be done in Wine but I really don't know why this was introduced and there's maybe a good reason.