cmd/go: go list commands called by golang.org/x/tools/go/packages.Load() varies from ~500ms to 3s with no other changes

[alecthomas]

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

$ go version
go version go1.21.3 darwin/arm64

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
GO111MODULE=''
GOARCH='arm64'
GOBIN='/Users/alec/dev/tools/.hermit/go/bin'
GOCACHE='/Users/alec/Library/Caches/go-build'
GOENV='/Users/alec/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/alec/go/pkg/mod'
GONOPROXY='*.sqcorp.co,github.com/squareup'
GONOSUMDB='*.sqcorp.co,github.com/squareup'
GOOS='darwin'
GOPATH='/Users/alec/go'
GOPRIVATE='*.sqcorp.co,github.com/squareup'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/alec/Library/Caches/hermit/pkg/go-1.21.3'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='local'
GOTOOLDIR='/Users/alec/Library/Caches/hermit/pkg/go-1.21.3/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.21.3'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/alec/dev/tools/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/h2/_9k30gds1dbdjsv1m3yw834w0000gn/T/go-build4090118491=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Repeated runs of golang.org/x/tools/go/packages.Load() vary wildly in their duration on the same small package, with no changes in between runs.

The code for the example below is here.

Strangely, setting GOMAXPROCS=1 significantly increases the likelihood of the time blowing out.

Here's output of me running the same command repeatedly. Notice that sometimes it takes 2+ seconds in total, but sometimes takes only ~500ms.

Example output:

🐚 ~/dev/chroma $ GOMAXPROCS=1 ../ftl/foo/list .
136.549875ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE=off GOPROXY= PWD=. go list -e -f {{context.ReleaseTags}} -- unsafe
422.417792ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,CompiledGoFiles,DepOnly,Imports,ImportMap,Export -compiled=true -test=false -export=true -deps=true -find=false -- ./...
1.122006208s for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
chroma
html
svg
formatters
lexers
styles
quick
🐚 ~/dev/chroma $ GOMAXPROCS=1 ../ftl/foo/list .
84.169167ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE=off GOPROXY= PWD=. go list -e -f {{context.ReleaseTags}} -- unsafe
172.097458ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,CompiledGoFiles,DepOnly,Imports,ImportMap,Export -compiled=true -test=false -export=true -deps=true -find=false -- ./...
1.1017975s for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
chroma
html
svg
formatters
lexers
styles
quick
🐚 ~/dev/chroma $ GOMAXPROCS=1 ../ftl/foo/list .
83.233916ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
84.077042ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE=off GOPROXY= PWD=. go list -e -f {{context.ReleaseTags}} -- unsafe
170.827167ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,CompiledGoFiles,DepOnly,Imports,ImportMap,Export -compiled=true -test=false -export=true -deps=true -find=false -- ./...
chroma
html
svg
formatters
lexers
styles
quick
🐚 ~/dev/chroma $ GOMAXPROCS=1 ../ftl/foo/list .
81.910833ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
1.100569875s for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE=off GOPROXY= PWD=. go list -e -f {{context.ReleaseTags}} -- unsafe
173.4445ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,CompiledGoFiles,DepOnly,Imports,ImportMap,Export -compiled=true -test=false -export=true -deps=true -find=false -- ./...
chroma
html
svg
formatters
lexers
styles
quick
🐚 ~/dev/chroma $ ../ftl/foo/list .
83.219708ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE=off GOPROXY= PWD=. go list -e -f {{context.ReleaseTags}} -- unsafe
83.307042ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
138.104459ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,CompiledGoFiles,DepOnly,Imports,ImportMap,Export -compiled=true -test=false -export=true -deps=true -find=false -- ./...
chroma
html
svg
formatters
lexers
styles
quick
🐚 ~/dev/chroma $ ../ftl/foo/list .
86.6445ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE=off GOPROXY= PWD=. go list -e -f {{context.ReleaseTags}} -- unsafe
86.885417ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
145.035625ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,CompiledGoFiles,DepOnly,Imports,ImportMap,Export -compiled=true -test=false -export=true -deps=true -find=false -- ./...
chroma
html
svg
formatters
lexers
styles
quick
🐚 ~/dev/chroma $ ../ftl/foo/list .
80.45975ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe
1.095275417s for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE=off GOPROXY= PWD=. go list -e -f {{context.ReleaseTags}} -- unsafe
140.623334ms for GOROOT=/Users/alec/Library/Caches/hermit/pkg/go-1.20.2 GOPATH= GO111MODULE= GOPROXY= PWD=. go list -e -json=Name,ImportPath,Error,Dir,GoFiles,IgnoredGoFiles,IgnoredOtherFiles,CFiles,CgoFiles,CXXFiles,MFiles,HFiles,FFiles,SFiles,SwigFiles,SwigCXXFiles,SysoFiles,CompiledGoFiles,DepOnly,Imports,ImportMap,Export -compiled=true -test=false -export=true -deps=true -find=false -- ./...
chroma
html
svg
formatters
lexers
styles
quick

What did you expect to see?

I would expect the command to take roughly the same time on each run.

What did you see instead?

It varies significantly. Most of the time it takes around ~500ms, but sometimes it spikes up to 2s and even 3s on occasion.

[seankhliao]

I don't see any code for reproducing this?

[alecthomas]

There's a link to a playground with the code. Running it against it itself reproduces it, or any project.

[seankhliao]

the playground link is just output, no code

[alecthomas]

Ah my apologies, I pasted the wrong link. Updated the description, but it's also here.

[seankhliao]

Even 500ms seems quite slow, is it perhaps a macos issue or some other antivirus software you have running?

[bcmills]

On macOS in particular, I wonder if this is yet another symptom of #63937. 🤔

[bcmills]

80ms or more to run go list -f "{{context.GOARCH}} {{context.Compiler}}" -- unsafe and go list -e -f {{context.ReleaseTags}} -- unsafe also seems excessive, and suggests perhaps a slow filesystem or antivirus interference.

[alecthomas]

I do indeed think this is something on my Mac. I tried it in a completely clean directory and couldn't replicate it, so it must be something local. Apologies for the noise.

[bcmills]

To be clear: we are definitely interested in addressing this sort of problem, if we can figure out where the delays are coming from. (But the space of “possible sources of delay” is unfortunately very large, and our resources for investigating are limited. 😅)