cmd/trace: "failed to parse trace: no consistent ordering of events possible" #29707

256dpi · 2019-01-12T11:44:01Z

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

$ go version
go version go1.11.4 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
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/256dpi/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/256dpi/Development/Go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/Cellar/go/1.11.4/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.11.4/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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/mj/lp3r462x6tqfd4v_93bvh65h0000gn/T/go-build000614795=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I ran a network intensive go program (closed source) with a fairly light workload.

What did you expect to see?

I expect to be able to obtain a trace profile and explore it with the viewer program.

What did you see instead?

After obtaining the profile with wget -O trace.out "http://localhost:6060/debug/pprof/trace?seconds=10". When running go tool trace trace.out I received:

2019/01/12 12:37:26 Parsing trace...
failed to parse trace: no consistent ordering of events possible

The text was updated successfully, but these errors were encountered:

256dpi · 2019-01-15T12:39:19Z

I have to add, I was testing a binary that was linked with C code (CGO). Is it possible that tracing does not work properly in CGO builds?

bcmills · 2019-01-30T16:30:40Z

CC @rsc @hyangah @matloob @dvyukov for pprof and trace

hyangah · 2019-01-30T17:38:53Z

#16755 was the first one that came to my mind, but I've never seen the issue with darwin/amd64, so I am not sure. I am not aware of cmd/trace issues involving cgo.

@256dpi is it possible to share the captured trace with me?

AlexRouSg · 2019-05-04T03:43:23Z

@hyangah I just ran into this and made a repo.

Basically it happens when you export a Go function to C and then call that function inside a C created thread.

package test

/*
	#include <pthread.h>

	extern void* callback(void*);
	typedef void* (*cb)(void*);

	static void testCallback(cb cb) {
		pthread_t thread_id;
		pthread_create(&thread_id, NULL, cb, NULL);
    	        pthread_join(thread_id, NULL);
	}
*/
import "C"
import (
	"context"
	"runtime/trace"
	"time"
	"unsafe"
)

var traceCtx, traceTask = trace.NewTask(context.Background(), "Debug")

func test() {
	C.testCallback(C.cb(C.callback))
}

//export callback
func callback(unsafe.Pointer) unsafe.Pointer {
	defer trace.StartRegion(traceCtx, "callback").End()
	time.Sleep(time.Millisecond)

	return nil
}

bcmills · 2019-06-26T14:35:24Z

Here's a related flake in runtime/trace.TestTraceStressStartStop on the freebsd-amd64-12_0 builder:
https://build.golang.org/log/65ddd079bfd87715555a97b296b41dfa64ff12b6

--- FAIL: TestTraceStressStartStop (1.14s)
    trace_test.go:147: failed to parse trace: no consistent ordering of events possible
FAIL
FAIL	runtime/trace	1.574s

let4be · 2020-02-17T18:59:23Z

Any update? I cannot parse trace created on arm64 from x86 machine

bcmills · 2020-05-04T18:43:33Z

2020-05-04T18:16:49-4c003f6/linux-amd64-jessie
2020-05-02T18:10:49-9439a7d/linux-arm
2020-05-01T18:01:28-b565d1e/linux-amd64
2020-05-01T15:02:37-f092be8/windows-amd64-longtest
2019-11-22T21:09:43-9f3c2b6/windows-amd64-longtest

gopherbot · 2020-05-19T16:40:33Z

Change https://golang.org/cl/234617 mentions this issue: runtime: synchronize StartTrace and StopTrace with sysmon

