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 <mpratt@google.com>
Reviewed-by: Michael Knyszek <mknyszek@google.com>
Auto-Submit: Michael Pratt <mpratt@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Michael Pratt <mpratt@google.com>

diff --git a/src/internal/trace/goroutines.go b/src/internal/trace/goroutines.go
index 5da90e0b6d83487c0d2bed337e80bd8855df345e..8df5e6c6c5eb405d5b9084d08cf00904fee25c41 100644 (file)
--- 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 5e5871229729ef1de41a44853668a7d7cf684d4e..d5df27cb113043756fb03203854cd5dd1c4777d3 100644 (file)
--- 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 a112c1b80c7b648540685db37eed05706e310dc7..9a7bd941db0fb70559310832642dc8ba3c53963d 100644 (file)
--- 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 32ad34ccdf1dc9d0bc3bb634789f90a10f5295d2..f95e11bec4fcca8840e3bf1c9f3214319d5612c9 100644 (file)
--- 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 (file)
index 0000000..5a35430
--- /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 <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 (
+       "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 1b5e9df38b78c9f6d7faaf3df6255c8dd144b24a..d0921eeaa8d973d1804c096304945cfcc8d4d765 100644 (file)
--- 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 {