os: using CommandLineToArgv slows process startup significantly

[jstarks]

Windows's os.init() calls syscall.CommandLineToArgv to split the Windows command line into separate arguments. This in turn loads shell32.dll and calls CommandLineToArgvW to do the actual work of splitting the command line. This is different from C programs generated by Microsoft's compiler, which use a nearly identical function in the CRT to do the splitting.

For a typical Go program, this is the only thing that causes shell32.dll to be loaded. Loading shell32 is expensive, since it depends on lots of additional DLLs -- on my machine shell32 loads 13 additional DLLs that would not otherwise be loaded.

By rewriting the algorithm from CommandLineToArgvW directly in go, we can eliminate the need to load all these extra DLLs. This algorithm is documented at https://msdn.microsoft.com/en-us/library/17w5ykft.aspx, although I have found that there is an undocumented special case where a " next to another " that ends a quoted argument should be included verbatim.

I have prototyped this change (3ae6766) and found on my machine that it reduces startup time for a simple Go program that pulls in os from 22ms to 16ms. The cost for this is about a 10KB increase in binary size.

If this approach seems worthwhile then I can send out a code review.

[alexbrainman]

Sounds good to me. Please send a code review. But it won't get submitted until after go1.7 is released - the tree is frozen at this moment. Thank you.

This will need a better test. We used to have a test for syscall.EscapeArg, but it's got lost over time. We would run Go process as a child of another Go process and make sure the arguments parent pass to the child match arguments received by the child. We would have a table of unusual arguments to test. We should resurrect that test. It will test your new code too. I suppose we could create new test regardless of your work. I will try and create this test if I have time.

Alex

[gopherbot]

CL https://golang.org/cl/22932 mentions this issue.

[alexbrainman]

I have prototyped this change (3ae6766) and found on my machine that it reduces startup time for a simple Go program that pulls in os from 22ms to 16ms.

@jstarks I do not see speed up you see. I cherry picked your CL 22932

git fetch https://go.googlesource.com/go refs/changes/32/22932/2 && git cherry-pick FETCH_HEAD

on top of 0a55a16 (current tip).

I run

go test -run=none -count=10 -bench=BenchmarkRunningGoProgram runtime

on my very old Windows XP computer

name old time/op new time/op delta
RunningGoProgram-2 11.3ms ± 2% 10.9ms ± 0% -3.11% (p=0.000 n=10+7)

and my not as old Windows 7 computer

name old time/op new time/op delta
RunningGoProgram 12.8ms ± 1% 12.7ms ± 2% ~ (p=0.075 n=10+9)

(I used github.com/rsc/benchstat to compare old and new benchmark output).

Do these figures look correct to you? What am I doing wrong?

Thank you.

Alex

[rsc]

@alexbrainman , where is BenchmarkRunningGoProgram? I don't see it in that CL.

[jstarks]

@alexbrainman Thanks for picking up the trail on this one (and the random number one too). The goal of this change is to stop loading shell32.dll into all Go processes; this is where the expense comes from. There are at least a couple possibilities why you're not seeing the improvement that I saw:

• I tested on Windows 10. It's possible (but unlikely) that in Windows 7 something else triggered a shell32 load, and so this change is insufficient to remove loading of shell32 on Windows 7.
• Perhaps Go took a dependency on shell32 somewhere else since I originally opened this issue.

One idea to figure this out is to use a debugger to determine whether shell32 is getting loaded during process run before and after the change.

[bradfitz]

@jstarks, makes sense, thanks. We can add a new regression test to make sure we don't introduce shell32 dependencies in the future. Is there a Windows API to list the DLLs loaded in the current process?

[randall77]

With our luck that API is implemented in shell32.dll...

[bradfitz]

Looks like this:

