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>

1 files changed, 97 insertions, 0 deletions

diff --git a/src/cmd/trace/trace_unix_test.go b/src/cmd/trace/trace_unix_test.go
new file mode 100644
index 0000000000..1c0d76fa3f
--- /dev/null
+++ b/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)
+			}
+		}
+	}
+}