]> Cypherpunks.ru repositories - gostls13.git/commitdiff
runtime/trace: add stack tests for GOMAXPROCS
authorHana Kim <hakim@google.com>
Thu, 8 Feb 2018 18:23:48 +0000 (13:23 -0500)
committerHyang-Ah Hana Kim <hyangah@gmail.com>
Tue, 13 Feb 2018 18:45:32 +0000 (18:45 +0000)
and reorganize test log messages for stack dumps
for easier debugging.

The error log will be formatted like the following:

trace_stack_test.go:282: Did not match event GoCreate with stack
 runtime/trace_test.TestTraceSymbolize  :39
 testing.tRunner  :0

Seen 30 events of the type
Offset 1890
 runtime/trace_test.TestTraceSymbolize /go/src/runtime/trace/trace_stack_test.go:30
 testing.tRunner /go/src/testing/testing.go:777
Offset 1899
 runtime/trace_test.TestTraceSymbolize /go/src/runtime/trace/trace_stack_test.go:30
 testing.tRunner /go/src/testing/testing.go:777
 ...

Change-Id: I0468de04507d6ae38ba84d99d13f7bf592e8d115
Reviewed-on: https://go-review.googlesource.com/92916
Reviewed-by: Heschi Kreinick <heschi@google.com>
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>

src/runtime/trace/trace_stack_test.go

index 274cdf7800ab3cfaf181db606784fc8d9210b2b8..0275279a6b45f37d8e83010c99141f5ffa6b23f9 100644 (file)
@@ -6,14 +6,17 @@ package trace_test
 
 import (
        "bytes"
+       "fmt"
        "internal/testenv"
        "internal/trace"
        "net"
        "os"
        "runtime"
        . "runtime/trace"
+       "strings"
        "sync"
        "testing"
+       "text/tabwriter"
        "time"
 )
 