EnumProcessModules
https://msdn.microsoft.com/en-us/library/windows/desktop/ms682631(v=vs.85).aspx
....
"Kernel32.dll on Windows 7 and Windows Server 2008 R2;
Psapi.dll (if PSAPI_VERSION=1) on Windows 7 and Windows Server 2008 R2;
Psapi.dll on Windows Server 2008, Windows Vista, Windows Server 2003, and Windows XP"

[mattn]

Do you want to check whether go binary generated with this change doesn't depend on CommandLineToArgv? Then, how about debug/pe?

[mattn]

Ah, no. debug/pe doesn't handle dynamic loading. ignore this.

[alexbrainman]

where is BenchmarkRunningGoProgram?

It was introduced by CL 29700 - another "stop using some DLLs" CL. It has been submitted.

I tested on Windows 10

I will try and find Windows 10 to test on. @mattn you have Windows 10. Could you try my instructions #15588 (comment) and check if you see any improvements?

One idea to figure this out is to use a debugger to determine whether shell32 is getting loaded during process run before and after the change.

How would I do that?

Thank you.

Alex

[mattn]

@alexbrainman I tried below.

Master branch (tip)

BenchmarkRunningGoProgram-4          100      19012756 ns/op
BenchmarkRunningGoProgram-4          100      18341186 ns/op
BenchmarkRunningGoProgram-4          100      17870580 ns/op
BenchmarkRunningGoProgram-4          100      16630704 ns/op
BenchmarkRunningGoProgram-4          100      16070425 ns/op
BenchmarkRunningGoProgram-4          100      16098128 ns/op
BenchmarkRunningGoProgram-4          100      16262916 ns/op
BenchmarkRunningGoProgram-4          100      16038416 ns/op
BenchmarkRunningGoProgram-4          100      16597668 ns/op
BenchmarkRunningGoProgram-4          100      16061061 ns/op
PASS
ok      runtime 35.862s

CL 22932

Note that I couldn't merge the CL.

git fetch https://go.googlesource.com/go refs/changes/32/22932/2 && git cherry-pick FETCH_HEAD

So I merged following patch. This should be same change. Just small different in that modify export_windows_test.go.

https://gist.github.com/mattn/0909a877904be548a595be732fe2bba6

BenchmarkRunningGoProgram-4          100      16487445 ns/op
BenchmarkRunningGoProgram-4          100      16397856 ns/op
BenchmarkRunningGoProgram-4          100      17882113 ns/op
BenchmarkRunningGoProgram-4          100      16305931 ns/op
BenchmarkRunningGoProgram-4          100      16416084 ns/op
BenchmarkRunningGoProgram-4          100      16269289 ns/op
BenchmarkRunningGoProgram-4          100      16276717 ns/op
BenchmarkRunningGoProgram-4          100      16716923 ns/op
BenchmarkRunningGoProgram-4          100      16436663 ns/op
BenchmarkRunningGoProgram-4          100      16276931 ns/op
PASS
ok      runtime 34.002s

name                old time/op  new time/op  delta
RunningGoProgram-4  16.9ms ±13%  16.4ms ± 2%   ~     (p=0.905 n=10+9)

Intel Core i5 2.2GHz 8GB Mem
Windows10 64bit

[alexbrainman]

RunningGoProgram-4 16.9ms ±13% 16.4ms ± 2% ~ (p=0.905 n=10+9)

Thank you. That is what I see too on my computers.

I will try and use EnumProcessModules to make sure that new version does not uses shell32.dll as requested,. I will report here.

Alex

[alexbrainman]

I cherry picked CL 22932

git fetch https://go.googlesource.com/go refs/changes/32/22932/2 &&
git cherry-pick FETCH_HEAD

on top of f36e1ad (current tip)
again. I had to resolve small conflict as @mattn.

I run

go test -run=none -count=10 -bench=BenchmarkRunningGoProgram runtime

my Windows 7 computer

name old time/op new time/op delta
RunningGoProgram 12.8ms ± 4% 12.7ms ± 1% ~ (p=0.588 n=9+8)

