runtime/trace: fails to parse trace with "time stamps out of order"

[ardan-bkennedy]

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

$ go version
go version go1.18.1 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/bill/Library/Caches/go-build"
GOENV="/Users/bill/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/bill/code/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/bill/code/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"
GOVCS=""
GOVERSION="go1.18.1"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/bill/code/go/src/github.com/ardanlabs/gotraining/go.mod"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/k6/bpxy86ts4yz4796zp3pj6wq00000gn/T/go-build4170740601=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

This is a program I have used for years to teach the tracing tool. https://github.com/ardanlabs/gotraining/tree/master/topics/go/profiling/trace

These are the changes you need to make to main.

Uncomment out the trace calls and run freqConcurrent

func main() {
    // pprof.StartCPUProfile(os.Stdout)
    // defer pprof.StopCPUProfile()

    trace.Start(os.Stdout)
    defer trace.Stop()

    docs := make([]string, 4000)
    for i := range docs {
        docs[i] = fmt.Sprintf("newsfeed-%.4d.xml", i)
    }

    topic := "president"
    // n := freq(topic, docs)
    n := freqConcurrent(topic, docs)
    // n := freqConcurrentSem(topic, docs)
    // n := freqProcessors(topic, docs)
    // n := freqProcessorsTasks(topic, docs)
    // n := freqActor(topic, docs)

    log.Printf("Searching %d files, found %s %d times.", len(docs), topic, n)
}

Then run as follows

$ go build
$ ./trace > t.out

What did you expect to see?

I expected the trace to be read and the browser to present itself.

What did you see instead?

2022/05/08 15:47:30 Parsing trace...
failed to parse trace: time stamps out of order

[ardan-bkennedy]

I just tested with gotip

$ gotip version
go version devel go1.19-3391517c0e Sun May 8 17:29:15 2022 +0000 darwin/arm64

I did not see this issue at all.

[rhysh]

It looks like there are two machines involved, one on amd64 (broken with go1.18.1) and one on arm64 (working with tip). Is that right?

IIUC, the timestamps available to the execution tracer are different on x86 processors vs on ARM.

I wasn't able to reproduce the problem on my darwin/arm64 machine with go1.18.1 or with tip (yesterday's go version devel go1.19-a131fd1313 Sat May 7 10:56:06 2022 +0000 darwin/arm64).

[heschi]

cc @golang/runtime

[bcmills]

See previously #16755.

[prattmic]

Does this program use cgo? (Looks like no?)

29707 is a known case of this with a pending fix, but it only affects cgo binaries.

[mknyszek]

With the new tracer this error can no longer happen -- timestamps are not used for ordering events anymore. (See #60773.)