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

cmd/go: cache results of exec.LookPath #36768

Open
Zyxon123 opened this issue Jan 25, 2020 · 51 comments
Open

cmd/go: cache results of exec.LookPath #36768

Zyxon123 opened this issue Jan 25, 2020 · 51 comments

Comments

@Zyxon123
Copy link

@Zyxon123 Zyxon123 commented Jan 25, 2020

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

$ go version
go version go1.13.6 windows/amd64

Does this issue reproduce with the latest release?

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

  • windows 10 64 bit version 1809
  • intel i5-8265U
go env Output
$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\lidic\AppData\Local\go-build
set GOENV=C:\Users\lidic\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\lidic\go
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=C:\Go\src\go.mod
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=C:\Users\lidic\AppData\Local\Temp\go-build756524190=/tmp/go-build -gno-record-gcc-switches
GOROOT/bin/go version: go version go1.13.6 windows/amd64
GOROOT/bin/go tool compile -V: compile version go1.13.6

What did you do?

Hi,

I followed the steps here after I installed Go. However, running go run hello.go takes around 10 - 20 seconds for it to output “hello, world”. Same thing with go build. I’ve also tried reinstalling and excluding my Go folder and Go temp folder from windows defender (the only antivirus I use). I've even disabled real time protection. How do I fix this? Any help is appreciated.

Thanks!

What did you expect to see?

I expect a hello world program to be compiled within seconds, other users are able to do so.

What did you see instead?

Takes 10-20 seconds to compile instead.

PS C:\Go\src\hello> Measure-Command {go run hello.go}


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 15
Milliseconds      : 582
Ticks             : 155821163
TotalDays         : 0.000180348568287037
TotalHours        : 0.00432836563888889
TotalMinutes      : 0.259701938333333
TotalSeconds      : 15.5821163
TotalMilliseconds : 15582.1163

go run -x output

C:\Go\src\hello>go run -x hello.go
WORK=C:\Users\lidic\AppData\Local\Temp\go-build803697114
mkdir -p $WORK\b001\
cat >$WORK\b001\importcfg.link << 'EOF' # internal
packagefile command-line-arguments=C:\Users\lidic\AppData\Local\go-build\a8\a8c4809a5f80405952f1e99a0a10c35826595987039565f2c4eed84d206e5060-d
packagefile fmt=c:\go\pkg\windows_amd64\fmt.a
packagefile runtime=c:\go\pkg\windows_amd64\runtime.a
packagefile errors=c:\go\pkg\windows_amd64\errors.a
packagefile internal/fmtsort=c:\go\pkg\windows_amd64\internal\fmtsort.a
packagefile io=c:\go\pkg\windows_amd64\io.a
packagefile math=c:\go\pkg\windows_amd64\math.a
packagefile os=c:\go\pkg\windows_amd64\os.a
packagefile reflect=c:\go\pkg\windows_amd64\reflect.a
packagefile strconv=c:\go\pkg\windows_amd64\strconv.a
packagefile sync=c:\go\pkg\windows_amd64\sync.a
packagefile unicode/utf8=c:\go\pkg\windows_amd64\unicode\utf8.a
packagefile internal/bytealg=c:\go\pkg\windows_amd64\internal\bytealg.a
packagefile internal/cpu=c:\go\pkg\windows_amd64\internal\cpu.a
packagefile runtime/internal/atomic=c:\go\pkg\windows_amd64\runtime\internal\atomic.a
packagefile runtime/internal/math=c:\go\pkg\windows_amd64\runtime\internal\math.a
packagefile runtime/internal/sys=c:\go\pkg\windows_amd64\runtime\internal\sys.a
packagefile internal/reflectlite=c:\go\pkg\windows_amd64\internal\reflectlite.a
packagefile sort=c:\go\pkg\windows_amd64\sort.a
packagefile sync/atomic=c:\go\pkg\windows_amd64\sync\atomic.a
packagefile math/bits=c:\go\pkg\windows_amd64\math\bits.a
packagefile internal/oserror=c:\go\pkg\windows_amd64\internal\oserror.a
packagefile internal/poll=c:\go\pkg\windows_amd64\internal\poll.a
packagefile internal/syscall/windows=c:\go\pkg\windows_amd64\internal\syscall\windows.a
packagefile internal/testlog=c:\go\pkg\windows_amd64\internal\testlog.a
packagefile syscall=c:\go\pkg\windows_amd64\syscall.a
packagefile time=c:\go\pkg\windows_amd64\time.a
packagefile unicode/utf16=c:\go\pkg\windows_amd64\unicode\utf16.a
packagefile unicode=c:\go\pkg\windows_amd64\unicode.a
packagefile internal/race=c:\go\pkg\windows_amd64\internal\race.a
packagefile internal/syscall/windows/sysdll=c:\go\pkg\windows_amd64\internal\syscall\windows\sysdll.a
packagefile internal/syscall/windows/registry=c:\go\pkg\windows_amd64\internal\syscall\windows\registry.a
EOF
mkdir -p $WORK\b001\exe\
cd .
"c:\\go\\pkg\\tool\\windows_amd64\\link.exe" -o "C:\\Users\\lidic\\AppData\\Local\\Temp\\go-build803697114\\b001\\exe\\hello.exe" -importcfg "C:\\Users\\lidic\\AppData\\Local\\Temp\\go-build803697114\\b001\\importcfg.link" -s -w -buildmode=exe -buildid=boKU76zxCBTD9TQHu-ws/-9UkAzfu17Kq0_a_DtT8/N9PQnONczWnG7Jk1PdaH/boKU76zxCBTD9TQHu-ws -extld=gcc "C:\\Users\\lidic\\AppData\\Local\\go-build\\a8\\a8c4809a5f80405952f1e99a0a10c35826595987039565f2c4eed84d206e5060-d"
$WORK\b001\exe\hello.exe
hello, world
@ghost
Copy link