my other Windows 7 computer

name old time/op new time/op delta
RunningGoProgram-2 10.2ms ± 1% 10.2ms ± 1% ~ (p=0.118 n=9+9)

my Windows 10 computer

name old time/op new time/op delta
RunningGoProgram-8 10.2ms ± 1% 10.3ms ± 3% ~ (p=0.447 n=9+10)

I also used "Process Explorer"
https://technet.microsoft.com/en-us/sysinternals/processexplorer.aspx
to make sure new version did not have shell32.dll loaded.

So I have no idea what else I can try.

One thing I noticed. On Windows 10 "Process Explorer" shows many more DLLs loaded for old version

comparing to new

Maybe my BenchmarkRunningGoProgram is the wrong way to measure small Go program running time. Suggestions are welcome.

Alex

[bradfitz]

Those p values (p=0.447) don't look good. Try running more than 10 iterations. Try like 100 or so.

[alexbrainman]

I did -count=20 on my Windows 7 computer. It is not much different

name old time/op new time/op delta
RunningGoProgram-2 10.3ms ± 2% 10.1ms ± 2% -2.14% (p=0.000 n=19+19)

I will sleep on it. Always helps.

Alex

[bradfitz]

Good p value (p=0.000) now, though.

[alexbrainman]

I tried looking where all the time goes in BenchmarkRunningGoProgram, and I noticed there is a time.Sleep in os.Process.wait that makes BenchmarkRunningGoProgram slower than it needs to be. I also thought, maybe that time.Sleep is so long, we do not notice CL 22932 improvements because that extra sleep is so large.

So I removed time.Sleep (see CL 31536 patch set 1). And then I cherry picked CL 22932 on top of that (see CL 31536 patch set 2). And then I tested performance improvements between CL 31536 base and ps1, and ps1 and ps2. As before I did

go test -run=none -count=10 -bench=BenchmarkRunningGoProgram runtime

I see this on my Windows XP:

base -> ps1:
name old time/op new time/op delta
RunningGoProgram-2 11.2ms ± 2% 5.8ms ± 1% -48.55% (p=0.000 n=10+9)

ps1 -> ps2:
name old time/op new time/op delta
RunningGoProgram-2 5.76ms ± 1% 5.76ms ± 2% ~ (p=0.646 n=9+10)

on Windows 7

base -> ps1:
name old time/op new time/op delta
RunningGoProgram 12.5ms ± 4% 6.7ms ± 1% -46.17% (p=0.000 n=10+10)

ps1 -> ps2:
name old time/op new time/op delta
RunningGoProgram 6.72ms ± 1% 6.86ms ± 4% +2.17% (p=0.017 n=10+10)

on another Windows 7

base -> ps1:
name old time/op new time/op delta
RunningGoProgram-2 10.2ms ± 1% 6.0ms ± 4% -41.01% (p=0.000 n=9+10)

ps1 -> ps2:
name old time/op new time/op delta
RunningGoProgram-2 6.01ms ± 4% 5.83ms ± 2% -2.88% (p=0.004 n=10+9)

on Windows 10 laptop

base -> ps1:
name old time/op new time/op delta
RunningGoProgram-4 20.5ms ± 2% 15.7ms ± 1% -23.55% (p=0.000 n=10+10)

ps1 -> ps2:
name old time/op new time/op delta
RunningGoProgram-4 15.7ms ± 1% 16.4ms ± 2% +4.90% (p=0.000 n=10+10)

So again I do not see much improvement in CL 22932. There is some speed up in removing time.Sleep in os.Process.wait (CL 31536 patch set 1), but all.bat fails during cmd/go testing with this change. I also tried replacing time.Sleep with SwitchToThread Windows API, but that still fails. It would be nice not to care if executable file is still locked after process completes, but a lot of our code depends on that.

