Severe regression in wine startup latencies
The startup latency of commands run under wine-1.3.27 is much worse than it used to be. I did the following experiment with bash-3.1.17 that you get with the latest (mingw-get-inst-20110802.exe) MinGW/MSYS installer. wineconsole --backend=curses MinGW/msys/1.0/bin/bash.exe Then I ran the following commands within that MSYS bash environment. bash.exe-3.1$ which echo /z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe bash.exe-3.1$ time echo "hello" hello real 0m0.000s user 0m0.000s sys 0m0.000s This shows there is at least one command (echo) available under wine that executes with essentially zero latency. So the problem cannot be the time wine takes to read the executable file (/z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe in this case). But the rest of the commands I tried had latencies near 1 second. (I only report the second run in each case to make sure as much as possible is cached in memory for maximum speed.) bash.exe-3.1$ time bash --version GNU bash, version 3.1.17(1)-release (i686-pc-msys) Copyright (C) 2005 Free Software Foundation, Inc. real 0m0.905s user 0m0.160s sys 0m0.060s bash.exe-3.1$ time cmake-2.8.5-win32-x86/bin/cmake --version cmake version 2.8.5 real 0m0.922s user 0m0.080s sys 0m0.020s bash.exe-3.1$ time make --version GNU Make 3.81 Copyright (C) 2006 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. This program built for i686-pc-msys real 0m0.540s user 0m0.100s sys 0m0.020s bash.exe-3.1$ time gcc --version gcc.exe (GCC) 4.5.2 Copyright (C) 2010 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. real 0m0.901s user 0m0.080s sys 0m0.040s Those are horrendous latencies. The last time I did such tests (for wine-1.3.9) the corresponding latency numbers were almost an order of magnitude better, and Linux latencies were two orders (!) of magnitude better than these. ==============Linux latency results here To prove those Linux latency results once again here are the corresponding results under Linux: wine(a)raven> which echo /bin/echo wine(a)raven> time echo "hello" hello real 0m0.000s user 0m0.000s sys 0m0.000s wine(a)raven> time bash --version GNU bash, version 4.1.5(1)-release (x86_64-pc-linux-gnu) Copyright (C) 2009 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software; you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. real 0m0.001s user 0m0.004s sys 0m0.000s wine(a)raven> time cmake --version cmake version 2.8.2 real 0m0.008s user 0m0.004s sys 0m0.008s wine(a)raven> time make --version GNU Make 3.81 Copyright (C) 2006 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. This program built for x86_64-pc-linux-gnu real 0m0.001s user 0m0.004s sys 0m0.000s wine(a)raven> time gcc --version gcc (Debian 4.4.5-8) 4.4.5 Copyright (C) 2010 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. real 0m0.001s user 0m0.000s sys 0m0.000s ==========End of Linux latency results I compiled wine-1.3.27 with -O3, and I run it with the wineserver turned on and export WINEDEBUG='fixme-all' Why is its command startup latency typically an order of magnitude worse than previous wine versions (1.3.9 is the one I previously tested in detail), and ~two orders of magnitude worse than the Linux case? Although startup latencies are not much of an issue if you are running just one command such as a game, they are a serious issue for those like me attempting to build software on the wine platform. I previously complained here about this issue for cmake-1.3.9 where cmake configuration and make commands were roughly 2-3 times slower than the corresponding Linux case because both commands execute _a lot_ of subcommands where latency delays accumulate like crazy. But now that the wine-1.3.27 latency is 10 times worse than in the 1.3.9 case, typical cmake configurations are something like 25 (!) times slower than the corresponding Linux command. What can be done to address this bad command-startup latency regression for wine? I would be happy to run any tests that might point to a solution. For example, I did run "top" from time to time while running the very long cmake configuration step, and the cpu's (I have a duo core system) were mostly idle indicating the latency bottleneck (whatever it is) does not involve excessive amounts of cpu time. However, wineserver was always high in the "top" list of commands that were grabbing the most cpu. If wine sets up a detailed GUI environment for every command it runs is there an easy way to turn that off in case that is the cause of the startup latency? (All the builds I want to do on the MinGW/MSYS/wine platform are strictly from the MSYS bash command line with no GUI required.) Alan __________________________ Alan W. Irwin Astronomical research affiliation with Department of Physics and Astronomy, University of Victoria (astrowww.phys.uvic.ca). Programming affiliations with the FreeEOS equation-of-state implementation for stellar interiors (freeeos.sf.net); the Time Ephemerides project (timeephem.sf.net); PLplot scientific plotting software package (plplot.sf.net); the libLASi project (unifont.org/lasi); the Loads of Linux Links project (loll.sf.net); and the Linux Brochure Project (lbproject.sf.net). __________________________ Linux-powered Science __________________________
On Sat, Aug 27, 2011 at 5:22 PM, Alan W. Irwin <irwin(a)beluga.phys.uvic.ca> wrote: [...]
bash.exe-3.1$ which echo /z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe
bash.exe-3.1$ time echo "hello" hello
real 0m0.000s user 0m0.000s sys 0m0.000s
This shows there is at least one command (echo) available under wine that executes with essentially zero latency. So the problem cannot be the time wine takes to read the executable file (/z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe in this case). But the rest of the commands I tried had latencies near 1 second. (I only report the second run in each case to make sure as much as possible is cached in memory for maximum speed.)
Aside from any actual slowdown, this test is not accurate - echo is a shell builtin. Try timing running the actual echo executable (with full path) rather than just "echo" (which will run the builtin).
On 2011-08-27 18:11-0700 Daniel Verkamp wrote:
On Sat, Aug 27, 2011 at 5:22 PM, Alan W. Irwin <irwin(a)beluga.phys.uvic.ca> wrote: [...]
bash.exe-3.1$ which echo /z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe
bash.exe-3.1$ time echo "hello" hello
real 0m0.000s user 0m0.000s sys 0m0.000s
This shows there is at least one command (echo) available under wine that executes with essentially zero latency. So the problem cannot be the time wine takes to read the executable file (/z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe in this case). But the rest of the commands I tried had latencies near 1 second. (I only report the second run in each case to make sure as much as possible is cached in memory for maximum speed.)
Aside from any actual slowdown, this test is not accurate - echo is a shell builtin. Try timing running the actual echo executable (with full path) rather than just "echo" (which will run the builtin).
You are absolutely right. bash.exe-3.1$ time /z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe hello hello real 0m0.503s user 0m0.080s sys 0m0.020s Also, I tried time (x; x; x; x; x; x; x; x; x; x), where "x" represents the complete echo command above, and the result was real 0m5.281s user 0m0.800s sys 0m0.200s In other words, it is the executable echo command that has the latency, not the built-in "time" command or built-in echo command. I have done some other time tests on MSYS bash built-ins such as test, and they were essentially instantaneous as well while the executable versions were slow (~0.5 seconds like above). Does this difference between built-in and executable latency give a clue about what the issue is? To move to a slightly different topic, after reviewing my previous notes about the 0.150 second latency of commands for 1.2-rc3 (the last time I checked this), it appears that I tested latency a different way, e.g., wine(a)raven> time wine MinGW/bin/mingw32-make.exe --version GNU Make 3.82 Built for i386-pc-mingw32 Copyright (C) 2010 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. real 0m0.405s user 0m0.080s sys 0m0.040s A half second is a huge amount of computer time. This time does not appear to be due to wine setup since if you misspell the executable name you get fast results: wine(a)raven> time wine MinGW/bin/mingw32-make.exe1 --version wine: cannot find 'MinGW/bin/mingw32-make.exe1' real 0m0.006s user 0m0.000s sys 0m0.008s This style of latency check corresponds to the cmake "MinGW Makefiles" generator approach which builds with pure MinGW commands without using MSYS at all so these sorts of latency checks are still relevant to the fundamental question of reducing overall latency of CMake builds on wine. My notes imply the above correctly spelled command took only 0.150 seconds for 1.2-rc3 which implies a factor of 3 regression in latency for wine 1.3.27. However, for those old tests my MinGW/MSYS software stack was different so I will attempt to replicate them again (and also the bash timing versions above) with the only change being wine-1.2 versus wine-1.3.27. I will also, just for kicks, try wine-bash (a much older bash version that started as a port of bash to NT) timing tests as well for the two wine versions. While I am doing those additional investigations, please consider the question of why there is a huge difference between built-in and executable latency for MSYS bash commands under wine. To start that investigation it would be good to compare the wine results for those two cases with the Windows results for those two cases. (I assume the two time results for built-in versus executable will be fairly similar in the Windows case, but that assumption needs to be checked.) I don't have access to Windows myself. Anybody up for doing that simple test and reporting the results back here? The automatic MinGW/MSYS installer at http://sourceforge.net/projects/mingw/files/Automated MinGW Installer/mingw-get-inst/ makes it easy to install the relevant MinGW/MSYS software on both wine and Windows. Alan __________________________ Alan W. Irwin Astronomical research affiliation with Department of Physics and Astronomy, University of Victoria (astrowww.phys.uvic.ca). Programming affiliations with the FreeEOS equation-of-state implementation for stellar interiors (freeeos.sf.net); the Time Ephemerides project (timeephem.sf.net); PLplot scientific plotting software package (plplot.sf.net); the libLASi project (unifont.org/lasi); the Loads of Linux Links project (loll.sf.net); and the Linux Brochure Project (lbproject.sf.net). __________________________ Linux-powered Science __________________________
On 29/08/2011 2:37 AM, Alan W. Irwin wrote:
bash.exe-3.1$ time /z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe hello hello
real 0m0.503s user 0m0.080s sys 0m0.020s
Also, I tried time (x; x; x; x; x; x; x; x; x; x), where "x" represents the complete echo command above, and the result was
real 0m5.281s user 0m0.800s sys 0m0.200s [snip]
While I am doing those additional investigations, please consider the question of why there is a huge difference between built-in and executable latency for MSYS bash commands under wine. To start that investigation it would be good to compare the wine results for those two cases with the Windows results for those two cases. (I assume the two time results for built-in versus executable will be fairly similar in the Windows case, but that assumption needs to be checked.) I don't have access to Windows myself. Anybody up for doing that simple test and reporting the results back here? The automatic MinGW/MSYS installer at http://sourceforge.net/projects/mingw/files/Automated MinGW Installer/mingw-get-inst/ makes it easy to install the relevant MinGW/MSYS software on both wine and Windows.
Under MSYS 1.0.17 running on Windows 7 x64 SP1: bash.exe-3.1$ /bin/bash --version GNU bash, version 3.1.17(1)-release (i686-pc-msys) Copyright (C) 2005 Free Software Foundation, Inc. bash.exe-3.1$ alias x='/bin/echo.exe -n .' bash.exe-3.1$ time x . real 0m0.031s user 0m0.000s sys 0m0.015s bash.exe-3.1$ time (x;x;x;x;x;x;x;x;x;x) .......... real 0m0.296s user 0m0.075s sys 0m0.136s This shows a latency of approximately 2 jiffies for each command - 1 jiffy in Windows is 15.6ms. -- Ben Peddell IT Support Bowen, Collinsville, Proserpine and Home Hill Catholic schools http://klightspeed.killerwolves.net/
On 2011-08-29 07:56+1000 Ben Peddell wrote:
On 29/08/2011 2:37 AM, Alan W. Irwin wrote:
bash.exe-3.1$ time /z/home/wine/newstart1/MinGW/msys/1.0/bin/echo.exe hello hello
real 0m0.503s user 0m0.080s sys 0m0.020s
Also, I tried time (x; x; x; x; x; x; x; x; x; x), where "x" represents the complete echo command above, and the result was
real 0m5.281s user 0m0.800s sys 0m0.200s [snip]
While I am doing those additional investigations, please consider the question of why there is a huge difference between built-in and executable latency for MSYS bash commands under wine. To start that investigation it would be good to compare the wine results for those two cases with the Windows results for those two cases. (I assume the two time results for built-in versus executable will be fairly similar in the Windows case, but that assumption needs to be checked.) I don't have access to Windows myself. Anybody up for doing that simple test and reporting the results back here? The automatic MinGW/MSYS installer at http://sourceforge.net/projects/mingw/files/Automated MinGW Installer/mingw-get-inst/ makes it easy to install the relevant MinGW/MSYS software on both wine and Windows.
Under MSYS 1.0.17 running on Windows 7 x64 SP1:
bash.exe-3.1$ /bin/bash --version GNU bash, version 3.1.17(1)-release (i686-pc-msys) Copyright (C) 2005 Free Software Foundation, Inc.
bash.exe-3.1$ alias x='/bin/echo.exe -n .'
bash.exe-3.1$ time x . real 0m0.031s user 0m0.000s sys 0m0.015s
bash.exe-3.1$ time (x;x;x;x;x;x;x;x;x;x) .......... real 0m0.296s user 0m0.075s sys 0m0.136s
This shows a latency of approximately 2 jiffies for each command - 1 jiffy in Windows is 15.6ms.
-- Ben Peddell IT Support Bowen, Collinsville, Proserpine and Home Hill Catholic schools http://klightspeed.killerwolves.net/
Thanks, Ben, for doing the requested test for the executable echo test. That shows the Windows startup latency is measureable but acceptable for that executable. Just out of curiosity, what happens for the corresponding bash executable built-in echo functionality? Is it essentially instantaneous (i.e., elapsed time less than 0.001 seconds) like in the wine case? Alan __________________________ Alan W. Irwin Astronomical research affiliation with Department of Physics and Astronomy, University of Victoria (astrowww.phys.uvic.ca). Programming affiliations with the FreeEOS equation-of-state implementation for stellar interiors (freeeos.sf.net); the Time Ephemerides project (timeephem.sf.net); PLplot scientific plotting software package (plplot.sf.net); the libLASi project (unifont.org/lasi); the Loads of Linux Links project (loll.sf.net); and the Linux Brochure Project (lbproject.sf.net). __________________________ Linux-powered Science __________________________
On 29/08/2011 2:37 AM, Alan W. Irwin wrote:
While I am doing those additional investigations, please consider the question of why there is a huge difference between built-in and executable latency for MSYS bash commands under wine. To start that investigation it would be good to compare the wine results for those two cases with the Windows results for those two cases. (I assume the two time results for built-in versus executable will be fairly similar in the Windows case, but that assumption needs to be checked.) I don't have access to Windows myself. Anybody up for doing that simple test and reporting the results back here? The automatic MinGW/MSYS installer at http://sourceforge.net/projects/mingw/files/Automated MinGW Installer/mingw-get-inst/ makes it easy to install the relevant MinGW/MSYS software on both wine and Windows.
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 execute a program. * make.exe takes about 8.8ms to execute a program. * cmd.exe takes about 5.9ms to execute a program. Under wine 1.2.1 on linux 2.6.38 on an AMD 5050e: * bash.exe takes about 236ms to execute a program. * bash.exe takes about 182ms to execute ${MINGW}/bin/true. * make.exe takes about 77ms to execute a program. * make.exe takes about 25ms to execute ${MINGW}/bin/true. * wine-cmd takes about 9ms to execute a program. Under wine-git on linux 2.6.38 on an AMD 5050e: * bash.exe takes about 190ms to execute a program. * bash.exe takes about 147ms to execute ${MINGW}/bin/true. * make.exe takes about 71ms to execute a program. * make.exe takes about 20ms to execute ${MINGW}/bin/true. * wine-cmd takes about 9ms to execute a program. 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. Times have actually improved between 1.2 and current. -- Ben Peddell IT Support Bowen, Collinsville, Proserpine and Home Hill Catholic schools http://klightspeed.killerwolves.net/
participants (3)
-
Alan W. Irwin -
Ben Peddell -
Daniel Verkamp