syscall: external process launching slower than other languages

[bobjalex]

What version of Go are you using (go version)?

$ go version
go version go1.12.5 windows/amd64

Does this issue reproduce with the latest release?

Yes.
I do not have a Linux installation, so this report does not apply to Linux.

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\bobja\AppData\Local\go-build
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOOS=windows
set GOPATH=C:\GoLib
set GOPROXY=
set GORACE=
set GOROOT=C:\Go
set GOTMPDIR=
set GOTOOLDIR=C:\Go\pkg\tool\windows_amd64
set GCCGO=gccgo
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\bobja\AppData\Local\Temp\go-build355190882=/tmp/go-build -gno-record-gcc-switches

What did you do?

Running some test programs written in Go that launch lots of external processes. Noticed that Go was running slower than same operations in Python, Ruby, and Java. So wrote some programs to time just process launching in the mentioned languages. Those programs are attached, and do demonstrate the performance difference.

timing.zip
The attached directory has files to demonstrate the timings. Just unzip it into some directory and run the included Python script. See the README file. All Python programs are Python 3.

What did you expect to see?

Hoped to see Go running faster than (or at least as fast as) the other languages.

What did you see instead?

Go ran slower. All of the other languages showed performance similar to each other. But Go was slower than all of them by a factor of around 1.5. Ouput from a run of my test script with a newly installed Go 1.12.5:

all_timings.py 1000

Hello from "Go"
(using os.StartProcess).
18.2624008s

Hello from "Go"
(using exec.Command).
18.1920394s

Hello from "Python".
12.799870s

Hello from "Ruby".
13.036183s

Hello from "Java".
12.796388101s

[ianlancetaylor]

I think issue may be specific to Windows. I ran your script on my GNU/Linux laptop and got

Hello from "Go"
 (using os.StartProcess).
203.121311ms

Hello from "Go"
 (using exec.Command).
167.040798ms

Hello from "Python".
0.200595s

Hello from "Ruby".
0.166577798s

Hello from "Java".
0.253690545s

[bobjalex]

I wondered if it might be Windows-specific but don't currently have a Linux to confirm that. This issue is no problem for me -- just thought you might like to know. I'm sure y'all want Go to be fast...

…

On Tue, May 7, 2019 at 5:03 PM Ian Lance Taylor ***@***.***> wrote: I think issue may be specific to Windows. I ran your script on my GNU/Linux laptop and got Hello from "Go" (using os.StartProcess). 203.121311ms Hello from "Go" (using exec.Command). 167.040798ms Hello from "Python". 0.200595s Hello from "Ruby". 0.166577798s Hello from "Java". 0.253690545s — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#31895 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABLA2AID7KYGX2HIEG2OB6TPUIKF7ANCNFSM4HLMHNSA> .

[alexbrainman]

@bobjalex thank you for reporting the problem.

I don't have Java or Python or Ruby installed on my Windows computer. So I could not verify your findings.

But, as far as I can see from your results, each Go process start is about 5ms slower than other languages. And there is a 5ms sleep here

go/src/os/exec_windows.go

Line 43 in 2e4edf4

defer time.Sleep(5 * time.Millisecond)

Could you try and remove the sleep and see, if your problem goes away?

Thank you.

Alex

Could you try

[bobjalex]

Hi Alex -- I did timings with: - the 5ms sleep totally removed, including its "defer" - various lesser sleep times, e.g. 1ms, 2, ... In summary, the sleep does appear to be the culprit. With the sleep totally removed, the results are essentially the same as the other "reference" languages. With varying sleep times the run times increase proportionally to the sleep time, as one would expect. You can run my Go rapid-fire launch timing program without having the other languages installed:

go run process_launch_timing.go -h

Hello from "Go" Times repeated execution of a do-nothing command. args: [options] [repetitions] repetitions number of repetitions (default 200) -c command a no-op command that runs quickly (default "cmd /c rem") -s use os.StartProcess to run process instead of exec.Command exit status 2 Even with the sleep and defer removed, my test program ran without a hitch -- I did not notice any problems for 10,000 rapid-file launches. Here are the comparative results with sleep and defer removed, 10,000 reps:

python3 all_timings.py 10000

Hello from "Go" (reps: 10000, command: "cmd /c rem", using os.StartProcess). 54.614608s Hello from "Go" (reps: 10000, command: "cmd /c rem", using exec.Command). 56.4145624s Hello from "Python" (reps: 10000, command: 'cmd /c rem'). 56.493070s Hello from "Ruby" (reps: 10000, command: "cmd /c rem"). 71.051627s Hello from "Java" (reps: 10000, command: "cmd /c rem"). 55.092178901s Bob

…

On Sun, May 12, 2019 at 1:18 AM Alex Brainman ***@***.***> wrote: @bobjalex <https://github.com/bobjalex> thank you for reporting the problem. I don't have Java or Python or Ruby installed on my Windows computer. So I could not verify your findings. But, as far as I can see from your results, each Go process start is about 5ms slower than other languages. And there is a 5ms sleep here https://github.com/golang/go/blob/2e4edf46977994c9d26df9327f0e41c1b60f3435/src/os/exec_windows.go#L43 Could you try and remove the sleep and see, if your problem goes away? Thank you. Alex Could you try — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#31895 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABLA2AIJANFPAWJ3SQBCJN3PU7HDZANCNFSM4HLMHNSA> .

[bobjalex]

