runtime: sometimes 100% CPU spin during init phase in Go 1.14 with preemptive scheduler

[mholt]

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

$ go version
go version go1.14 darwin/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
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/matt/Library/Caches/go-build"
GOENV="/Users/matt/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/matt/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/matt/Dev/caddyserver/caddy/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/97/r6t5z7zj0sd8pgh13bnwjh2w0000gn/T/go-build879531905=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Ran go run main.go, in my case, specifically in this folder.

What did you expect to see?

The program should run.

What did you see instead?

Sometimes, the CPU spins at 100% and the entry point of the program is never reached reached after anywhere from 5-50s (but there are probably no hard bounds on this, it's just what I've observed).

This is part of my typical development cycle where I write some code, then run the program, write more code, run the program, etc. Sometimes it happens, sometimes it doesn't. Even without changes, re-running the command will work. I can't pin it down, unfortunately, nor make a simpler test case.

I verified that the entry point main() is never reached, by changing main() so it is now:

func main() {
	log.Println("Got here")
	caddycmd.Main()
}

and can verify that "Got here" is never printed. Instead, the CPU spins:

In the past, @whitestrake has reported a similar phenomenon independently, but I only started noticing it recently myself. So, I know it's not isolated to just my machine.

Let me know what more would be useful to debug this. Thanks!

[dmitshur]

How often does this happen? Is it possible to reproduce by trying it some number of times?

Does it happen with go build too, or only go run main.go?

All imported packages get initialized before main is executed (see https://golang.org/ref/spec#Package_initialization for details). Is it possible some of your imported packages have init() that sometimes take too long? Or top level variable declarations that call functions?

In the screenshot you posted, the process name is main, which I believe means what's running and using 100% CPU is the binary that was built, not the go command.

[mholt]

That's a good point about init(), I could put the log line into init() but I guess that won't help since inits are called in a nondeterminstic (or at least unknown) order, so any offending init() might be called first.

You're probably right... although I haven't seen it happen with go build or any non-temporary binaries. I'll get more info and reopen if I can pin it down. Thanks

[dmitshur]

To clarify, package initialization is done in a deterministic order, as defined in the Go specification.

I agree it might be hard to know what init functions are being called when you are importing many packages transitively. Maybe a debugger or some other tool can help when investigating an issue like this.

[mholt]

To clarify, package initialization is done in a deterministic order,

Yes, but it's pretty opaque in practice :) i.e. it's not trivial to know in a large project the exact order of all instances of init(). If there's a tool that can print that out, that could be helpful in this case. It's deterministic to the compiler, but not to the program being compiled, since the program being compiled doesn't have the scope of perspective of the compiler AFAIK. Anyway, thanks!

[mholt]

@dmitshur Do you know of a way I can run a profile that starts before the init phase? Based on your feedback, I'm 99% sure this is a bad init() function or bad var foo = ... declaration somewhere. So I need to start a profile before all those are run.

[randall77]

Starting the profiler early would be hard. Can you run under a debugger, then just ctrl-C when it hangs and see where the code is executing?

[mholt]

Nevermind! Gopher Slack is awesome. Someone gave me a tip: pkill -ABRT main and then you get a stack trace and registers. Worked like a charm. Thanks everyone!

[mholt]

@dmitshur @randall77 The plot thickens, as I can only reproduce the bug in Go 1.14 and not Go 1.13: census-instrumentation/opencensus-go#1200

I suspect this might be a bug in the Go scheduler? One or more goroutines are blocking on select, but the stack trace of the active goroutine is still "unavailable". That linked issue has more details.

Any advice on where to go from here? I wish I could make the reproduction more minimal, but I just haven't figured it out as it seems dependent on importing (and using) these packages (even though the "using" code doesn't even get reached).