runtime, cmd/trace: recent regression: "failed to parse trace: no consistent ordering of events possible

[danscales]

Recent regression: I ran the BenchmarkClientServerParallel4 benchmark with tracing enabled and 'go tool trace' can't deal with the trace file. I bisected the problem to change 7148478 by @rhysh . I'm guessing that the semaphore optimization in that change is somehow confusing the trace tool, and the trace tool needs to be updated to understand the event ordering.

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

Tip 4b21702 , essentially go 1.14 beta 1

Does this issue reproduce with the latest release?

Does not happen in go 1.13

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

go env Output

$ go env
GO111MODULE=""

GOARCH="amd64"

GOBIN=""

GOCACHE="/usr/local/google/home/danscales/.cache/go-build"

GOENV="/usr/local/google/home/danscales/.config/go/env"

GOEXE=""

GOFLAGS=""

GOHOSTARCH="amd64"

GOHOSTOS="linux"

GOINSECURE=""

GONOPROXY=""

GONOSUMDB=""

GOOS="linux"

GOPATH="/usr/local/google/home/danscales/go"

GOPRIVATE=""

GOPROXY="https://proxy.golang.org,direct"

GOROOT="/usr/local/google/home/danscales/gerrit/go"

GOSUMDB="sum.golang.org"

GOTMPDIR=""

GOTOOLDIR="/usr/local/google/home/danscales/gerrit/go/pkg/tool/linux_amd64"

GCCGO="gccgo"

AR="ar"

CC="gcc"

CXX="g++"

CGO_ENABLED="1"

GOMOD="/usr/local/google/home/danscales/gerrit/go/src/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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build750268088=/tmp/go-build -gno-record-gcc-switches"

What did you do?

% go test -trace trace.out -run NONE -bench BenchmarkClientServerParallel4 net/http
goos: linux
goarch: amd64
pkg: net/http
BenchmarkClientServerParallel4-12          31840             39298 ns/op           10043 B/op        80 allocs/op
PASS
ok      net/http        2.416s
% go tool trace trace.out
2019/12/17 10:07:54 Parsing trace...
failed to parse trace: no consistent ordering of events possible

What did you expect to see?

Expected to see normal output like:

2019/12/17 10:19:17 Parsing trace...
2019/12/17 10:19:22 Splitting trace...
2019/12/17 10:19:28 Opening browser. Trace viewer is listening on http://127.0.0.1:42335

and the trace web page comes up in the browser.

What did you see instead?

The "failed to parse trace: no consistent ordering of events possible" error message.

This is related to issue #29707 , which has the same error message, but is currently only indicated for programs related to cgo or a rare test failure. The failure in this bug is consistent and a more recent regression (and seems unrelated to cgo).

[aclements]

Tentatively marking this as a release blocker, since it could make the execution tracer unusable.

I suspect we're missing some trace event or just modeling things wrong in the new direct-yield path.

[gopherbot]

Change https://golang.org/cl/211797 mentions this issue: runtime: emit trace event in direct semaphore handoff