@@ -34,28 +37,28 @@ func TestTraceSymbolize(t *testing.T) {
        // on a channel, in a select or otherwise. So we kick off goroutines
        // that need to block first in the hope that while we are executing
        // the rest of the test, they will block.
-       go func() {
+       go func() { // func1
                select {}
        }()
-       go func() {
+       go func() { // func2
                var c chan int
                c <- 0
        }()
-       go func() {
+       go func() { // func3
                var c chan int
                <-c
        }()
        done1 := make(chan bool)
-       go func() {
+       go func() { // func4
                <-done1
        }()
        done2 := make(chan bool)
-       go func() {
+       go func() { // func5
                done2 <- true
        }()
        c1 := make(chan int)
        c2 := make(chan int)
-       go func() {
+       go func() { // func6
                select {
                case <-c1:
                case <-c2:
@@ -63,17 +66,17 @@ func TestTraceSymbolize(t *testing.T) {
        }()
        var mu sync.Mutex
        mu.Lock()
-       go func() {
+       go func() { // func7
                mu.Lock()
                mu.Unlock()
        }()
        var wg sync.WaitGroup
        wg.Add(1)
-       go func() {
+       go func() { // func8
                wg.Wait()
        }()
        cv := sync.NewCond(&sync.Mutex{})
-       go func() {
+       go func() { // func9
                cv.L.Lock()
                cv.Wait()
                cv.L.Unlock()
@@ -82,7 +85,7 @@ func TestTraceSymbolize(t *testing.T) {
        if err != nil {
                t.Fatalf("failed to listen: %v", err)
        }
-       go func() {
+       go func() { // func10
                c, err := ln.Accept()
                if err != nil {
                        t.Errorf("failed to accept: %v", err)
@@ -97,7 +100,7 @@ func TestTraceSymbolize(t *testing.T) {
        defer rp.Close()
        defer wp.Close()
        pipeReadDone := make(chan bool)
-       go func() {
+       go func() { // func11
                var data [1]byte
                rp.Read(data[:])
                pipeReadDone <- true
@@ -125,14 +128,15 @@ func TestTraceSymbolize(t *testing.T) {
        wp.Write(data[:])
        <-pipeReadDone
 
+       oldGoMaxProcs := runtime.GOMAXPROCS(1)
+
        Stop()
+
+       runtime.GOMAXPROCS(oldGoMaxProcs)
+
        events, _ := parseTrace(t, buf)
 
        // Now check that the stacks are correct.
-       type frame struct {
-               Fn   string
-               Line int
-       }
        type eventDesc struct {
                Type byte
                Stk  []frame
@@ -140,90 +144,96 @@ func TestTraceSymbolize(t *testing.T) {
        want := []eventDesc{
                {trace.EvGCStart, []frame{
                        {"runtime.GC", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 107},
+                       {"runtime/trace_test.TestTraceSymbolize", 0},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoStart, []frame{
-                       {"runtime/trace_test.TestTraceSymbolize.func1", 37},
+                       {"runtime/trace_test.TestTraceSymbolize.func1", 0},
                }},
                {trace.EvGoSched, []frame{
-                       {"runtime/trace_test.TestTraceSymbolize", 108},
+                       {"runtime/trace_test.TestTraceSymbolize", 111},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoCreate, []frame{
-                       {"runtime/trace_test.TestTraceSymbolize", 37},
+                       {"runtime/trace_test.TestTraceSymbolize", 40},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoStop, []frame{
                        {"runtime.block", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func1", 38},
+                       {"runtime/trace_test.TestTraceSymbolize.func1", 0},
                }},
                {trace.EvGoStop, []frame{
                        {"runtime.chansend1", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func2", 42},
+                       {"runtime/trace_test.TestTraceSymbolize.func2", 0},
                }},
                {trace.EvGoStop, []frame{
                        {"runtime.chanrecv1", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func3", 46},
+                       {"runtime/trace_test.TestTraceSymbolize.func3", 0},
                }},
                {trace.EvGoBlockRecv, []frame{
                        {"runtime.chanrecv1", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func4", 50},
+                       {"runtime/trace_test.TestTraceSymbolize.func4", 0},
                }},
                {trace.EvGoUnblock, []frame{
                        {"runtime.chansend1", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 110},
+                       {"runtime/trace_test.TestTraceSymbolize", 113},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoBlockSend, []frame{
                        {"runtime.chansend1", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func5", 54},
+                       {"runtime/trace_test.TestTraceSymbolize.func5", 0},
                }},
                {trace.EvGoUnblock, []frame{
                        {"runtime.chanrecv1", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 111},
+                       {"runtime/trace_test.TestTraceSymbolize", 114},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoBlockSelect, []frame{
                        {"runtime.selectgo", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func6", 59},
+                       {"runtime/trace_test.TestTraceSymbolize.func6", 0},
                }},
                {trace.EvGoUnblock, []frame{
                        {"runtime.selectgo", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 112},
+                       {"runtime/trace_test.TestTraceSymbolize", 115},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoBlockSync, []frame{
                        {"sync.(*Mutex).Lock", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func7", 67},
+                       {"runtime/trace_test.TestTraceSymbolize.func7", 0},
                }},
                {trace.EvGoUnblock, []frame{
                        {"sync.(*Mutex).Unlock", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 116},
+                       {"runtime/trace_test.TestTraceSymbolize", 0},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoBlockSync, []frame{
                        {"sync.(*WaitGroup).Wait", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func8", 73},
+                       {"runtime/trace_test.TestTraceSymbolize.func8", 0},
                }},
                {trace.EvGoUnblock, []frame{
                        {"sync.(*WaitGroup).Add", 0},
                        {"sync.(*WaitGroup).Done", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 117},
+                       {"runtime/trace_test.TestTraceSymbolize", 120},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoBlockCond, []frame{
                        {"sync.(*Cond).Wait", 0},
-                       {"runtime/trace_test.TestTraceSymbolize.func9", 78},
+                       {"runtime/trace_test.TestTraceSymbolize.func9", 0},
                }},
                {trace.EvGoUnblock, []frame{
                        {"sync.(*Cond).Signal", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 118},
+                       {"runtime/trace_test.TestTraceSymbolize", 0},
                        {"testing.tRunner", 0},
                }},
                {trace.EvGoSleep, []frame{
                        {"time.Sleep", 0},
-                       {"runtime/trace_test.TestTraceSymbolize", 109},
+                       {"runtime/trace_test.TestTraceSymbolize", 0},
+                       {"testing.tRunner", 0},
+               }},
+               {trace.EvGomaxprocs, []frame{
+                       {"runtime.startTheWorld", 0}, // this is when the current gomaxprocs is logged.
+                       {"runtime.GOMAXPROCS", 0},
+                       {"runtime/trace_test.TestTraceSymbolize", 0},
                        {"testing.tRunner", 0},
                }},
        }
@@ -235,7 +245,7 @@ func TestTraceSymbolize(t *testing.T) {
                                {"net.(*netFD).accept", 0},
                                {"net.(*TCPListener).accept", 0},
                                {"net.(*TCPListener).Accept", 0},
-                               {"runtime/trace_test.TestTraceSymbolize.func10", 86},
+                               {"runtime/trace_test.TestTraceSymbolize.func10", 0},
                        }},
                        {trace.EvGoSysCall, []frame{
                                {"syscall.read", 0},
@@ -243,7 +253,7 @@ func TestTraceSymbolize(t *testing.T) {
                                {"internal/poll.(*FD).Read", 0},
                                {"os.(*File).read", 0},
                                {"os.(*File).Read", 0},
-                               {"runtime/trace_test.TestTraceSymbolize.func11", 102},
+                               {"runtime/trace_test.TestTraceSymbolize.func11", 0},
                        }},
                }...)
        }
@@ -264,22 +274,50 @@ func TestTraceSymbolize(t *testing.T) {
                        matched[i] = true
                }
        }
-       for i, m := range matched {
-               if m {
+       for i, w := range want {
+               if matched[i] {
                        continue
                }
-               w := want[i]
-               t.Errorf("did not match event %v at %v:%v", trace.EventDescriptions[w.Type].Name, w.Stk[0].Fn, w.Stk[0].Line)
-               t.Errorf("seen the following events of this type:")
-               for _, ev := range events {
-                       if ev.Type != w.Type {
-                               continue
-                       }
-                       for _, f := range ev.Stk {
-                               t.Logf("  %v :: %s:%v", f.Fn, f.File, f.Line)
+               seen, n := dumpEventStacks(w.Type, events)
+               t.Errorf("Did not match event %v with stack\n%s\nSeen %d events of the type\n%s",
+                       trace.EventDescriptions[w.Type].Name, dumpFrames(w.Stk), n, seen)
+       }
+}
+
+func dumpEventStacks(typ byte, events []*trace.Event) ([]byte, int) {
+       matched := 0
+       o := new(bytes.Buffer)
+       tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
+       for _, ev := range events {
+               if ev.Type != typ {
+                       continue
+               }
+               matched++
+               fmt.Fprintf(tw, "Offset %d\n", ev.Off)
+               for _, f := range ev.Stk {
+                       fname := f.File
+                       if idx := strings.Index(fname, "/go/src/"); idx > 0 {
+                               fname = fname[idx:]
                        }
-                       t.Logf("---")
+                       fmt.Fprintf(tw, "  %v\t%s:%d\n", f.Fn, fname, f.Line)
                }
-               t.Logf("======")
        }
+       tw.Flush()
+       return o.Bytes(), matched
+}
+
+type frame struct {
+       Fn   string
+       Line int
+}
+
+func dumpFrames(frames []frame) []byte {
+       o := new(bytes.Buffer)
+       tw := tabwriter.NewWriter(o, 0, 8, 0, '\t', 0)
+
+       for _, f := range frames {
+               fmt.Fprintf(tw, "  %v\t :%d\n", f.Fn, f.Line)
+       }
+       tw.Flush()
+       return o.Bytes()
 }