Maybe Windows caches DLL well, so second execution of the same process is just quick. So I run make.bat against all versions of CL 31536 (I used github.com/alexbrainman/time to measure this):

my Windows XP:

CL 31536 base 1m23.984s 1m24.172s 1m23.938s
CL 31536 ps1 1m23.203s 1m22.953s 1m23.656s
CL 31536 ps2 1m22.344s 1m22.797s 1m23.234s

my Windows 7:

CL 31536 base 2m14.284s 1m57.884s 2m11.774s
CL 31536 ps1 1m59.779s 1m57.583s 2m1.458s
CL 31536 ps2 1m57.501s 1m58.761s 2m1.522s

And I do not see much improvements anywhere. Even removing time.Sleep from os.Process.wait does not look important.

I am out of ideas. Unless I can see some improvements, I do not think CL 22932 is worth the trouble.

Alex

[rsc]

Thanks @alexbrainman.

@jstarks, can you say more about the measurements you used to find that the startup time reduced from 22ms to 16ms? Those are enormous startup times to begin with. I wonder if something else was wrong on your system?

[rsc]

The sleep in os.Process.wait strikes again! (Just commented on #17245.)

It sounds like we need to understand that before we can understand whether we need to avoid shell32.dll.

[egonelbre]

Did some raw measurements against loading shell32 vs not-loading.

dynamic.exe, static.exe, none.exe are C programs that do nothing but only load shell32.dll run-time, load-time or not at all.

// average of 1000 runs, on Windows 10 x64

>timemem dynamic.exe 
Elapsed 10.987367ms
Kernel  8.375000ms
User    2.890625ms
PageFault     1254 KB
WorkingSet    4732219 KB
PagedPool     147729 KB
NonPagedPool  6432 KB
PageFileSize  1161183 KB

>timemem static.exe 
Elapsed 10.894525ms
Kernel  8.406250ms
User    3.046875ms
PageFault     1266 KB
WorkingSet    4764729 KB
PagedPool     147730 KB
NonPagedPool  6432 KB
PageFileSize  1166266 KB

>timemem none.exe 
Elapsed 3.543882ms
Kernel  2.250000ms
User    0.765625ms
PageFault     545 KB
WorkingSet    2108276 KB
PagedPool     21128 KB
NonPagedPool  3112 KB
PageFileSize  464617 KB 

Code here https://gist.github.com/egonelbre/d4c8bcc7e61b32fd42bedb2d6847b57a

[alexbrainman]

Did some raw measurements against loading shell32 vs not-loading.

Why do you measure loading shell32.dll vs loading nothing? Go needs quite a few DLLs (other than shell32.dll) to run. It would be more appropriate to start with a set of DLLs that Go uses, and compare that with the same set + shell32.dll.

Alex

[egonelbre]

Sure... I collected all dll names found in stdlib, code here https://gist.github.com/egonelbre/ab6c7a4a004227a168a8229656e9863c (and binaries)

Also added 32bit vs 64bit comparison, just in case...

"32bit none"

> timemem -n 1000 loader.32.exe 
Elapsed       6.632988ms
Kernel        4.562500ms
User          1.640625ms
PageFault     842 KB
WorkingSet    3207196 KB
PagedPool     26564 KB
NonPagedPool  5144 KB
PageFileSize  926793 KB

"32bit stdlib"

> timemem -n 1000 loader.32.exe kernel32.dll advapi32.dll shell32.dll mswsock.dll crypt32.dll ws2_32.dll dnsapi.dll iphlpapi.dll secur32.dll netapi32.dll userenv.dll winmm.dll 
Elapsed       19.552634ms
Kernel        17.343750ms
User          5.250000ms
PageFault     1621 KB
WorkingSet    6055870 KB
PagedPool     147967 KB
NonPagedPool  9639 KB
PageFileSize  2017587 KB

"32bit stdlib wo shell32"

> timemem -n 1000 loader.32.exe kernel32.dll advapi32.dll mswsock.dll crypt32.dll ws2_32.dll dnsapi.dll iphlpapi.dll secur32.dll netapi32.dll userenv.dll winmm.dll 
Elapsed       17.698333ms
Kernel        15.171875ms
User          4.343750ms
PageFault     1331 KB
WorkingSet    4973576 KB
PagedPool     92711 KB
NonPagedPool  8472 KB
PageFileSize  1548333 KB

"64bit none"

> timemem -n 1000 loader.64.exe 
Elapsed       4.072379ms
Kernel        2.218750ms
User          0.828125ms
PageFault     568 KB
WorkingSet    2186186 KB
PagedPool     21216 KB
NonPagedPool  3456 KB
PageFileSize  546955 KB

"64bit stdlib"

> timemem -n 1000 loader.64.exe kernel32.dll advapi32.dll shell32.dll mswsock.dll crypt32.dll ws2_32.dll dnsapi.dll iphlpapi.dll secur32.dll netapi32.dll userenv.dll winmm.dll 
Elapsed       16.688060ms
Kernel        14.781250ms
User          3.828125ms
PageFault     1482 KB
WorkingSet    5612027 KB
PagedPool     154687 KB
NonPagedPool  8280 KB
PageFileSize  1541869 KB

"64bit stdlib wo shell32"

> timemem -n 1000 loader.64.exe kernel32.dll advapi32.dll mswsock.dll crypt32.dll ws2_32.dll dnsapi.dll iphlpapi.dll secur32.dll netapi32.dll userenv.dll winmm.dll 
Elapsed       14.111531ms
Kernel        13.062500ms
User          3.171875ms
PageFault     1118 KB
WorkingSet    4173291 KB
PagedPool     90879 KB
NonPagedPool  6976 KB
PageFileSize  1198116 KB

Also, it looks like winmm.dll could be removed as well, there's only a single call to timeBeginPeriod and it doesn't look like the result is being used.

[egonelbre]

It looks like not loading winmm.dll, has even bigger impact:

"32bit stdlib wo shell32,winmm"

>timemem -n 1000 loader.32.exe kernel32.dll advapi32.dll mswsock.dll crypt32.dll ws2_32.dll dnsapi.dll iphlpapi.dll secur32.dll netapi32.dll userenv.dll 
Elapsed       11.105567ms
Kernel        8.250000ms
User          2.703125ms
PageFault     978 KB
WorkingSet    3773644 KB
PagedPool     34008 KB
NonPagedPool  6642 KB
PageFileSize  1001115 KB

"64bit stdlib wo shell32,winmm"

>timemem -n 1000 loader.64.exe kernel32.dll advapi32.dll mswsock.dll crypt32.dll ws2_32.dll dnsapi.dll iphlpapi.dll secur32.dll netapi32.dll userenv.dll
Elapsed       8.641501ms
Kernel        6.453125ms
User          1.656250ms
PageFault     776 KB
WorkingSet    3029708 KB
PagedPool     31264 KB
NonPagedPool  5016 KB
PageFileSize  740032 KB 

[minux]

FTR, we call timeBeginPeriod for its side effects only, and I don't think we can remove winmm.dll.

[egonelbre]

Oh right, it modifies how Sleep works... also found issue #8687.

[alexbrainman]

I have found my problem. The BenchmarkRunningGoProgram in runtime - I made it too simple - it does not even import os package, so it cannot tell the difference. If I import os package into BenchmarkRunningGoProgram (see patch set 1) and compare that to cherry picked CL 22932 on top of it (see patch set 2), I finally see some small improvements on my Windows 7 pc:

name                old time/op  new time/op  delta
RunningGoProgram-2  11.0ms ± 4%  10.3ms ± 1%  -5.89%  (p=0.000 n=10+9)

Alex

[alexbrainman]

CL 33264 has my changes.

[egonelbre]

I had a thought, whether it would make sense to implement syscall code-generation such that it would load the dll-s only when necessary. For many command-line tools these dlls seem unnecessary; and the same for the functions themselves. Of course, I'm not sure how deeply are they tied into the runtime and how much more benefit it gives in practice.

[bradfitz]

They are lazily loaded already, no?

[egonelbre]

Never-mind... yeah... probably should stop trying to think when tired :)