Currently sysmon is not stopped when the world is stopped, which is in general a difficult thing to do. The result of this is that when tracing starts and the value of trace.enabled changes, it's possible for sysmon to fail to emit an event when it really should. This leads to traces which the execution trace parser deems inconsistent. Fix this by putting all of sysmon's work behind a new lock sysmonlock. StartTrace and StopTrace both acquire this lock after stopping the world but before performing any work in order to ensure sysmon sees the required state change in tracing. This change is expected to slow down StartTrace and StopTrace, but will help ensure consistent traces are generated. Updates #29707. Fixes #38794. Change-Id: I64c58e7c3fd173cd5281ffc208d6db24ff6c0284 Reviewed-on: https://go-review.googlesource.com/c/go/+/234617 Run-TryBot: Michael Knyszek <mknyszek@google.com> Run-TryBot: Ian Lance Taylor <iant@golang.org> Reviewed-by: Ian Lance Taylor <iant@golang.org> Reviewed-by: Hyang-Ah Hana Kim <hyangah@gmail.com> Reviewed-by: Michael Pratt <mpratt@google.com>

davies · 2020-06-22T07:44:30Z

I tried with latest master branch, it still has this problem

$ go version
go version devel +60f7876 Sat Jun 20 08:40:13 2020 +0000 linux/amd64

The go code is built as a so, and called by Java. We can reproduce it every time under normal workload, but OK when it's idle.

entombedvirus · 2020-07-20T19:35:57Z

I can repro this issue on our production services consistently:

go version
go version go1.14.4 linux/amd64

I've also tried running gotip tool trace to parse trace output generated from go1.14.4 binary and that gives the same result. I haven't tried generating trace output from gotip because I want to avoid running gotip in production. Please let me know if having access to the trace output is helpful to debug.

choleraehyq · 2020-08-19T12:45:59Z

Can repro this issue on our production services every time, with Go 1.15. Our code involves cgo, don't know whether it's related.

hyangah · 2020-09-09T20:03:18Z

For anyone who's interested in investigating this, I am attaching a trace from the program @AlexRouSg posted.
trace.out in the attached repro.zip file was generated with go test -trace=trace.out.

This trace parsing failed because of an unexpected GoSysExit event at offset 48 (almost at the beginning of the trace) This is unexpected - there was no preceding event with the goroutine 17 before this event. We usually expect a GoInSyscall if the goroutine was in syscall. See

go/src/runtime/trace.go

Lines 207 to 213 in c847589

    
           // Can't set trace.enabled yet. While the world is stopped, exitsyscall could 
        
           // already emit a delayed event (see exitTicks in exitsyscall) if we set trace.enabled here. 
        
           // That would lead to an inconsistent trace: 
        
           // - either GoSysExit appears before EvGoInSyscall, 
        
           // - or GoSysExit appears for a goroutine for which we don't emit EvGoInSyscall below. 
        
           // To instruct traceEvent that it must not ignore events below, we set startingtrace. 
        
           // trace.enabled is set afterwards once we have emitted all preliminary events.

.

I suspect the code path that should trigger GoInSyscall events for all goroutines in syscall was broken.

go/src/runtime/trace.go

Line 239 in c847589

traceEvent(traceEvGoInSyscall, -1, uint64(gp.goid))

