From ea9c3fd42d94182ce6f87104b68a51ea92f1a571 Mon Sep 17 00:00:00 2001 From: doujiang24 Date: Fri, 12 Aug 2022 02:28:43 +0000 Subject: [PATCH] runtime/trace: add missing events for the locked g in extra M. Extra Ms may lead to the "no consistent ordering of events possible" error when parsing trace file with cgo enabled, since: 1. The gs in the extra Ms may be in `_Gdead` status while starting trace by invoking `runtime.StartTrace`, 2. and these gs will trigger `traceEvGoSysExit` events in `runtime.exitsyscall` when invoking go functions from c, 3. then, the events of those gs are under non-consistent ordering, due to missing the previous events. Add two events, `traceEvGoCreate` and `traceEvGoInSyscall`, in `runtime.StartTrace`, will make the trace parser happy. Fixes #29707 Change-Id: I7cc4b80822d2c46591304a59c9da2c9fc470f1d0 GitHub-Last-Rev: 445de8eaf3fb54e12795ac31e26650f821c5efbc GitHub-Pull-Request: golang/go#53284 Reviewed-on: https://go-review.googlesource.com/c/go/+/411034 Run-TryBot: Michael Pratt Reviewed-by: Michael Knyszek Auto-Submit: Michael Pratt TryBot-Result: Gopher Robot Reviewed-by: Michael Pratt --- src/internal/trace/goroutines.go | 5 +- src/runtime/crash_cgo_test.go | 13 +++++ src/runtime/proc.go | 9 +++ src/runtime/runtime2.go | 1 + .../testdata/testprogcgo/issue29707.go | 58 +++++++++++++++++++ src/runtime/trace.go | 13 ++++- 6 files changed, 96 insertions(+), 3 deletions(-) create mode 100644 src/runtime/testdata/testprogcgo/issue29707.go diff --git a/src/internal/trace/goroutines.go b/src/internal/trace/goroutines.go index 5da90e0b6d..8df5e6c6c5 100644 --- a/src/internal/trace/goroutines.go +++ b/src/internal/trace/goroutines.go @@ -187,7 +187,7 @@ func GoroutineStats(events []*Event) map[uint64]*GDesc { gs[g.ID] = g case EvGoStart, EvGoStartLabel: g := gs[ev.G] - if g.PC == 0 { + if g.PC == 0 && len(ev.Stk) > 0 { g.PC = ev.Stk[0].PC g.Name = ev.Stk[0].Fn } @@ -353,5 +353,6 @@ func RelatedGoroutines(events []*Event, goid uint64) map[uint64]bool { func IsSystemGoroutine(entryFn string) bool { // This mimics runtime.isSystemGoroutine as closely as // possible. - return entryFn != "runtime.main" && strings.HasPrefix(entryFn, "runtime.") + // Also, locked g in extra M (with empty entryFn) is system goroutine. + return entryFn == "" || entryFn != "runtime.main" && strings.HasPrefix(entryFn, "runtime.") } diff --git a/src/runtime/crash_cgo_test.go b/src/runtime/crash_cgo_test.go index 5e58712297..d5df27cb11 100644 --- a/src/runtime/crash_cgo_test.go +++ b/src/runtime/crash_cgo_test.go @@ -710,3 +710,16 @@ func TestCgoTracebackGoroutineProfile(t *testing.T) { t.Fatalf("want %s, got %s\n", want, output) } } + +func TestCgoTraceParser(t *testing.T) { + // Test issue 29707. + switch runtime.GOOS { + case "windows", "plan9": + t.Skipf("skipping cgo trace parser test on %s", runtime.GOOS) + } + output := runTestProg(t, "testprogcgo", "CgoTraceParser") + want := "OK\n" + if output != want { + t.Fatalf("want %s, got %s\n", want, output) + } +} diff --git a/src/runtime/proc.go b/src/runtime/proc.go index a112c1b80c..9a7bd941db 100644 --- a/src/runtime/proc.go +++ b/src/runtime/proc.go @@ -1917,6 +1917,7 @@ func oneNewExtraM() { casgstatus(gp, _Gidle, _Gdead) gp.m = mp mp.curg = gp + mp.isextra = true mp.lockedInt++ mp.lockedg.set(gp) gp.lockedm.set(mp) @@ -1924,6 +1925,14 @@ func oneNewExtraM() { if raceenabled { gp.racectx = racegostart(abi.FuncPCABIInternal(newextram) + sys.PCQuantum) } + if trace.enabled { + // trigger two trace events for the locked g in the extra m, + // since the next event of the g will be traceEvGoSysExit in exitsyscall, + // while calling from C thread to Go. + traceGoCreate(gp, 0) // no start pc + gp.traceseq++ + traceEvent(traceEvGoInSyscall, -1, gp.goid) + } // put on allg for garbage collector allgadd(gp) diff --git a/src/runtime/runtime2.go b/src/runtime/runtime2.go index 32ad34ccdf..f95e11bec4 100644 --- a/src/runtime/runtime2.go +++ b/src/runtime/runtime2.go @@ -546,6 +546,7 @@ type m struct { newSigstack bool // minit on C thread called sigaltstack printlock int8 incgo bool // m is executing a cgo call + isextra bool // m is an extra m freeWait uint32 // if == 0, safe to free g0 and delete m (atomic) fastrand uint64 needextram bool diff --git a/src/runtime/testdata/testprogcgo/issue29707.go b/src/runtime/testdata/testprogcgo/issue29707.go new file mode 100644 index 0000000000..5a354301ae --- /dev/null +++ b/src/runtime/testdata/testprogcgo/issue29707.go @@ -0,0 +1,58 @@ +// Copyright 2011 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +//go:build !plan9 && !windows +// +build !plan9,!windows + +// This is for issue #29707 + +package main + +/* +#include + +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 ( + "bytes" + "fmt" + traceparser "internal/trace" + "runtime/trace" + "time" + "unsafe" +) + +func init() { + register("CgoTraceParser", CgoTraceParser) +} + +//export callback +func callback(unsafe.Pointer) unsafe.Pointer { + time.Sleep(time.Millisecond) + return nil +} + +func CgoTraceParser() { + buf := new(bytes.Buffer) + + trace.Start(buf) + C.testCallback(C.cb(C.callback)) + trace.Stop() + + _, err := traceparser.Parse(buf, "") + if err != nil { + fmt.Println("Parse error: ", err) + } else { + fmt.Println("OK") + } +} diff --git a/src/runtime/trace.go b/src/runtime/trace.go index 1b5e9df38b..d0921eeaa8 100644 --- a/src/runtime/trace.go +++ b/src/runtime/trace.go @@ -272,6 +272,17 @@ func StartTrace() error { if status == _Gsyscall { gp.traceseq++ traceEvent(traceEvGoInSyscall, -1, gp.goid) + } else if status == _Gdead && gp.m != nil && gp.m.isextra { + // trigger two trace events for the dead g in the extra m, + // since the next event of the g will be traceEvGoSysExit in exitsyscall, + // while calling from C thread to Go. + gp.traceseq = 0 + gp.tracelastp = getg().m.p + // +PCQuantum because traceFrameForPC expects return PCs and subtracts PCQuantum. + id := trace.stackTab.put([]uintptr{startPCforTrace(0) + sys.PCQuantum}) // no start pc + traceEvent(traceEvGoCreate, -1, gp.goid, uint64(id), stackID) + gp.traceseq++ + traceEvent(traceEvGoInSyscall, -1, gp.goid) } else { gp.sysblocktraced = false } @@ -1555,7 +1566,7 @@ func trace_userLog(id uint64, category, message string) { func startPCforTrace(pc uintptr) uintptr { f := findfunc(pc) if !f.valid() { - return pc // should not happen, but don't care + return pc // may happen for locked g in extra M since its pc is 0. } w := funcdata(f, _FUNCDATA_WrapInfo) if w == nil { -- 2.48.1