cmd/trace: init goroutine info entries with GoCreate event

golang.org/cl/81315 attempted to distinguish system goroutines
by examining the function name in the goroutine stack. It assumes that
the information would be available when GoSysBlock or GoInSyscall
events are processed, but it turned out the stack information is
set too late (when the goroutine gets a chance to run).

This change initializes the goroutine information entry when
processing GoCreate event which should be one of the very first
events for the every goroutine in trace.

Fixes #22574

Change-Id: I1ed37087ce2e78ed27c9b419b7d942eb4140cc69
Reviewed-on: https://go-review.googlesource.com/83595
Reviewed-by: Austin Clements <austin@google.com>
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>

src/cmd/trace/main.go

@@ -106,19 +106,19 @@ func main() {
 	}
 
 	log.Print("Parsing trace...")
-	events, err := parseEvents()
+	res, err := parseTrace()
 	if err != nil {
 		dief("%v\n", err)
 	}
 
 	if *debugFlag {
-		trace.Print(events)
+		trace.Print(res.Events)
 		os.Exit(0)
 	}
 
 	log.Print("Serializing trace...")
 	params := &traceParams{
-		events:  events,
+		parsed:  res,
 		endTime: int64(1<<63 - 1),
 	}
 	data, err := generateTrace(params)
@@ -142,12 +142,22 @@ func main() {
 var ranges []Range
 
 var loader struct {
-	once   sync.Once
-	events []*trace.Event
-	err    error
+	once sync.Once
+	res  trace.ParseResult
+	err  error
 }
 
+// parseEvents is a compatibility wrapper that returns only
+// the Events part of trace.ParseResult returned by parseTrace.
 func parseEvents() ([]*trace.Event, error) {
+	res, err := parseTrace()
+	if err != nil {
+		return nil, err
+	}
+	return res.Events, err
+}
+
+func parseTrace() (trace.ParseResult, error) {
 	loader.once.Do(func() {
 		tracef, err := os.Open(traceFile)
 		if err != nil {
@@ -157,14 +167,14 @@ func parseEvents() ([]*trace.Event, error) {
 		defer tracef.Close()
 
 		// Parse and symbolize.
-		events, err := trace.Parse(bufio.NewReader(tracef), programBinary)
+		res, err := trace.Parse(bufio.NewReader(tracef), programBinary)
 		if err != nil {
 			loader.err = fmt.Errorf("failed to parse trace: %v", err)
 			return
 		}
-		loader.events = events
+		loader.res = res
 	})
-	return loader.events, loader.err
+	return loader.res, loader.err
 }
 
 // httpMain serves the starting page.

src/cmd/trace/trace.go

@@ -25,7 +25,7 @@ func init() {
 
 // httpTrace serves either whole trace (goid==0) or trace for goid goroutine.
 func httpTrace(w http.ResponseWriter, r *http.Request) {
-	_, err := parseEvents()
+	_, err := parseTrace()
 	if err != nil {
 		http.Error(w, err.Error(), http.StatusInternalServerError)
 		return
@@ -153,14 +153,14 @@ func httpTraceViewerHTML(w http.ResponseWriter, r *http.Request) {
 // httpJsonTrace serves json trace, requested from within templTrace HTML.
 func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
 	// This is an AJAX handler, so instead of http.Error we use log.Printf to log errors.
-	events, err := parseEvents()
+	res, err := parseTrace()
 	if err != nil {
 		log.Printf("failed to parse trace: %v", err)
 		return
 	}
 
 	params := &traceParams{
-		events:  events,
+		parsed:  res,
 		endTime: int64(1<<63 - 1),
 	}
 
@@ -171,13 +171,13 @@ func httpJsonTrace(w http.ResponseWriter, r *http.Request) {
 			log.Printf("failed to parse goid parameter '%v': %v", goids, err)
 			return
 		}
-		analyzeGoroutines(events)
+		analyzeGoroutines(res.Events)
 		g := gs[goid]
 		params.gtrace = true
 		params.startTime = g.StartTime
 		params.endTime = g.EndTime
 		params.maing = goid
-		params.gs = trace.RelatedGoroutines(events, goid)
+		params.gs = trace.RelatedGoroutines(res.Events, goid)
 	}
 
 	data, err := generateTrace(params)
@@ -260,7 +260,7 @@ func (cw *countingWriter) Write(data []byte) (int, error) {
 }
 
 type traceParams struct {
-	events    []*trace.Event
+	parsed    trace.ParseResult
 	gtrace    bool
 	startTime int64
 	endTime   int64
@@ -367,6 +367,7 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 	ctx.data.TimeUnit = "ns"
 	maxProc := 0
 	ginfos := make(map[uint64]*gInfo)
+	stacks := params.parsed.Stacks
 
 	getGInfo := func(g uint64) *gInfo {
 		info, ok := ginfos[g]
@@ -394,29 +395,35 @@ func generateTrace(params *traceParams) (ViewerData, error) {
 		info.state = newState
 	}
 
-	for _, ev := range ctx.events {
+	for _, ev := range ctx.parsed.Events {
 		// Handle state transitions before we filter out events.
 		switch ev.Type {
 		case trace.EvGoStart, trace.EvGoStartLabel:
 			setGState(ev, ev.G, gRunnable, gRunning)
 			info := getGInfo(ev.G)
-			if info.name == "" {
-				if len(ev.Stk) == 0 {
-					info.name = fmt.Sprintf("G%v", ev.G)
-				} else {
-					fname := ev.Stk[0].Fn
-					info.name = fmt.Sprintf("G%v %s", ev.G, fname)
-					info.isSystemG = strings.HasPrefix(fname, "runtime.") && fname != "runtime.main"
-				}
-			}
 			info.start = ev
 		case trace.EvProcStart:
 			ctx.threadStats.prunning++
 		case trace.EvProcStop:
 			ctx.threadStats.prunning--
 		case trace.EvGoCreate:
+			newG := ev.Args[0]
+			info := getGInfo(newG)
+			if info.name != "" {
+				return ctx.data, fmt.Errorf("duplicate go create event for go id=%d detected at offset %d", newG, ev.Off)
+			}
+
+			stk, ok := stacks[ev.Args[1]]
+			if !ok || len(stk) == 0 {
+				return ctx.data, fmt.Errorf("invalid go create event: missing stack information for go id=%d at offset %d", newG, ev.Off)
+			}
+
+			fname := stk[0].Fn
+			info.name = fmt.Sprintf("G%v %s", newG, fname)
+			info.isSystemG = strings.HasPrefix(fname, "runtime.") && fname != "runtime.main"
+
 			ctx.gcount++
-			setGState(ev, ev.Args[0], gDead, gRunnable)
+			setGState(ev, newG, gDead, gRunnable)
 		case trace.EvGoEnd:
 			ctx.gcount--
 			setGState(ev, ev.G, gRunning, gDead)

src/cmd/trace/trace_test.go

@@ -1,3 +1,7 @@
+// Copyright 2016 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.
+
 package main
 
 import (
@@ -6,6 +10,21 @@ import (
 	"testing"
 )
 
+// stacks is a fake stack map populated for test.
+type stacks map[uint64][]*trace.Frame
+
+// add adds a stack with a single frame whose Fn field is
+// set to the provided fname and returns a unique stack id.
+func (s *stacks) add(fname string) uint64 {
+	if *s == nil {
+		*s = make(map[uint64][]*trace.Frame)
+	}
+
+	id := uint64(len(*s))
+	(*s)[id] = []*trace.Frame{{Fn: fname}}
+	return id
+}
+
 // TestGoroutineCount tests runnable/running goroutine counts computed by generateTrace
 // remain in the valid range.
 //   - the counts must not be negative. generateTrace will return an error.
@@ -15,34 +34,37 @@ func TestGoroutineCount(t *testing.T) {
 	w.Emit(trace.EvBatch, 0, 0)  // start of per-P batch event [pid, timestamp]
 	w.Emit(trace.EvFrequency, 1) // [ticks per second]
 
+	var s stacks
+
 	// In this test, we assume a valid trace contains EvGoWaiting or EvGoInSyscall
 	// event for every blocked goroutine.
 
 	// goroutine 10: blocked
-	w.Emit(trace.EvGoCreate, 1, 10, 1, 1) // [timestamp, new goroutine id, new stack id, stack id]
-	w.Emit(trace.EvGoWaiting, 1, 10)      // [timestamp, goroutine id]
+	w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
+	w.Emit(trace.EvGoWaiting, 1, 10)                                   // [timestamp, goroutine id]
 
 	// goroutine 20: in syscall
-	w.Emit(trace.EvGoCreate, 1, 20, 2, 1)
+	w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
 	w.Emit(trace.EvGoInSyscall, 1, 20) // [timestamp, goroutine id]
 
 	// goroutine 30: runnable
-	w.Emit(trace.EvGoCreate, 1, 30, 5, 1)
+	w.Emit(trace.EvGoCreate, 1, 30, s.add("pkg.f3"), s.add("main.f3"))
 
 	w.Emit(trace.EvProcStart, 2, 0) // [timestamp, thread id]
 
 	// goroutine 40: runnable->running->runnable
-	w.Emit(trace.EvGoCreate, 1, 40, 7, 1)
-	w.Emit(trace.EvGoStartLocal, 1, 40) // [timestamp, goroutine id]
-	w.Emit(trace.EvGoSched, 1, 8)       // [timestamp, stack]
+	w.Emit(trace.EvGoCreate, 1, 40, s.add("pkg.f4"), s.add("main.f4"))
+	w.Emit(trace.EvGoStartLocal, 1, 40)          // [timestamp, goroutine id]
+	w.Emit(trace.EvGoSched, 1, s.add("main.f4")) // [timestamp, stack]
 
-	events, err := trace.Parse(w, "")
+	res, err := trace.Parse(w, "")
 	if err != nil {
 		t.Fatalf("failed to parse test trace: %v", err)
 	}
+	res.Stacks = s // use fake stacks.
 
 	params := &traceParams{
-		events:  events,
+		parsed:  res,
 		endTime: int64(1<<63 - 1),
 	}
 
@@ -66,31 +88,34 @@ func TestGoroutineFilter(t *testing.T) {
 	// Test that we handle state changes to selected goroutines
 	// caused by events on goroutines that are not selected.
 
+	var s stacks
+
 	w := trace.NewWriter()
 	w.Emit(trace.EvBatch, 0, 0)  // start of per-P batch event [pid, timestamp]
 	w.Emit(trace.EvFrequency, 1) // [ticks per second]
 
 	// goroutine 10: blocked
-	w.Emit(trace.EvGoCreate, 1, 10, 1, 1) // [timestamp, new goroutine id, new stack id, stack id]
-	w.Emit(trace.EvGoWaiting, 1, 10)      // [timestamp, goroutine id]
+	w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
+	w.Emit(trace.EvGoWaiting, 1, 10)                                   // [timestamp, goroutine id]
 
 	// goroutine 20: runnable->running->unblock 10
-	w.Emit(trace.EvGoCreate, 1, 20, 7, 1)
-	w.Emit(trace.EvGoStartLocal, 1, 20)      // [timestamp, goroutine id]
-	w.Emit(trace.EvGoUnblockLocal, 1, 10, 8) // [timestamp, goroutine id, stack]
-	w.Emit(trace.EvGoEnd, 1)                 // [timestamp]
+	w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
+	w.Emit(trace.EvGoStartLocal, 1, 20)                    // [timestamp, goroutine id]
+	w.Emit(trace.EvGoUnblockLocal, 1, 10, s.add("pkg.f2")) // [timestamp, goroutine id, stack]
+	w.Emit(trace.EvGoEnd, 1)                               // [timestamp]
 
 	// goroutine 10: runnable->running->block
-	w.Emit(trace.EvGoStartLocal, 1, 10) // [timestamp, goroutine id]
-	w.Emit(trace.EvGoBlock, 1, 9)       // [timestamp, stack]
+	w.Emit(trace.EvGoStartLocal, 1, 10)         // [timestamp, goroutine id]
+	w.Emit(trace.EvGoBlock, 1, s.add("pkg.f3")) // [timestamp, stack]
 
-	events, err := trace.Parse(w, "")
+	res, err := trace.Parse(w, "")
 	if err != nil {
 		t.Fatalf("failed to parse test trace: %v", err)
 	}
+	res.Stacks = s // use fake stacks
 
 	params := &traceParams{
-		events:  events,
+		parsed:  res,
 		endTime: int64(1<<63 - 1),
 		gs:      map[uint64]bool{10: true},
 	}
@@ -106,22 +131,24 @@ func TestPreemptedMarkAssist(t *testing.T) {
 	w.Emit(trace.EvBatch, 0, 0)  // start of per-P batch event [pid, timestamp]
 	w.Emit(trace.EvFrequency, 1) // [ticks per second]
 
+	var s stacks
 	// goroutine 9999: running -> mark assisting -> preempted -> assisting -> running -> block
-	w.Emit(trace.EvGoCreate, 1, 9999, 1, 1) // [timestamp, new goroutine id, new stack id, stack id]
-	w.Emit(trace.EvGoStartLocal, 1, 9999)   // [timestamp, goroutine id]
-	w.Emit(trace.EvGCMarkAssistStart, 1, 2) // [timestamp, stack]
-	w.Emit(trace.EvGoPreempt, 1, 3)         // [timestamp, stack]
-	w.Emit(trace.EvGoStartLocal, 1, 9999)   // [timestamp, goroutine id]
-	w.Emit(trace.EvGCMarkAssistDone, 1)     // [timestamp]
-	w.Emit(trace.EvGoBlock, 1, 4)           // [timestamp, stack]
+	w.Emit(trace.EvGoCreate, 1, 9999, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
+	w.Emit(trace.EvGoStartLocal, 1, 9999)                                // [timestamp, goroutine id]
+	w.Emit(trace.EvGCMarkAssistStart, 1, s.add("main.f1"))               // [timestamp, stack]
+	w.Emit(trace.EvGoPreempt, 1, s.add("main.f1"))                       // [timestamp, stack]
+	w.Emit(trace.EvGoStartLocal, 1, 9999)                                // [timestamp, goroutine id]
+	w.Emit(trace.EvGCMarkAssistDone, 1)                                  // [timestamp]
+	w.Emit(trace.EvGoBlock, 1, s.add("main.f2"))                         // [timestamp, stack]
 
-	events, err := trace.Parse(w, "")
+	res, err := trace.Parse(w, "")
 	if err != nil {
 		t.Fatalf("failed to parse test trace: %v", err)
 	}
+	res.Stacks = s // use fake stacks
 
 	params := &traceParams{
-		events:  events,
+		parsed:  res,
 		endTime: int64(1<<63 - 1),
 	}
 

src/cmd/trace/trace_unix_test.go

@@ -0,0 +1,97 @@
+// Copyright 2017 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.
+
+// +build darwin dragonfly freebsd linux netbsd openbsd solaris
+
+package main
+
+import (
+	"bytes"
+	"internal/trace"
+	"runtime"
+	rtrace "runtime/trace"
+	"sync"
+	"syscall"
+	"testing"
+	"time"
+)
+
+// TestGoroutineInSyscall tests threads for timer goroutines
+// that preexisted when the tracing started were not counted
+// as threads in syscall. See golang.org/issues/22574.
+func TestGoroutineInSyscall(t *testing.T) {
+	// Start one goroutine blocked in syscall.
+	//
+	// TODO: syscall.Pipe used to cause the goroutine to
+	// remain blocked in syscall is not portable. Replace
+	// it with a more portable way so this test can run
+	// on non-unix architecture e.g. Windows.
+	var p [2]int
+	if err := syscall.Pipe(p[:]); err != nil {
+		t.Fatalf("failed to create pipe: %v", err)
+	}
+
+	var wg sync.WaitGroup
+	defer func() {
+		syscall.Write(p[1], []byte("a"))
+		wg.Wait()
+
+		syscall.Close(p[0])
+		syscall.Close(p[1])
+	}()
+	wg.Add(1)
+	go func() {
+		var tmp [1]byte
+		syscall.Read(p[0], tmp[:])
+		wg.Done()
+	}()
+
+	// Start multiple timer goroutines.
+	allTimers := make([]*time.Timer, 2*runtime.GOMAXPROCS(0))
+	defer func() {
+		for _, timer := range allTimers {
+			timer.Stop()
+		}
+	}()
+
+	var timerSetup sync.WaitGroup
+	for i := range allTimers {
+		timerSetup.Add(1)
+		go func(i int) {
+			defer timerSetup.Done()
+			allTimers[i] = time.AfterFunc(time.Hour, nil)
+		}(i)
+	}
+	timerSetup.Wait()
+
+	// Collect and parse trace.
+	buf := new(bytes.Buffer)
+	if err := rtrace.Start(buf); err != nil {
+		t.Fatalf("failed to start tracing: %v", err)
+	}
+	rtrace.Stop()
+
+	res, err := trace.Parse(buf, "")
+	if err != nil {
+		t.Fatalf("failed to parse trace: %v", err)
+	}
+
+	// Check only one thread for the pipe read goroutine is
+	// considered in-syscall.
+	viewerData, err := generateTrace(&traceParams{
+		parsed:  res,
+		endTime: int64(1<<63 - 1),
+	})
+	if err != nil {
+		t.Fatalf("failed to generate ViewerData: %v", err)
+	}
+	for _, ev := range viewerData.Events {
+		if ev.Name == "Threads" {
+			arg := ev.Arg.(*threadCountersArg)
+			if arg.InSyscall > 1 {
+				t.Errorf("%d threads in syscall at time %v; want less than 1 thread in syscall", arg.InSyscall, ev.Time)
+			}
+		}
+	}
+}

src/internal/trace/parser.go

@@ -75,36 +75,44 @@ const (
 	GCP      // depicts GC state
 )
 
+// ParseResult is the result of Parse.
+type ParseResult struct {
+	// Events is the sorted list of Events in the trace.
+	Events []*Event
+	// Stacks is the stack traces keyed by stack IDs from the trace.
+	Stacks map[uint64][]*Frame
+}
+
 // Parse parses, post-processes and verifies the trace.
-func Parse(r io.Reader, bin string) ([]*Event, error) {
-	ver, events, err := parse(r, bin)
+func Parse(r io.Reader, bin string) (ParseResult, error) {
+	ver, res, err := parse(r, bin)
 	if err != nil {
-		return nil, err
+		return ParseResult{}, err
 	}
 	if ver < 1007 && bin == "" {
-		return nil, fmt.Errorf("for traces produced by go 1.6 or below, the binary argument must be provided")
+		return ParseResult{}, fmt.Errorf("for traces produced by go 1.6 or below, the binary argument must be provided")
 	}
-	return events, nil
+	return res, nil
 }
 
 // parse parses, post-processes and verifies the trace. It returns the
 // trace version and the list of events.
-func parse(r io.Reader, bin string) (int, []*Event, error) {
+func parse(r io.Reader, bin string) (int, ParseResult, error) {
 	ver, rawEvents, strings, err := readTrace(r)
 	if err != nil {
-		return 0, nil, err
+		return 0, ParseResult{}, err
 	}
 	events, stacks, err := parseEvents(ver, rawEvents, strings)
 	if err != nil {
-		return 0, nil, err
+		return 0, ParseResult{}, err
 	}
 	events, err = removeFutile(events)
 	if err != nil {
-		return 0, nil, err
+		return 0, ParseResult{}, err
 	}
 	err = postProcessTrace(ver, events)
 	if err != nil {
-		return 0, nil, err
+		return 0, ParseResult{}, err
 	}
 	// Attach stack traces.
 	for _, ev := range events {
@@ -114,10 +122,10 @@ func parse(r io.Reader, bin string) (int, []*Event, error) {
 	}
 	if ver < 1007 && bin != "" {
 		if err := symbolize(events, bin); err != nil {
-			return 0, nil, err
+			return 0, ParseResult{}, err
 		}
 	}
-	return ver, events, nil
+	return ver, ParseResult{Events: events, Stacks: stacks}, nil
 }
 
 // rawEvent is a helper type used during parsing.

src/internal/trace/parser_test.go

@@ -25,8 +25,8 @@ func TestCorruptedInputs(t *testing.T) {
 		"go 1.5 trace\x00\x00\x00\x00\xc3\x0200",
 	}
 	for _, data := range tests {
-		events, err := Parse(strings.NewReader(data), "")
-		if err == nil || events != nil {
+		res, err := Parse(strings.NewReader(data), "")
+		if err == nil || res.Events != nil || res.Stacks != nil {
 			t.Fatalf("no error on input: %q", data)
 		}
 	}

src/runtime/trace/trace_test.go

@@ -127,20 +127,20 @@ func TestTrace(t *testing.T) {
 }
 
 func parseTrace(t *testing.T, r io.Reader) ([]*trace.Event, map[uint64]*trace.GDesc) {
-	events, err := trace.Parse(r, "")
+	res, err := trace.Parse(r, "")
 	if err == trace.ErrTimeOrder {
 		t.Skipf("skipping trace: %v", err)
 	}
 	if err != nil {
 		t.Fatalf("failed to parse trace: %v", err)
 	}
-	gs := trace.GoroutineStats(events)
+	gs := trace.GoroutineStats(res.Events)
 	for goid := range gs {
 		// We don't do any particular checks on the result at the moment.
 		// But still check that RelatedGoroutines does not crash, hang, etc.
-		_ = trace.RelatedGoroutines(events, goid)
+		_ = trace.RelatedGoroutines(res.Events, goid)
 	}
-	return events, gs
+	return res.Events, gs
 }
 
 func testBrokenTimestamps(t *testing.T, data []byte) {