[alexbrainman]

They are lazily loaded already, no?

Yes, but the code that uses shell32.dll is in init function in os package.
That confused me too - the program I was benchmarking, I could not see any change until I imported os package into it.

Alex

[alexbrainman]

More stats comparing different patch-sets of CL 33264.

My Windows XP:

name                old time/op  new time/op  delta
RunningGoProgram-2  18.2ms ± 2%  11.4ms ± 6%  -37.51%  (p=0.000 n=10+10)

A Windows 7 (running inside of vm):

name              old time/op  new time/op  delta
RunningGoProgram  13.1ms ± 2%  12.9ms ± 1%  -1.66%  (p=0.001 n=10+9)

Alex

[alexbrainman]

Another Windows 10 pc comparing different patch-sets of CL 33264:

name                old time/op  new time/op  delta
RunningGoProgram-8  13.0ms ± 2%  10.5ms ± 3%  -18.95%  (p=0.000 n=8+10)

I think we should implement this change.

Alex

[bradfitz]

@alexbrainman, you wrote "comparing different patch-sets of CL 33264". Which one did you compare for your posted numbers?

[alexbrainman]

Which one did you compare for your posted numbers?

This is what I did:

cd %GOROOT%\src
git fetch https://go.googlesource.com/go refs/changes/64/33264/1 && git checkout FETCH_HEAD
make.bat
go test -run=none -count=10 -bench=BenchmarkRunningGoProgram runtime > old.txt
git fetch https://go.googlesource.com/go refs/changes/64/33264/2 && git checkout FETCH_HEAD
make.bat
go test -run=none -count=10 -bench=BenchmarkRunningGoProgram runtime > new.txt
benchstat old.txt new.txt