@ghost ghost commented Jan 25, 2020

go run (timing)

It may be of interest to the Golang developers to check the timing of other available downloads.

go1.13.6.linux-386.tar.gz

bash-4.3$ uname -mp                             
i686 Intel(R) Atom(TM) CPU N270   @ 1.60GHz
bash-4.3$ free --giga | perl -lae 'print @F[0,1] if $. == 2'
Mem:1
bash-4.3$ export PATH=/usr/local/go/bin:${PATH}
bash-4.3$ mkdir -p ~/go/src/hello
bash-4.3$ cat << EOF | gofmt > ~/go/src/hello/hello.go
> package main
> 
> import "fmt"
> 
> func main() {
> fmt.Printf("hello, world\n")
> }
> EOF
bash-4.3$ /usr/bin/time -p go run ~/go/src/hello/hello.go
hello, world
real 2.33
user 1.59
sys 0.31
bash-4.3$ rm -r ~/.cache/go-build
bash-4.3$ $PLAN9/bin/time go run ~/go/src/hello/hello.go
hello, world
1.57u 0.35s 1.86r 	 go run /home/eric/go/src/hello/hello.go
bash-4.3$ file /usr/local/go/bin/go
/usr/local/go/bin/go: ELF 32-bit LSB executable, Intel 80386, version 1 (SYSV), dynamically linked, interpreter /lib/ld-linux.so.2, Go BuildID=bVwMwAdXBpYp4PBvIrqZ/vbfX15UF6cgq3THigMUx/QSxQRVWmK-8uFUlegS1A/TD0XQ0eQXwJkvrDVR_B1, not stripped
bash-4.3$ rm -r ~/.cache/go-build
bash-4.3$

Stripping the files from go1.13.6.linux-386.tar.gz the time is slightly different.

GNU 1.7
real 2.23
user 1.49
sys 0.36

Plan 9 from User Space
1.58u 0.31s 1.81r

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Jan 25, 2020

You didn't fill out the issue template. What is the output of go env?

Also, what is the output of go run -x hello.go?

@Zyxon123
Copy link
Author

@Zyxon123 Zyxon123 commented Jan 25, 2020

You didn't fill out the issue template. What is the output of go env?

Also, what is the output of go run -x hello.go?

Ok I've updated my post

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Jan 26, 2020

Thanks. Unfortunately I still don't see why it is so slow.

What is the output of go build -ldflags=-v hello.go?

Since this is Windows, the problem may be due to a virus checker.

@Zyxon123
Copy link
Author

@Zyxon123 Zyxon123 commented Jan 26, 2020

Thanks. Unfortunately I still don't see why it is so slow.

What is the output of go build -ldflags=-v hello.go?

Since this is Windows, the problem may be due to a virus checker.

Here's the output:

PS C:\go\src\hello> go build -ldflags=-v hello.go
# command-line-arguments
HEADER = -H11 -T0xffffffffffffffff -R0xffffffff
 0.00 deadcode
 0.01 symsize = 0
 0.08 pclntab=460347 bytes, funcdata total 109854 bytes
 0.09 dodata
 0.09 dwarf
 0.12 reloc
 0.12 asmb
 0.12 codeblk
 0.12 rodatblk
 0.13 datblk
 0.13 sym
 0.13 dwarf
 0.13 headr
 0.13 symsize = 0
 0.13 cpu time
