Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

syscall: starting a process with large number of arguments is way too slow #41825

Closed
bobjalex opened this issue Oct 6, 2020 · 21 comments
Closed

syscall: starting a process with large number of arguments is way too slow #41825

bobjalex opened this issue Oct 6, 2020 · 21 comments
Milestone

Comments

@bobjalex
Copy link

@bobjalex bobjalex commented Oct 6, 2020

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

$ go version
go version go1.15.2 windows/amd64

Does this issue reproduce with the latest release?

yes

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

go env Output
$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\bobja\AppData\Local\go-build
set GOENV=C:\Users\bobja\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\GoLib\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\GoLib
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=c:\go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=c:\go\pkg\tool\windows_amd64
set GCCGO=gccgo
set AR=ar
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-build291250466=/tmp/go-build -gno-record-gcc-switches

What did you do?

started a process with lots of arguments (thousands)

What did you expect to see?

Process runs

What did you see instead?

Process runs but starts slowly, much slower that equivalent launch in Python.

And I have the solution...

In investigating the said slowness, I gathered some timings,
running on my fairly modern Windows 10 laptop:

Starting a nop process 100 times  (table looks best with a monospace font)

                                 0 args           10,000 args
                                 ------           -----------
Go as ships with built-in        1148ms             6005ms
Windows 5ms delay

Go without 5ms delay              479ms             5607ms

Python                            457ms             1342ms

Go with the below fix             445ms              845ms

The fix is a few lines in the syscall/exec_windows.go file, at line 86 in my 1.15.2 source:

Replace:

func makeCmdLine(args []string) string {
	var s string
	for _, v := range args {
		if s != "" {
			s += " "
		}
		s += EscapeArg(v)
	}
	return s
}

with:

func makeCmdLine(args []string) string {
	var b []byte
	for _, v := range args {
		if b != nil {
			b = append(b, ' ')
		}
		b = append(b, []byte(EscapeArg(v))...)
	}
	return string(b)
}

I hope someone on the Go team can make this modification.

Here is the program I used for the benchmarks:
{you will have to provide your own "nop" command -- set the nopCommand constant)

package main

import (
	"golang.org/x/text/message"
	"os/exec"
	"time"
)

const (

    // nopCommand is a command that accepts any arguments, and does
    // no processing that depends on the number or content of arguments.
	nopCommand = `C:\winbin\nop`

	repetitions = 100
	argCount    = 10_000
)

var p *message.Printer

func init() {
	p = message.NewPrinter(message.MatchLanguage("en"))
}

func main() {
	p.Print(repetitions, " repetitions\n\n")
	test(0)
	args10 := test(10)
	test(50)
	test(200)
	test(1000)
	argsMany := test(argCount)

	p.Printf("\nRatio of %d : 10 argument durations: %.2f\n", argCount,
		float64(argsMany.Milliseconds())/float64(args10.Milliseconds()))
}

func test(argCount int) time.Duration {
	args := make([]string, argCount)
	for i := range args {
		args[i] = "x"
	}
	t0 := time.Now()
	for i := 0; i < repetitions; i++ {
		cmd := exec.Command(nopCommand, args...)
		cmd.Run()
	}
	duration := time.Now().Sub(t0)
	p.Printf("%d arguments: %dms\n", argCount, duration.Milliseconds())
	return duration
}