I couldn't find the corresponding stack info (stack id: 0) in the trace, so don't know what goroutine this is either. :-(

cc runtime people: @dvyukov @aclements @mknyszek @ianlancetaylor

michaelfig · 2021-01-29T20:41:46Z

Is there any progress on this? Even a suggested workaround would be welcome.

I'm using the same basic pattern as #29707 (comment)
to invoke a Go shared library from a Node.js driver program.

AlexRouSg · 2021-01-29T20:50:41Z

@michaelfig the only workaround I can find is to never call Go code from C created threads

michaelfig · 2021-01-31T21:33:45Z

@michaelfig the only workaround I can find is to never call Go code from C created threads

Thanks, I think I'll be able to manage that for our application.

wangfakang · 2021-06-23T06:08:12Z

same issue，have any update?

nejisama · 2021-07-16T06:12:13Z

I use curl http://addr:port/debug/pprof/trace to get the trace file, and get the same error.
by my test, if my program is in a high concurrency state, the trace file will be parsed failed with the error, if my program is idle, the trace file will be ok.

aclements · 2021-07-19T13:19:38Z

@wangfakang, @nejisama, do your applications also involve call-backs from C to Go on threads created in C?

wenxuwan · 2021-08-20T02:08:50Z

same issue, waiting for update, program no cgo, go version 1.14.15

leonsal · 2021-09-20T16:05:41Z

same problem here using go1.17.1.
My app uses a binding to rtaudio C library which callbacks the Go program periodically to get more samples to play.
If I don't use rtaudio, discarding the generated samples, trace works.

wangfakang · 2021-11-12T06:35:05Z

@aclements yeah.

bcmills · 2022-02-16T20:18:06Z

greplogs --dashboard -md -l -e 'failed to parse trace: no consistent ordering of events possible' --since=2020-05-05

2022-02-16T16:06:39-f985833/dragonfly-amd64
2020-05-20T03:40:22-4ec4a79/darwin-amd64-race
2020-05-18T20:53:36-3b0882e/linux-arm
2020-05-14T18:58:17-f474e9e/openbsd-386-64
2020-05-11T15:33:30-daf39d0/linux-386-longtest
2020-05-11T14:21:36-d40b0a1/linux-arm
2020-05-08T20:28:57-26de581/windows-amd64-longtest
2020-05-08T00:05:42-95c5ec6/freebsd-amd64-race
2020-05-07T21:39:50-14ae846/linux-arm64-packet
2020-05-07T20:45:42-f9640b8/linux-amd64-longtest
2020-05-07T19:22:19-6f52790/windows-amd64-2008
2020-05-07T15:47:09-97240d5/windows-amd64-longtest
2020-05-07T07:06:11-1764819/linux-mips64le-mengzhuo
2020-05-07T04:45:51-9e81578/windows-amd64-longtest
2020-05-07T04:05:18-94e61ab/windows-amd64-longtest
2020-05-06T19:03:06-641918e/linux-s390x-ibm
2020-05-06T17:06:02-e538b7e/linux-386-longtest
2020-05-06T01:27:05-fdb8a3e/android-amd64-emu

The nearly-two-year gap in builder failures matching this pattern is very curious.

bcmills · 2022-02-16T20:24:15Z

The 2022 failure is also not one of the tests that frequently triggered this in the past. 🤔

(I've filed it separately as #51224.)

xiaoyao · 2022-05-27T07:31:53Z

I meet the same problem!

gopherbot · 2022-06-08T08:54:19Z

Change https://go.dev/cl/411034 mentions this issue: runtime/trace: missing events for the locked g in extra M.

yalon · 2022-07-11T08:21:17Z

Have the same issue on Go 1.18.3 linux/amd64, in my case Python's the main, calling Go via CFFI (C basically). While Python/C creates its own threads, the problem happens when there's high concurrency. Unfortunately in my case I can't control the Python side so any idea on how to work around this would be great.

prattmic · 2022-08-15T15:30:18Z

Temporarily reverted in https://go.dev/cl/423437.

gopherbot · 2022-09-10T16:01:14Z

Change https://go.dev/cl/429858 mentions this issue: runtime/trace: add missing events for the locked g in extra M.

bcmills changed the title ~~failed to parse trace: no consistent ordering of events possible~~ net/http/pprof: "failed to parse trace: no consistent ordering of events possible" Jan 30, 2019

bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 30, 2019

bcmills added this to the Go1.13 milestone Jan 30, 2019

bcmills changed the title ~~net/http/pprof: "failed to parse trace: no consistent ordering of events possible"~~ cmd/trace: "failed to parse trace: no consistent ordering of events possible" Jan 30, 2019

andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019

rsc modified the milestones: Go1.14, Backlog Oct 9, 2019

danscales mentioned this issue Dec 17, 2019

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

Closed

hyangah mentioned this issue May 7, 2020

runtime/trace: test failures increased as of 2020-05-01 #38794

Closed

tpaschalis mentioned this issue Sep 9, 2020

go tool trace not work #41291

Closed

bcmills mentioned this issue Feb 16, 2022

runtime/trace: TestTraceFutileWakeup failure with "no consistent ordering of events possible" #51224

Open

doujiang24 mentioned this issue Jun 8, 2022

runtime/trace: add missing events for the locked g in extra M. #53284

Closed

gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jul 7, 2022

prattmic mentioned this issue Jul 27, 2022

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

Closed

gopherbot closed this as completed in ea9c3fd Aug 12, 2022

prattmic mentioned this issue Aug 15, 2022

runtime: new test TestCgoTraceParser failing #54458

Closed

prattmic reopened this Aug 15, 2022

doujiang24 mentioned this issue Sep 10, 2022

runtime/trace: add missing events for the locked g in extra M. #54974

Closed

gopherbot closed this as completed in fb6c210 Sep 27, 2022

golang locked and limited conversation to collaborators Sep 27, 2023

gopherbot added the FrozenDueToAge label Sep 27, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/trace: "failed to parse trace: no consistent ordering of events possible" #29707

cmd/trace: "failed to parse trace: no consistent ordering of events possible" #29707

256dpi commented Jan 12, 2019

256dpi commented Jan 15, 2019

bcmills commented Jan 30, 2019 •

edited

Loading

hyangah commented Jan 30, 2019

AlexRouSg commented May 4, 2019

bcmills commented Jun 26, 2019

let4be commented Feb 17, 2020

bcmills commented May 4, 2020

gopherbot commented May 19, 2020

davies commented Jun 22, 2020

entombedvirus commented Jul 20, 2020

choleraehyq commented Aug 19, 2020

hyangah commented Sep 9, 2020 •

edited

Loading

michaelfig commented Jan 29, 2021

AlexRouSg commented Jan 29, 2021

michaelfig commented Jan 31, 2021

wangfakang commented Jun 23, 2021

nejisama commented Jul 16, 2021

aclements commented Jul 19, 2021

wenxuwan commented Aug 20, 2021

leonsal commented Sep 20, 2021

wangfakang commented Nov 12, 2021

bcmills commented Feb 16, 2022

bcmills commented Feb 16, 2022

xiaoyao commented May 27, 2022

gopherbot commented Jun 8, 2022

yalon commented Jul 11, 2022 •

edited

Loading

prattmic commented Aug 15, 2022

gopherbot commented Sep 10, 2022

cmd/trace: "failed to parse trace: no consistent ordering of events possible" #29707

cmd/trace: "failed to parse trace: no consistent ordering of events possible" #29707

Comments

256dpi commented Jan 12, 2019

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

256dpi commented Jan 15, 2019

bcmills commented Jan 30, 2019 • edited Loading

hyangah commented Jan 30, 2019

AlexRouSg commented May 4, 2019

bcmills commented Jun 26, 2019

let4be commented Feb 17, 2020

bcmills commented May 4, 2020

gopherbot commented May 19, 2020

davies commented Jun 22, 2020

entombedvirus commented Jul 20, 2020

choleraehyq commented Aug 19, 2020

hyangah commented Sep 9, 2020 • edited Loading

michaelfig commented Jan 29, 2021

AlexRouSg commented Jan 29, 2021

michaelfig commented Jan 31, 2021

wangfakang commented Jun 23, 2021

nejisama commented Jul 16, 2021

aclements commented Jul 19, 2021

wenxuwan commented Aug 20, 2021

leonsal commented Sep 20, 2021

wangfakang commented Nov 12, 2021

bcmills commented Feb 16, 2022

bcmills commented Feb 16, 2022

xiaoyao commented May 27, 2022

gopherbot commented Jun 8, 2022

yalon commented Jul 11, 2022 • edited Loading

prattmic commented Aug 15, 2022

gopherbot commented Sep 10, 2022

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

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

bcmills commented Jan 30, 2019 •

edited

Loading

hyangah commented Sep 9, 2020 •

edited

Loading

yalon commented Jul 11, 2022 •

edited

Loading