53707 symbols
63284 liveness data

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Jan 26, 2020

Thanks. I was wondering if it were using external linking, but it's not.

I have no explanation other than possibly a virus checker. Sorry.

@ghost
Copy link

@ghost ghost commented Jan 26, 2020

The go.exe env output lists GOPATH=C:\Users\lidic\go.

From your update it looks like C:\Go\src\hello is where your source file is.

I installed Golang only once on Windows 10 (64-bit).

I downloaded a go1.xx.x.windows-amd64.zip file, extracted it, opened an elevated command prompt and moved it to C:\.

Next I disabled via the context menu indexing for C:\go.

Does locating hello.go in C:\Users\lidic\go\src\hello make any difference?

@Zyxon123
Copy link
Author

@Zyxon123 Zyxon123 commented Jan 26, 2020

The go.exe env output lists GOPATH=C:\Users\lidic\go.

From your update it looks like C:\Go\src\hello is where your source file is.

I installed Golang only once on Windows 10 (64-bit).

I downloaded a go1.xx.x.windows-amd64.zip file, extracted it, opened an elevated command prompt and moved it to C:\.

Next I disabled via the context menu indexing for C:\go.

Does locating hello.go in C:\Users\lidic\go\src\hello make any difference?

I moved hello.go to C:\Users\lidic\go\src\hello and it made no difference. I also changed my GOPATH to C:\Go and it made no difference too.

@ghost
Copy link

@ghost ghost commented Jan 26, 2020

I received a reply to an e-mail I sent to Redmond.

Doesn't look like it's specific to AV/Defender.

The way you rule out (or in) Defender is to temporarily disable it, do the compile, and then compare on vs off times. Looks like they've done that, though.

@ghost
Copy link

@ghost ghost commented Jan 26, 2020

#36768 (comment).

The root of the Go tree cannot be included as a value in the Go path.

@proyb6
Copy link

@proyb6 proyb6 commented Jan 27, 2020

I'm not using Windows, my assumption if did you have made any Windows performance tuning e.g. disable timestamp or etc?

@Zyxon123
Copy link
Author

@Zyxon123 Zyxon123 commented Jan 28, 2020

I'm not using Windows, my assumption if did you have made any Windows performance tuning e.g. disable timestamp or etc?

No. I am able to reproduce this behaviour on another PC that is also windows 10 with i7.

@0intro
Copy link
Member

@0intro 0intro commented Jan 28, 2020

@Zyxon123 asked me to provide the time measurements on Plan 9 for reference.

% go version
go version go1.13.6 plan9/386
% time go run hello.go
hello, world
0.04u 0.25s 0.77r 	 go run hello.go

@ALTree ALTree changed the title Go compiles really slowly even for a hello world program cmd/go: compiles really slowly even for a hello world program Jan 28, 2020
@ALTree ALTree added this to the Unplanned milestone Jan 28, 2020
@ALTree
Copy link
Member

@ALTree ALTree commented Jan 28, 2020

This is sometimes caused by a broken installation. In this Go1.13 install the first you did on your machine? Or did you update Go from an older version you had?

Also, when you write:

I’ve also tried reinstalling

do you mean reinstalling over the existing version? If yes, can you instead completely nuke every trace of Go from your machine, and try to follow the installation steps again, from scratch?

@Zyxon123
Copy link
Author

@Zyxon123 Zyxon123 commented Jan 28, 2020

Go 1.13.6 is the first version I did on my machine.

This is sometimes caused by a broken installation. In this Go1.13 install the first you did on your machine? Or did you update Go from an older version you had?

Also, when you write:

I’ve also tried reinstalling

do you mean reinstalling over the existing version? If yes, can you instead completely nuke every trace of Go from your machine, and try to follow the installation steps again, from scratch?

I have just uninstalled Go again by deleting C:\Go, C:\Users\lidic\AppData\Local\go-build, C:\Users\lidic\AppData\Local\Temp\go-buildxxxxx, and removing it from PATH. I also clicked the "Uninstall" option after opening the installer. However, the issue still persists (with exclusion and real time protection off).

PS C:\Go\src\hello> Measure-Command {go run hello.go}


Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 17
Milliseconds      : 229
Ticks             : 172295263
TotalDays         : 0.000199415813657407
TotalHours        : 0.00478597952777778
TotalMinutes      : 0.287158771666667
TotalSeconds      : 17.2295263
TotalMilliseconds : 17229.5263

