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: 445de8eaf3
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>

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.")
 }

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)
+	}
+}

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)
 

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

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")
+	}
+}

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 {