```-----------------------------------------------------

Thanks,
Bob

- 
@ianlancetaylor ianlancetaylor changed the title Starting a process with large number of arguments is way too slow syscall: starting a process with large number of arguments is way too slow Oct 6, 2020
@ianlancetaylor ianlancetaylor added this to the Backlog milestone Oct 6, 2020
@gopherbot
Copy link

@gopherbot gopherbot commented Oct 6, 2020

Change https://golang.org/cl/259978 mentions this issue: syscall: rewrite Windows makeCmdLine to use []byte

@alexbrainman
Copy link
Member

@alexbrainman alexbrainman commented Oct 7, 2020

@bobjalex

I tried running your test before and after @ianlancetaylor change is applied

https://go-review.googlesource.com/c/go/+/259978

100 repetitions

0 arguments: 1,590ms
10 arguments: 1,637ms
50 arguments: 1,592ms
200 arguments: 1,611ms
1,000 arguments: 1,658ms
10,000 arguments: 7,828ms

Ratio of 10,000 : 10 argument durations: 4.78
100 repetitions

0 arguments: 1,563ms
10 arguments: 1,456ms
50 arguments: 1,526ms
200 arguments: 1,575ms
1,000 arguments: 1,565ms
10,000 arguments: 6,768ms

Ratio of 10,000 : 10 argument durations: 4.65

Not much difference in time it takes to execute your program. Until you have 10,000 arguments. I am yet to see that program that takes 10,000 arguments.

Alex

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 7, 2020

@gopherbot gopherbot closed this in 4922585 Oct 7, 2020
@networkimprov
Copy link

@networkimprov networkimprov commented Oct 7, 2020

@bobjalex does the merged fix improve your example as expected? Alex found it had virtually no effect.

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 7, 2020

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 7, 2020

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 7, 2020

@gopherbot
Copy link

@gopherbot gopherbot commented Oct 7, 2020

Change https://golang.org/cl/260397 mentions this issue: syscall: restore EscapeArg behavior for empty string

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 7, 2020

To clarify, I was referring to the just-merged fix, vs the fix you suggested (which is much simpler).

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 7, 2020

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 7, 2020

Here's a patch for the newly merged change which you can download & apply to your local go tree (first undo the change you made):
https://github.com/golang/go/commit/49225854.patch

To view on github: 4922585

Hopefully this gives the same performance boost as your change; if not, please tell us what you got.

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 7, 2020

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 8, 2020

Please could you test the new patch, and report the results for the benchmark you tried earlier?

gopherbot pushed a commit that referenced this issue Oct 8, 2020
Accidentally broken by CL 259978.

For #41825

Change-Id: Id663514e6eefa325faccdb66493d0bb2b3281046
Reviewed-on: https://go-review.googlesource.com/c/go/+/260397
Trust: Ian Lance Taylor <iant@golang.org>
Trust: Alex Brainman <alex.brainman@gmail.com>
Trust: Emmanuel Odeke <emm.odeke@gmail.com>
Run-TryBot: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Alex Brainman <alex.brainman@gmail.com>
Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 9, 2020

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 10, 2020

Thanks, that clarifies the issue :-)

@tandr
Copy link

@tandr tandr commented Oct 10, 2020

Well, if I read it correctly there is "at least" 10-12x improvement already, which is not bad. (10-12 sec to 1 sec)

Now, to think of it... there is a whole lot of memory buffer expansion is going on. Makes me wonder if doing something like this would help (pseudo code, just an idea, might not compile)

func estimateLen(args []string) int {
	// very rough preestimate for a  buffer length
	var estimate = len(args) // spaces between args
	for _, v := range args {
		var estimateQuote, estimateSlash int
		for _, s := range v {
			switch s {
			case '\\':
				estimateSlash += 1
			case '"':
				estimateSlash += 1
				needQuote = 1

			case ' ', '\t':
				needQuote = 1

			}
		}
		estimate += len(v) + needQuote*(estimateSlash+1)
	}
	return estimate
}

func makeCmdLine(args []string) string {
	estimate := 1024
	if len(args) > 100 {
		estimate = estimateLen(args)
	}

	var b []byte = make([]byte, 0, estimate)
	for _, v := range args {
		b = append(b, ' ')
		b = append(b, []byte(EscapeArg(v))...)
	}
	return string(b[1:])
}

(but I suspect conversion []byte(EscapeArg(v))... might make whole thing a matter of "noise")

Sorry, I don't have Windows machine handy to try it myself

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 10, 2020

@tandr
Copy link

@tandr tandr commented Oct 11, 2020

Thank you @bobjalex. With these numbers I guess we should put it to rest. (unless you really want to run profiler to see where the time is mostly spent.)

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 11, 2020

This issue doesn't need any further work given the results above.

@bobjalex
Copy link
Author

@bobjalex bobjalex commented Oct 15, 2020

@networkimprov
Copy link

@networkimprov networkimprov commented Oct 15, 2020

Please post your thoughts re the 5ms delay on #25965 or #31895.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants
You can’t perform that action at this time.