@ALTree
Copy link
Member

@ALTree ALTree commented Jan 30, 2020

@Zyxon123 thanks for trying. If your installation is not broken and you're absolutely sure your antivirus is not disturbing the compilation process, I don't have any other idea to fix this.

These kind of slow-compilation-on-windows issues are most commonly caused by a broken installation or by a nosy antivirus. It's clear that there is something wrong with your machines and/or with the way you're installing Go, since many many people are able to compile a Go hello world in < 1s on Windows; but I don't know what that may be.

@ghost
Copy link

@ghost ghost commented Feb 2, 2020

Could someone other than the OP add 9pm's time.exe output
for go1.13.6 running on Windows 10 64 bit.

go1.10.windows-386.zip
9pm051031.zip (S. Quinlan's 9pm)

% time.exe /Programmer/go/bin/go.exe run hello.go
hello, world
0.438u 0.359s 2.125r 	 /Programmer/go/bin/go.exe run hello.go
%

@ctd1500
Copy link

@ctd1500 ctd1500 commented Feb 3, 2020

@apparluk Windows 10 64-bit time output for reference

# go version
go version go1.13.6 windows/amd64

# ..\9pm\bin\time.exe go run hello.go
hello, world
0.031u 0.188s 1.022r     go run hello.go

@proyb6
Copy link

@proyb6 proyb6 commented Feb 4, 2020

I'm not using Windows, my assumption if did you have made any Windows performance tuning e.g. disable timestamp or etc?

No. I am able to reproduce this behaviour on another PC that is also windows 10 with i7.

Mind to share the model and brand of your PC, how much free memory does it has?

@ghost
Copy link

@ghost ghost commented Feb 4, 2020

The program in which the command time.exe go.exe run hello.go is executed (on win10 64-bit) might be factored out by running that command (time.exe referring to Quinlan's 9pm) in 9term.exe, cmd.exe and powershell.exe.

Here's a result from Windows 10 (run in 9term.exe).

go1.13.7.windows-amd64.zip

% time.exe /go/bin/go.exe run hello.go
hello, world
0.391u 1.563s 6.071r      /go/bin/go.exe run hello.go
% 

I didn't have the opportunity to obtain the specs on the hardware,
nor to clear out go-build and rerun in powershell.exe.


There was an earlier ticket regarding CRLF, and IIRC, PowerShell (by default) generates UTF-16 content, when running a go executable to output a string, and that is then redirected to a file.

@ghost
Copy link

@ghost ghost commented Feb 10, 2020

Measurement on macOS for reference.

go1.13.7.darwin-amd64.tar.gz

$time go run hello.go
hello, world

real   0m1.410s
user   0m0.306s
sys    0m0.377s
$

@MaxSem
Copy link

@MaxSem MaxSem commented Feb 10, 2020

@Zyxon123, does it still run slowly if you try it several times in a rapid succession? For me (with both workspace and Go installation whitelisted in Defender), it drops from

real    0m3.609s
user    0m0.015s
sys     0m0.000s

to

real    0m0.561s
user    0m0.000s
sys     0m0.000s

And that's on a M.2 drive with 3Gb/s read speed.

@andreykaipov
Copy link

@andreykaipov andreykaipov commented Aug 11, 2020

I'm experiencing slow successive builds too. Tried both 1.14.2 and 1.15rc2.

I've made sure my GOCACHE is set and excluded it from Windows Defender, among other directories like the Go installation and project directory. I don't think hardware is an issue because building the project within my WSL distro is quick as expected. Hell - it's quicker iteration for me to cross-compile to Windows from the WSL distro! 😅

This gave me the idea to try both binaries from the same environment:

$ uname -a
Linux Andrey 4.4.0-18362-Microsoft #836-Microsoft Mon May 05 16:04:00 PST 2020 x86_64 x86_64 x86_64 GNU/Linux

$ alias gowindows=/mnt/c/Users/Andrey/sdk/go1.14.2/bin/go.exe

$ alias golinux=/home/andrey/bin/go

$ gowindows version
go version go1.14.2 windows/amd64

$ golinux version
go version go1.14.2 linux/amd64

$ time gowindows build hello.go

real    0m5.237s
user    0m0.000s
sys     0m0.031s

$ time golinux build hello.go

real    0m0.402s
user    0m0.031s
sys     0m0.422s

For completeness the file contents are:

package main

import "fmt"

func main() {
        fmt.Println("hello")
}

Both installations were installed similarly - just unzipping the folder and adding a/b/c/go/bin to the system path. I even tried using the MSI installer but no dice.

Strangely it's not just go build that's slow:

$ time gowindows env >/dev/null

real    0m3.101s
user    0m0.000s
sys     0m0.000s

$ time golinux env >/dev/null

real    0m0.146s
user    0m0.016s
sys     0m0.172s

Something is definitely wrong but I can't find what.

@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 11, 2020

Could the difference in build time be explained by the file system bridge that WSL uses?

@andreykaipov
Copy link

@andreykaipov andreykaipov commented Aug 11, 2020

Could the difference in build time be explained by the file system bridge that WSL uses?

Are you saying that since I'm accessing go.exe from the WSL side, that might be the cause for the slowness? I've also tried downloading Go for Windows onto the WSL distro and accessing it from there directly, and experience similar behavior, so I'm not sure if that's part of it.

One interesting thing I've noticed is when building with -x, there's a significant delay between when the WORK directory is printed and when the rest of the compilation commands are printed:

C:\Users\Andrey\Projects\Test> go build -x -ldflags=-v hello.go
WORK=C:\Users\Andrey\AppData\Local\Temp\go-build674494450
██████ significant delay here ██████
mkdir -p $WORK\b001\
cat >$WORK\b001\importcfg.link << 'EOF' # internal
packagefile command-line-arguments=C:\Users\Andrey\.cache\go\f1\f174f809fb722f16637244c56012840d3d558a2a2b7a0dc8d5cdcfd33fd35af1-d
packagefile fmt=C:\Users\Andrey\sdk\go1.14.2\pkg\windows_amd64\fmt.a
packagefile runtime=C:\Users\Andrey\sdk\go1.14.2\pkg\windows_amd64\runtime.a
...

I think I've narrowed it down to this code range just by playing around with build flags to cause fatal errors that failed quickly. https://github.com/golang/go/blob/go1.14.2/src/cmd/go/internal/work/exec.go#L98-L190

I've got no clue what any of this code does, but I hope I'll find it within myself to keep going and build Go from source with debug print statements to narrow down the slowness further, but I'm considering just working off the MacBook at this point lol

@davecheney
Copy link
Contributor

@davecheney davecheney commented Aug 11, 2020

Are you saying that since I'm accessing go.exe from the WSL side, that might be the cause for the slowness?

That's my suggestion. I don't have a WSL host to verify, sorry.

@duguanyue
Copy link

@duguanyue duguanyue commented Jan 23, 2021

I'm using go 1.15.6 and this issue still exists on my computer.

$ go version
go version go1.15.6 windows/amd64

$ time go run main.go
real    0m4.986s
user    0m0.000s
sys     0m0.015s

main.go is just a hello world program.

This happened when I updated my go version from 1.15.5 to 1.15.6 the other day.

@josharian
Copy link
Contributor

@josharian josharian commented Jan 23, 2021

Does it still occur?

When upgrading Go versions, all the cached compilation artifacts are now unused. As a result, everything must be compiled from scratch, which can be slow. Plus this will (eventually) result in a bunch of cache entries that have to get cleaned up, which is also slow.

Both of those should be one time effects, though, and things should return to being fast later.

@josharian
Copy link
Contributor

@josharian josharian commented Jan 23, 2021

Possibly related: #38939

@ALTree
Copy link
Member

@ALTree ALTree commented Jan 26, 2021

@duguanyue can you try disconnecting the machine from the network so that is has no internet access, waiting 30s, and the running your hello world again? Is it still slow?

@omaskery
Copy link

@omaskery omaskery commented Jan 30, 2021

Hi, I've spent a little while digging into this on my machine. It's hard to be sure we're having exactly the same problem, but my symptoms are go run <trivial go program> taking ~12 seconds to build, and even go env takes ~3 seconds to run.

I am not familiar with developing the go executable (it has quite a complex build process in terms of, I don't know how to step-by-step debug the go executable in an IDE 😞), but the build process is quite straight-forward, so I just added print statements with timing information and bisected the go env command.

I ended up tracking down the slowness to exec.Command, in particular, exec.LookPath. It seems common on Windows to havae a PATHEXT contain ~12 different executable file extensions, and a PATH variable commonly in excess of 30-50 entries (particularly for development machines!). This means that the worst case performance of LookPath is to check for executable files something like (12 * 50 = 600) times.

Digging into this a little deeper, it appears that on Windows (on my machine), os.Stat takes ~5us to get stats for a file that exists and ~380us to error when asked for stats on a file that does not exist. Combined with the above, this makes the worst case performance of exec.LookPath in the order of (600 paths to check * 380us per check = ~230ms) per invocation.

If you look at go env it attempts to invoke GCC in order to identify supported GCC arguments (or something like that). On my machine I don't have GCC installed, so this causes each attempted exec.Command call take >200ms.

If you consider the number of external processes that are invoked during the normal operation of go env or go run, etc., all of these several-hundred-millisecond calls add up.

Once I identified that (at least one possible cause for) the issue was in exec.Command I moved to a little test bed, which I'm keeping in a Gist here: https://gist.github.com/omaskery/8313096dd475659d63297889cff1818c.

You can gain further confidence in this being the issue by setting your PATH variable to be just your Go installation:

With my normal path:

> Measure-Command {go env}
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 2
Milliseconds      : 552
Ticks             : 25520824
TotalDays         : 2.95379907407407E-05
TotalHours        : 0.000708911777777778
TotalMinutes      : 0.0425347066666667
TotalSeconds      : 2.5520824
TotalMilliseconds : 2552.0824

With PATH set to only my go installation:

> $Env:PATH="F:\Go\bin"
> Measure-Command {go env}
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 593
Ticks             : 5933060
TotalDays         : 6.86696759259259E-06
TotalHours        : 0.000164807222222222
TotalMinutes      : 0.00988843333333333
TotalSeconds      : 0.593306
TotalMilliseconds : 593.306

With PATHEXT set to only .exe:

> $Env:PATHEXT=".exe"
> Measure-Command {go env}
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 0
Milliseconds      : 533
Ticks             : 5335311
TotalDays         : 6.17512847222222E-06
TotalHours        : 0.000148203083333333
TotalMinutes      : 0.008892185
TotalSeconds      : 0.5335311
TotalMilliseconds : 533.5311

Same experiment on WSL:

With normal PATH:

$ time go env
real    0m0.175s
user    0m0.025s
sys     0m0.024s

With limited PATH:

$ export PATH=/usr/bin
$ time go env
real    0m0.039s
user    0m0.036s
sys     0m0.001s

You can further exacerbate the issue on WSL (or presumably Linux in general) by "hiding" gcc from Go:

$ sudo mv /usr/bin/gcc /usr/bin/gcc-temp
$ time go env
real    0m1.161s
user    0m0.000s
sys     0m0.094s

Note: you may be tempted to think that installing GCC on Windows might circumvent the issue by having it find GCC. On the contrary, invoking GCC seems to in fact increase the time it takes to execute 😱:

> Measure-Command {go env}
Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 5
Milliseconds      : 212
Ticks             : 52121975
TotalDays         : 6.03263599537037E-05
TotalHours        : 0.00144783263888889
TotalMinutes      : 0.0868699583333333
TotalSeconds      : 5.2121975
TotalMilliseconds : 5212.1975

@josharian
Copy link
Contributor

@josharian josharian commented Jan 30, 2021

@omaskery useful diagnosis, thanks!

cc @bcmills @jayconrod

@omaskery
Copy link

@omaskery omaskery commented Jan 30, 2021

I can't tell how directly this is related to the actual compilation process, however, as my attempts to print-debug the speed of the go executable didn't go as far as including invocations from within the go compiler itself.

All I can tell is that go run <basic program> still takes >10 seconds, and spends most of that time on external programs executing (not on exec.LookPath as with go env above, as invocations of explicit paths to binaries don't invoke LookPath).

I did make a bit of effort to try and understand the Go compiler enough to try and debug it, but couldn't fumble my way through it, I'm afraid. I can only hypothesise that there's a similar issue going on inside each Go compiler invocation, something about the way it invokes sub-processes, perhaps, or perhaps something else entirely.

@jayconrod
Copy link
Contributor

@jayconrod jayconrod commented Feb 1, 2021

@omaskery Thanks for doing the work of tracking this down.

Based on these numbers, it seems like it would be reasonable to try and cache exec.LookPath calls, so we don't repeatedly look for the C compiler. Note that we tried to do that in 1.15.7 to fix a security issue, but we ran into a regression (#43808) and had to revert part of that fix. A complete solution will need to be a bit more clever.

That said, it seems like os.Stat takes a surprisingly long time on your machine. I ran a quick benchmark on my Windows box:

BenchmarkStatExists-16             35599             32790 ns/op
BenchmarkStatMissing-16            31488             37484 ns/op
BenchmarkLookPathExists-16           267           4431754 ns/op
BenchmarkLookPathMissing-16          112          10707762 ns/op

On my machine, an os.Stat call for a missing file takes about 37us. That was with a pretty standard Windows 10 / NTFS installation with no antivirus other than Defender. Any idea what might cause it to be slower in your environment?

@omaskery
Copy link

@omaskery omaskery commented Feb 1, 2021

Now that is interesting! I'm afraid I have no idea what might be causing os.Stat to be slow on my machine specifically, though I'd be fascinated to find out. I'm not really sure how I'd investigate this, though - any advice?

The source code, compiler, IDEs, etc. are all on NVMe drives, so I don't think it's some kind of I/O latency. My RAM isn't full, so I don't think it's memory constrained. My CPU isn't maxed out, so I don't think it's CPU constrained. I've tried updating every driver I could get my hands on for my machine, wondering if it was some obscure driver issue for certain I/O operations, but that didn't help at all.

I do notice that on Linux the os.Stat command is very simple (presumably because it has a 1-1 mapping with the underlying APIs on Linux), whilst on Windows there are several underlying API calls it makes. I wonder which of those invocations is slow for me, and whether that will give us any hints? I might try copying the implementation of os.Stat and benchmarking bits of it, or something like that.

@jayconrod
Copy link
Contributor

@jayconrod jayconrod commented Feb 1, 2021

@omaskery I wish I knew what might cause this. I don't know enough about Windows internals to know what to look for though.

If you're running with NVMe drives, I expect you're running on more modern hardware than I am. I'd expect these microbenchmarks to mostly be bottlenecked on RAM speed, but since there's an order of magnitude difference, I'd be very surprised if it were anything hardware related.

So my uninformed guess is that this is something related to antivirus or some other system software that runs code when the file system is accessed.

@omaskery
Copy link

@omaskery omaskery commented Feb 2, 2021

@jayconrod good intuition!

I consulted a Wizard Friend of mine for help diagnosing what might be intercepting my IO, given I thought I had no antivirus installed (and I had tried disabling Windows Defender). They suggested I use Driver View and sent them the output, and they just validated the kernel drivers with their eyes and pointed me at all the suspect ones.

I ended up identifying Trusteer Endpoint Security from IBM as the cause!

My benchmark output for now:

NOTE: pathext contains 11 extensions
NOTE: path has 36 entries
goos: windows
goarch: amd64
pkg: golang-exec-slow-testbed
BenchmarkBuiltinUnknownCommand-12                                      	      31	  35757552 ns/op
BenchmarkBuiltinKnownCommand-12                                        	    1904	    550471 ns/op
BenchmarkLocalCopyWithUnknownCommand-12                                	      38	  32026726 ns/op
BenchmarkLocalCopyWithKnownCommand-12                                  	    2181	    533699 ns/op
BenchmarkFindExecutableWithExistingFileButNoExtensions-12              	  190474	      6452 ns/op
BenchmarkFindExecutableWithExistingFileWithSomeExtensions-12           	  184616	      6522 ns/op
BenchmarkFindExecutableWithExistingFileWithRealExtensions-12           	  187111	      6504 ns/op
BenchmarkFindExecutableWithNonExistingFileButNoExtensions-12           	   34681	     34688 ns/op
BenchmarkFindExecutableWithNonExistingFileWithSomeExtensions-12        	   10000	    106400 ns/op
BenchmarkFindExecutableWithNonExistingFileWithRealExtensions-12        	    3076	    386866 ns/op
BenchmarkFindExecutableOnExistingFileProportionalToPathLength-12       	    5217	    236151 ns/op
BenchmarkFindExecutableOnNonExistingFileProportionalToPathLength-12    	      85	  13894148 ns/op
BenchmarkStatOnExistingFile-12                                         	  173916	      6325 ns/op
BenchmarkStatOnNonExistingFile-12                                      	   34681	     34601 ns/op
PASS

My os.Stat benchmarks now look a lot like yours, ~35us! What a day, what a lovely day!

Edit: COMPILING GO (as in github.com/golang/go) NOW TAKES ABOUT A MINUTE! So exciting! :)

Is this enough evidence to suggest that these issues are just down to antivirus-like software intercepting IO and generally ruining things?

@jayconrod
Copy link
Contributor

@jayconrod jayconrod commented Feb 2, 2021

@omaskery Awesome! Glad you were able to find the culprit. I think that's pretty strong evidence.

For cmd/go, I think the right way to handle this is still to cache results of exec.LookPath. Even without antivirus, it's still a relatively expensive operation on Windows, and we should avoid repeating the work for each package.

I'll put this on the Go1.17 milestone. Not 100% sure we'll get to it, but it seems like low-hanging fruit as far as optimizations go.

@jayconrod jayconrod removed this from the Unplanned milestone Feb 2, 2021
@jayconrod jayconrod added this to the Go1.17 milestone Feb 2, 2021
@duguanyue
Copy link

@duguanyue duguanyue commented Feb 8, 2021

@jayconrod

Awesome!. I close my antivirus and everything is back to normal.

@StayTherapy
Copy link

@StayTherapy StayTherapy commented Mar 18, 2021

@jayconrod good intuition!

I consulted a Wizard Friend of mine for help diagnosing what might be intercepting my IO, given I thought I had no antivirus installed (and I had tried disabling Windows Defender). They suggested I use Driver View and sent them the output, and they just validated the kernel drivers with their eyes and pointed me at all the suspect ones.

I ended up identifying Trusteer Endpoint Security from IBM as the cause!

My benchmark output for now:

NOTE: pathext contains 11 extensions
NOTE: path has 36 entries
goos: windows
goarch: amd64
pkg: golang-exec-slow-testbed
BenchmarkBuiltinUnknownCommand-12                                      	      31	  35757552 ns/op
BenchmarkBuiltinKnownCommand-12                                        	    1904	    550471 ns/op
BenchmarkLocalCopyWithUnknownCommand-12                                	      38	  32026726 ns/op
BenchmarkLocalCopyWithKnownCommand-12                                  	    2181	    533699 ns/op
BenchmarkFindExecutableWithExistingFileButNoExtensions-12              	  190474	      6452 ns/op
BenchmarkFindExecutableWithExistingFileWithSomeExtensions-12           	  184616	      6522 ns/op
BenchmarkFindExecutableWithExistingFileWithRealExtensions-12           	  187111	      6504 ns/op
BenchmarkFindExecutableWithNonExistingFileButNoExtensions-12           	   34681	     34688 ns/op
BenchmarkFindExecutableWithNonExistingFileWithSomeExtensions-12        	   10000	    106400 ns/op
BenchmarkFindExecutableWithNonExistingFileWithRealExtensions-12        	    3076	    386866 ns/op
BenchmarkFindExecutableOnExistingFileProportionalToPathLength-12       	    5217	    236151 ns/op
BenchmarkFindExecutableOnNonExistingFileProportionalToPathLength-12    	      85	  13894148 ns/op
BenchmarkStatOnExistingFile-12                                         	  173916	      6325 ns/op
BenchmarkStatOnNonExistingFile-12                                      	   34681	     34601 ns/op
PASS

My os.Stat benchmarks now look a lot like yours, ~35us! What a day, what a lovely day!

Edit: COMPILING GO (as in github.com/golang/go) NOW TAKES ABOUT A MINUTE! So exciting! :)

Is this enough evidence to suggest that these issues are just down to antivirus-like software intercepting IO and generally ruining things?

Can NOT believe it ! The antivirus software affects Golang 😧
I have the same problem. OS is macOS 11.2.3, Golang is go1.16, and even go run hello world (just main function and print simple string) took 2 minutes+, I debug this problem a long time , including changing the proxy settings .

When I disable Avira realtime protect, every thing be OK.

@ianlancetaylor ianlancetaylor changed the title cmd/go: compiles really slowly even for a hello world program cmd/go: cache results of exec.LookPath Apr 22, 2021
@ianlancetaylor ianlancetaylor removed this from the Go1.17 milestone Apr 22, 2021
@ianlancetaylor ianlancetaylor added this to the Backlog milestone Apr 22, 2021
@bitwayiki

This comment was marked as off-topic.

@ianlancetaylor

This comment was marked as off-topic.

@ch33hau
Copy link

@ch33hau ch33hau commented May 21, 2021

Hi @ianlancetaylor, can I work on this issue?

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented May 21, 2021

@ch33hau

Hi @ianlancetaylor, can I work on this issue?

Thanks for offering. That is a question for @jayconrod. I don't know if there are any plans for this already in progress.

@jayconrod
Copy link
Contributor

@jayconrod jayconrod commented May 24, 2021

@ch33hau Sure, you're welcome to take a look. I don't think anyone's actively working on this.

The simplest thing is probably to wrap calls to exec.Command and exec.LookPath from cmd/go/internal/work with something that caches the lookup. So we'd only directly call exec.Command with an absolute path after that.

We use cmd/go/internal/par.Cache for caching operations like this that could be performed concurrently, which may be the case here.

@ch33hau
Copy link

@ch33hau ch33hau commented May 27, 2021

Hi @ianlancetaylor @jayconrod, thank you for the replies and tips, I am glad to hear this!

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