Lot of wait_for_withdrawn_state when running with xvfb-run

[marto]

Hello There,

I'm trying to run Keil (an ARM "IDE") through wine for CI. It works quite ok on my machine, but on CI (w/o X server), it's very slow.
I'm running version 2.0 from debian, but I experience the same behavior with version 3.4 (debian package). Below are traces from version 3.4.

Here is the log with my X server:

Code: Select all

$(git root)/tools/wine-keil-build.sh -c -X Tests 2>&1 | ts -s '%.S'
00.000010 [*] Build: Tests
00.000081 [+] Cleaning
00.768396 0009:fixme:ntdll:EtwEventRegister ({5eec90ab-c022-44b2-a5dd-fd716a222a15}, 0x401123, 0xac04c0, 0xac04d8) stub.
00.768450 0009:fixme:ntdll:EtwEventSetInformation (deadbeef, 2, 0xa831b0, 43) stub
00.864385 0009:fixme:nls:GetThreadPreferredUILanguages 00000038, 0x32fb44, 0x32fb54 0x32fb48
00.864441 0009:fixme:nls:get_dummy_preferred_ui_language (0x38 0x32fb44 0x32fb54 0x32fb48) returning a dummy value (current locale)
00.870597 0009:fixme:ntdll:EtwEventRegister ({5eec90ab-c022-44b2-a5dd-fd716a222a15}, 0x10001123, 0x1012a080, 0x1012a098) stub.
00.870812 0009:fixme:ntdll:EtwEventSetInformation (deadbeef, 2, 0x10122f70, 43) stub
00.953043 0009:err:winediag:WS_getaddrinfo Failed to resolve your host name IP
01.124562 002f:fixme:heap:RtlSetHeapInformation (nil) 1 (nil) 0 stub
02.046121 0009:fixme:dwmapi:DwmIsCompositionEnabled 0xae5e08
02.400873 0009:fixme:ver:GetCurrentPackageId (0x32fe24 (nil)): stub
02.401106 0009:fixme:ntdll:EtwEventUnregister (deadbeef) stub.
02.401128 0009:fixme:ntdll:EtwEventUnregister (0) stub.
02.412955 Keil: rc=0: No Errors or Warnings
02.420712 [-] clean took 00:00:03 (3s)

Now the output when wrapped with `xvfb-run`:

Code: Select all

$(git root)/tools/wine-keil-build.sh -c Tests 2>&1 | ts -s '%.S'
00.076517 [*] Build: Tests
00.076650 [+] Cleaning
00.908044 0009:fixme:ntdll:EtwEventRegister ({5eec90ab-c022-44b2-a5dd-fd716a222a15}, 0x401123, 0xac04c0, 0xac04d8) stub.
00.908097 0009:fixme:ntdll:EtwEventSetInformation (deadbeef, 2, 0xa831b0, 43) stub
00.988386 0009:fixme:nls:GetThreadPreferredUILanguages 00000038, 0x32fb44, 0x32fb54 0x32fb48
00.988437 0009:fixme:nls:get_dummy_preferred_ui_language (0x38 0x32fb44 0x32fb54 0x32fb48) returning a dummy value (current locale)
00.993844 0009:fixme:ntdll:EtwEventRegister ({5eec90ab-c022-44b2-a5dd-fd716a222a15}, 0x10001123, 0x1012a080, 0x1012a098) stub.
00.994055 0009:fixme:ntdll:EtwEventSetInformation (deadbeef, 2, 0x10122f70, 43) stub
01.089090 0009:err:winediag:WS_getaddrinfo Failed to resolve your host name IP
01.247396 002f:fixme:heap:RtlSetHeapInformation (nil) 1 (nil) 0 stub
03.938366 0009:fixme:event:wait_for_withdrawn_state window 0x102b6/c0004a wait timed out
05.964679 0009:fixme:event:wait_for_withdrawn_state window 0x102ce/c00050 wait timed out
07.982258 0009:fixme:event:wait_for_withdrawn_state window 0x102e6/c00056 wait timed out
10.086928 0009:fixme:event:wait_for_withdrawn_state window 0x1048e/c00077 wait timed out
12.134930 0009:fixme:event:wait_for_withdrawn_state window 0x20516/c00096 wait timed out
12.163493 0009:fixme:dwmapi:DwmIsCompositionEnabled 0xae5e08
14.174039 0009:fixme:event:wait_for_withdrawn_state window 0x10076/c00001 wait timed out
16.365767 0009:fixme:event:wait_for_withdrawn_state window 0x10076/c00001 wait timed out
18.461253 0009:fixme:event:wait_for_withdrawn_state window 0x1011a/c00019 wait timed out
20.463700 0009:fixme:event:wait_for_withdrawn_state window 0x1014e/c00020 wait timed out
22.464540 0009:fixme:event:wait_for_withdrawn_state window 0x10166/c00024 wait timed out
24.467038 0009:fixme:event:wait_for_withdrawn_state window 0x1018c/c00029 wait timed out
26.469603 0009:fixme:event:wait_for_withdrawn_state window 0x1019a/c0002b wait timed out
28.472320 0009:fixme:event:wait_for_withdrawn_state window 0x101ae/c0002e wait timed out
30.474829 0009:fixme:event:wait_for_withdrawn_state window 0x1024c/c0003a wait timed out
32.476570 0009:fixme:event:wait_for_withdrawn_state window 0x1027a/c00040 wait timed out
34.479178 0009:fixme:event:wait_for_withdrawn_state window 0x10298/c00045 wait timed out
36.481133 0009:fixme:event:wait_for_withdrawn_state window 0x202b2/c0004c wait timed out
38.483680 0009:fixme:event:wait_for_withdrawn_state window 0x202ca/c00052 wait timed out
40.486346 0009:fixme:event:wait_for_withdrawn_state window 0x202e2/c00058 wait timed out
42.487768 0009:fixme:event:wait_for_withdrawn_state window 0x1035e/c00064 wait timed out
44.490276 0009:fixme:event:wait_for_withdrawn_state window 0x2048a/c0007d wait timed out
46.492760 0009:fixme:event:wait_for_withdrawn_state window 0x104bc/c00080 wait timed out
46.553570 0009:fixme:ver:GetCurrentPackageId (0x32fe24 (nil)): stub
46.553838 0009:fixme:ntdll:EtwEventUnregister (deadbeef) stub.
46.553865 0009:fixme:ntdll:EtwEventUnregister (0) stub.
46.563195 Keil: rc=0: No Errors or Warnings
46.572766 [-] clean took 00:00:47 (47s)
46.578310 XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":99"
46.578577       after 185 requests (183 known processed) with 0 events remaining.
46.578602 XIO:  fatal IO error 11 (Resource temporarily unavailable) on X server ":99"
46.578615       after 34 requests (34 known processed) with 0 events remaining.

