Severe startup latencies for Windows applications run under wine

[Ben Peddell]

On 08/30/11 10:33, Alan W. Irwin wrote:
> On 2011-08-30 08:20+1000 Ben Peddell wrote:
>> Some things I have seen while investigating:
>>
>> I created a program which had a startup that immediately called
>> ExitProcess to attempt to eliminate most of the initialization of the
>> process being forked.
>>
>> On Windows 7 x64 SP1 on an AMD 5050e:
>> bash.exe takes about 22.2ms to fork.
>> make.exe takes about 8.8ms to fork.
>> cmd.exe takes about 5.9ms to fork.
>>
>> Under wine 1.2.1 on linux 2.6.38 on an AMD 5050e:
>> bash.exe takes about 236ms to fork nothing, and 182ms to fork /bin/true.
>> make.exe takes about 77ms to fork nothing, and 25ms to fork /bin/true.
>> wine-cmd takes about 9ms to fork nothing.
>>
>> Under wine-git on linux 2.6.38 on an AMD 5050e:
>> bash.exe takes about 190ms to fork nothing, and 147ms to fork /bin/true
>> make.exe takes about 71ms to fork nothing and 20ms to fork /bin/true.
>> wine-cmd takes about 9ms to fork nothing.
> 
> Just out of curiosity do you have any explanation of why /bin/true provided
> faster make.exe results than your quick-exiting programme both for
> wine-1.2.1 and wine-git?

I suspect that the fork/exec emulation detects if the executable is a
MSYS executable, and if so, takes a fast path, skipping a lot of the
initialization that the MSYS executable would have done.

> 
>>
>> Even the native bash takes twice as long to fork as make - 1.1ms vs
>> 0.5ms.
>>
>> It looks to me like the fork emulation in MSYS is encountering a
>> bottleneck, and not actual process creation.
> 
> I assume you meant "encountering a _wine_ bottleneck" since clearly
> above your MSYS tests of make.exe and bash.exe on Windows don't have
> the large startup latencies you encounter with wine-1.2 and wine-git.
> 
> How does the MSYS version of make (make.exe that you tried above)
> compare in this regard with the MinGW version of make
> (MinGW/bin/mingw32-make.exe) that specifically excludes everything to
> do with MSYS?  My guess is you will encounter a similar wine
> bottleneck for this case as well, but it is worth verifying that.

I suspect mingw32-make uses fork() emulation when launching MSYS
programs, and CreateProcess() otherwise - the execution time for
msys-echo and msys-true are on par with those under msys-make, and the
execution time for ExitProcess.exe is on par with that under wine-cmd.

> 
> And now you have done a clean comparison with the same software stack
> it is clear that wine-git somewhat reduces the bottleneck compared to
> wine-1.2.  Thus, I expect my own planned clean comparisons to show the
> same.  So I have changed the subject line appropriately.
> 
> Now, if someone could just figure out what the wine bottleneck is that
> is causing these severe start-up latencies for Windows applications....

A modification of the timestamp patch from Bernhard Loos should help us
find what calls are taking the longest.

bash: running /bin/echo:
   +0ms:0024:Call KERNEL32.CreateProcessA(bash) => tid 0028
   +8ms:0028:Call KERNEL32.__wine_kernel_init()
  +11ms:0024:Call KERNEL32.WaitForMultipleObjects()
  +21ms:0028:DLLs loading
  +43ms:0028:Process starting
  +45ms:0028:Call KERNEL32.SetEvent() => wake 0024
  +45ms:0024:Call KERNEL32.WriteProcessMemory()
  +45ms:0028:Call KERNEL32.WaitForSingleObject()
        write-process-memory 10 times, totalling 500kB
 +134ms:0024:Ret  KERNEL32.WriteProcessMemory()
 +134ms:0028:Ret  KERNEL32.SetFileApisToANSI() ???
 +148ms:0028:Call KERNEL32.CreateProcessA(echo) => tid 002b
 +155ms:002b:Call KERNEL32.__wine_kernel_init()
 +157ms:0028:Ret  KERNEL32.CreateProcessA()
 +158ms:0028:Call KERNEL32.WaitForMultipleObjects()
 +163ms:002b:DLLs loading
 +163ms:002b:Process starting
 +169ms:0028:Call KERNEL32.ExitProcess()
 +172ms:002b:Call KERNEL32.ExitProcess()

bash: running ExitProcess.exe:
   +0ms:0024:Call KERNEL32.CreateProcessA(bash) =>  tid 0034
   +7ms:0034:Call KERNEL32.__wine_kernel_init()
  +11ms:0024:Call KERNEL32.WaitForMultipleObjects()
  +20ms:0034:DLLs loading
  +42ms:0034:Process starting
  +44ms:0034:Call KERNEL32.SetEvent() => wake 0024
  +44ms:0024:Call KERNEL32.WriteProcessMemory()
  +44ms:0034:Call KERNEL32.WaitForSingleObject()
        write-process-memory 10 times, totalling 500kB
 +130ms:0024:Ret  KERNEL32.WriteProcessMemory()
 +130ms:0034:Ret  KERNEL32.WaitForSingleObject()
        looking at attributes of a whole heap of directories...
 +215ms:0034:Call KERNEL32.CreateProcessA(ExitProcess.exe) => tid 0037
 +221ms:0037:Call KERNEL32.__wine_kernel_init()
 +223ms:0034:Ret  KERNEL32.CreateProcessA()
 +224ms:0034:Call KERNEL32.WaitForMultipleObjects()
 +224ms:0037:Call KERNEL32.ExitProcess()
 +225ms:0034:Call KERNEL32.ExitProcess()

-- 
Ben Peddell
IT Support Bowen, Collinsville, Proserpine and Home Hill Catholic schools
http://klightspeed.killerwolves.net/