Here are some more timings with sleep removed, on another Windows box with different architecture: Previous box: Windows 10 desktop, Intel core I7, conventional spinning disk This box: Windows 10 laptop, later generation core I5, solid state disk The comparative timings are all just about the same! Hello from "Go" (reps: 10000, command: "cmd /c rem", using os.StartProcess). 2m11.6298252s Hello from "Go" (reps: 10000, command: "cmd /c rem", using exec.Command). 2m13.6333152s Hello from "Python" (reps: 10000, command: 'cmd /c rem'). 132.485249s Hello from "Ruby" (reps: 10000, command: "cmd /c rem"). 134.177437s Hello from "Java" (reps: 10000, command: "cmd /c rem"). 132.7421891s

…

On Tue, May 14, 2019 at 9:44 AM Bob Alexander ***@***.***> wrote: Hi Alex -- I did timings with: - the 5ms sleep totally removed, including its "defer" - various lesser sleep times, e.g. 1ms, 2, ... In summary, the sleep does appear to be the culprit. With the sleep totally removed, the results are essentially the same as the other "reference" languages. With varying sleep times the run times increase proportionally to the sleep time, as one would expect. You can run my Go rapid-fire launch timing program without having the other languages installed: >go run process_launch_timing.go -h Hello from "Go" Times repeated execution of a do-nothing command. args: [options] [repetitions] repetitions number of repetitions (default 200) -c command a no-op command that runs quickly (default "cmd /c rem") -s use os.StartProcess to run process instead of exec.Command exit status 2 Even with the sleep and defer removed, my test program ran without a hitch -- I did not notice any problems for 10,000 rapid-file launches. Here are the comparative results with sleep and defer removed, 10,000 reps: >python3 all_timings.py 10000 Hello from "Go" (reps: 10000, command: "cmd /c rem", using os.StartProcess). 54.614608s Hello from "Go" (reps: 10000, command: "cmd /c rem", using exec.Command). 56.4145624s Hello from "Python" (reps: 10000, command: 'cmd /c rem'). 56.493070s Hello from "Ruby" (reps: 10000, command: "cmd /c rem"). 71.051627s Hello from "Java" (reps: 10000, command: "cmd /c rem"). 55.092178901s Bob On Sun, May 12, 2019 at 1:18 AM Alex Brainman ***@***.***> wrote: > @bobjalex <https://github.com/bobjalex> thank you for reporting the > problem. > > I don't have Java or Python or Ruby installed on my Windows computer. So > I could not verify your findings. > > But, as far as I can see from your results, each Go process start is > about 5ms slower than other languages. And there is a 5ms sleep here > https://github.com/golang/go/blob/2e4edf46977994c9d26df9327f0e41c1b60f3435/src/os/exec_windows.go#L43 > Could you try and remove the sleep and see, if your problem goes away? > > Thank you. > > Alex > > Could you try > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > <#31895 (comment)>, or mute > the thread > <https://github.com/notifications/unsubscribe-auth/ABLA2AIJANFPAWJ3SQBCJN3PU7HDZANCNFSM4HLMHNSA> > . >

[alexbrainman]

In summary, the sleep does appear to be the culprit.

I am glad we know what your problem is.

Unfortunately we cannot remove sleep. Otherwise we have trouble removing executable file once process has exited. See #25965 for details, for example.

If you have any good suggestions, I am all ears.

Alex

[bobjalex]

One possibility: remove the 5ms, and when deleting the executable retry several times if the delete fails, until it finally succeeds.

I've been piddling around with testing the need for the delay: instrumented my process_launch_timing program with some code that attempts to detect when the executable is not "released" on return from exec.Run. Using Go with the 5ms removed, I added this to the repeated-launching program:

• use a do-nothing launched-program target that is writable and is not being used by other processes
• upon return from Run, attempt to open the target executable for writing:
  os.OpenFile(executable, os.O_WRONLY, 0755)
  I confirmed that this fails if the file is being executed, and succeeds if not.
• If the above test fails, print a message.

Not really sure how well this works, but it did report problems if I provoked it by manually running the executable during a test run. Of course my environment is a home computer with not a whole lot going on besides the usual Windows 10 background stuff. And I'm using a fully up to date, modern version of Windows.

With that program, I can reliably run a million repetitions without any "open executable immediately after wait" errors detected. (If I start 2 instances of that program running at the same time on the same target executable, it's fun to watch the chaos that ensues -- suggesting the that detection technique is working.)

I have left the delay out of my personal Go environments, to see what happens. So far, so good.

[alexbrainman]

One possibility: remove the 5ms, and when deleting the executable retry several times if the delete fails, until it finally succeeds.

Sounds reasonable. Would you like to adjust Go standard library and see what happens? Send your change for review, if it works for you.

Not really sure how well this works, but it did report problems if I provoked it by manually running the executable during a test run.

We have many tests and many different environments https://build.golang.org to test your change. And other Go users will complain, if your change will not work for them.

Of course my environment is a home computer with not a whole lot going on besides the usual Windows 10 background stuff.

Yes, your environment matters. See, for example, my comment #25965 (comment) But I can test your change in my environment.

Alex

[gopherbot]

Change https://golang.org/cl/369017 mentions this issue: os/signal: remove delay on Wait() for a process for windows

[gopherbot]

Change https://go.dev/cl/463840 mentions this issue: os: remove unconditional wait sleep on Windows