Notes:
- Except timing and '0009:fixme:event:wait_for_withdrawn_state window [xxx] wait timed out`, logs are the same.
- I already use the "IDE" in batch mode, but unfortunately it creates windows... (on my machine I can see windows appearing and disappearing).
- the XIO errors come from xvfb-run (when wine stops)

Versions:
- debian: strecth
- wine: 2.0 (from debian wine-development), or 3.4
- xvfb: 2:1.19.2-1+deb9u2

Any idea how I could get rid of this problem (here, I have a 43 seconds delay just for waiting something).

Thanks,

Marc.

[Bob Wya]

@Marc,

I presume you're doing something like:

Code: Select all

Xvfb :0 -screen 0 1024x768x16 &
DISPLAY=:0.0 wine my_app.exe

Your application X Windows are possibly staying in a Withdrawn (aka limbo) state - because Wine isn't drawing to the correct X (Xvfb) Display.

If you've still got no joy...

Then you could try compiling Wine with the wait_for_withdrawn_state() function disabled.
Each call to this function will have a 2 second pause - for Windows that are in a Withdrawn state.
Since you don't actually need X Window handling to work!

E.g.:

Code: Select all

--- wine.a/dlls/winex11.drv/event.c	2017-11-15 23:26:23.124003244 +0000
+++ wine.b/dlls/winex11.drv/event.c	2018-03-26 22:06:48.636938651 +0100
@@ -1328,2 +1328,4 @@ void wait_for_withdrawn_state( HWND hwnd
 
+	return;
+
     for (;;)

Bob

[marto]

Hey,

I have to use an X server otherwise wine complains about wrong DISPLAY (or driver), and my windows application even if it retruns 0 does not work as expected (i.e. does not clean/compile).

Thanks for the hint to directly patch wine, I'll have a look when time permits since compiling for x64 (on x64) environement does not look straighforward.

Marc.

[Bob Wya]

...

Thanks for the hint to directly patch wine, I'll have a look when time permits since compiling for x64 (on x64) environement does not look straighforward.

Marc.

I have a general Multilib Wine / Wine Staging build script for Debian / Ubuntu on Github.
The script allows supplying a directory (or multiple directories) of user patches (like the one I suggested above).
It's a pretty simple script that just "installs" Wine to your Linux user's home directory (i.e. not via your Package Manager).
You still need to install the WineHQ package(s) to get the necessary Wine runtime dependencies.
I've only tested the script on Ubuntu - but there is no reason it shouldn't run on Debian as well.
It uses dual Debian Schroot environments to do the x86 and amd64 builds of Wine.

In fact it would provide some useful extra testing for me - if you tried it out...

Thanks
Bob

[marto]

Re,

I tried to build from sources with https://github.com/wine-compholio/wine-packaging but as far as I understood it only compiled the 64 bit version, not the WoW64.

I tried your file with some modifications for debian (and zsh), and after some colors and time compiling, I now have a 1 or 2 seconds overhead:
- 3s to clean (2 reported by tool, approx the same time in real windows)
- 17s to build (14 reported by tool, approx the same time in a real windows)
Great ! \o/

But it still puzzles me, is this behavior (2s timeout) really wanted ? Where is the bug hidden ? On wine ? On xvfb ? Should we make this behavior configurable ?

I'm a little bit nervous on using a custom wine version to build on CI.

Thanks,

Marc.

[Bob Wya]

But it still puzzles me, is this behaviour (2s timeout) really wanted ? Where is the bug hidden ? On wine ? On xvfb ? Should we make this behaviour configurable ?

I'm a little bit nervous on using a custom wine version to build on CI.

I'd recommend filing a bug against your winex11 issue, on Xvfb, with

Code: Select all

export WINEDEBUG=+timestamp,+tid,+x11drv,+event
wine ...

The rather arbitrary 2 second delay looks highly dubious!

I wouldn't worry about the stability of a custom built version of Wine... That build script has been well tested.
Ideally of course it would build a "proper" deb package - with a control file listing the required and optional runtime package dependencies.

Bob