Navigation Menu

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

Jump to bottom

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

Closed
ardan-bkennedy opened this issue May 8, 2022 · 6 comments
Closed

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

ardan-bkennedy opened this issue May 8, 2022 · 6 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@ardan-bkennedy
Copy link

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
Copy link
Author

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
Copy link
Contributor

rhysh commented May 8, 2022

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
Copy link
Contributor

heschi commented May 9, 2022

cc @golang/runtime

@heschi heschi added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 9, 2022
@heschi heschi added this to the Backlog milestone May 9, 2022
@heschi heschi changed the title runtime/trace: runtime/trace: fails to parse trace with "time stamps out of order" May 9, 2022
@bcmills
Copy link
Contributor

bcmills commented May 9, 2022

See previously #16755.

@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jul 7, 2022
@prattmic
Copy link
Member

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
Copy link
Contributor

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
7 participants
@rhysh @mknyszek @prattmic @ardan-bkennedy @bcmills @gopherbot @heschi