Re: 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()

Severe startup latencies for Windows applications run under wine

[Octavian Voicu]

On Tue, Aug 30, 2011 at 6:56 PM, Ben Peddell wrote:
> A modification of the timestamp patch from Bernhard Loos should help us
> find what calls are taking the longest.

Speaking of that, I've been trying to compile cmd tests with profiling (-pg,
for use with gprof), but no luck. I added -pg to both compile & link phases.
Looking at disassembled .exe.so binary, it doesn't have the gprof code that
a proper gprof executable would have, so I'm guessing winegcc does some
magic that is not compatible with -pg. Anybody managed to make it work?

Octavian