Alex

[alexbrainman]

I have implemented fix in CL 37914 and 37915. But I am still trying to convince myself it is worth the complexity.

I can see these speed ups for runtime.BenchmarkRunningGoProgram

on my Windows 7 amd64:

name                old time/op  new time/op  delta
RunningGoProgram-2  11.2ms ± 1%  10.4ms ± 2%  -6.63%  (p=0.000 n=9+10)

on my Windows XP 386:

name                old time/op  new time/op  delta
RunningGoProgram-2  19.0ms ± 3%  12.1ms ± 1%  -36.20%  (p=0.000 n=10+10)

these are the steps I followed to collect benchmarks:

git fetch https://go.googlesource.com/go refs/changes/14/37914/1 && git checkout FETCH_HEAD
make
go test -run=none -count=10 -bench=BenchmarkRunningGoProgram runtime > old.txt
git fetch https://go.googlesource.com/go refs/changes/15/37915/2 && git checkout FETCH_HEAD
make
go test -run=none -count=10 -bench=BenchmarkRunningGoProgram runtime > new.txt
benchstat old.txt new.txt

These are only Windows computers I can get my hands on. I wonder if other Windows users can see similar improvements. I am more interested in recent Windows OS versions. Please post your results here. Thank you.

Alex

[egonelbre]

Windows 10 amd64:

name                old time/op  new time/op  delta
RunningGoProgram-8  17.0ms ± 1%  15.3ms ± 2%  -9.71%  (p=0.000 n=10+10)

[alexbrainman]

-9.71%

That convinces me, thank you very much, @egonelbre.
I will use your figures on CL 37915 commit message. I hope it is OK.

Alex

[gopherbot]

CL https://golang.org/cl/37915 mentions this issue.

[gopherbot]

CL https://golang.org/cl/37914 mentions this issue.