...
Run Format

Source file src/cmd/trace/trace_test.go

Documentation: cmd/trace

     1  // Copyright 2016 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  // +build !js
     6  
     7  package main
     8  
     9  import (
    10  	"context"
    11  	"internal/trace"
    12  	"io/ioutil"
    13  	rtrace "runtime/trace"
    14  	"strings"
    15  	"testing"
    16  )
    17  
    18  // stacks is a fake stack map populated for test.
    19  type stacks map[uint64][]*trace.Frame
    20  
    21  // add adds a stack with a single frame whose Fn field is
    22  // set to the provided fname and returns a unique stack id.
    23  func (s *stacks) add(fname string) uint64 {
    24  	if *s == nil {
    25  		*s = make(map[uint64][]*trace.Frame)
    26  	}
    27  
    28  	id := uint64(len(*s))
    29  	(*s)[id] = []*trace.Frame{{Fn: fname}}
    30  	return id
    31  }
    32  
    33  // TestGoroutineCount tests runnable/running goroutine counts computed by generateTrace
    34  // remain in the valid range.
    35  //   - the counts must not be negative. generateTrace will return an error.
    36  //   - the counts must not include goroutines blocked waiting on channels or in syscall.
    37  func TestGoroutineCount(t *testing.T) {
    38  	w := trace.NewWriter()
    39  	w.Emit(trace.EvBatch, 0, 0)  // start of per-P batch event [pid, timestamp]
    40  	w.Emit(trace.EvFrequency, 1) // [ticks per second]
    41  
    42  	var s stacks
    43  
    44  	// In this test, we assume a valid trace contains EvGoWaiting or EvGoInSyscall
    45  	// event for every blocked goroutine.
    46  
    47  	// goroutine 10: blocked
    48  	w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
    49  	w.Emit(trace.EvGoWaiting, 1, 10)                                   // [timestamp, goroutine id]
    50  
    51  	// goroutine 20: in syscall
    52  	w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
    53  	w.Emit(trace.EvGoInSyscall, 1, 20) // [timestamp, goroutine id]
    54  
    55  	// goroutine 30: runnable
    56  	w.Emit(trace.EvGoCreate, 1, 30, s.add("pkg.f3"), s.add("main.f3"))
    57  
    58  	w.Emit(trace.EvProcStart, 2, 0) // [timestamp, thread id]
    59  
    60  	// goroutine 40: runnable->running->runnable
    61  	w.Emit(trace.EvGoCreate, 1, 40, s.add("pkg.f4"), s.add("main.f4"))
    62  	w.Emit(trace.EvGoStartLocal, 1, 40)          // [timestamp, goroutine id]
    63  	w.Emit(trace.EvGoSched, 1, s.add("main.f4")) // [timestamp, stack]
    64  
    65  	res, err := trace.Parse(w, "")
    66  	if err != nil {
    67  		t.Fatalf("failed to parse test trace: %v", err)
    68  	}
    69  	res.Stacks = s // use fake stacks.
    70  
    71  	params := &traceParams{
    72  		parsed:  res,
    73  		endTime: int64(1<<63 - 1),
    74  	}
    75  
    76  	// Use the default viewerDataTraceConsumer but replace
    77  	// consumeViewerEvent to intercept the ViewerEvents for testing.
    78  	c := viewerDataTraceConsumer(ioutil.Discard, 0, 1<<63-1)
    79  	c.consumeViewerEvent = func(ev *ViewerEvent, _ bool) {
    80  		if ev.Name == "Goroutines" {
    81  			cnt := ev.Arg.(*goroutineCountersArg)
    82  			if cnt.Runnable+cnt.Running > 2 {
    83  				t.Errorf("goroutine count=%+v; want no more than 2 goroutines in runnable/running state", cnt)
    84  			}
    85  			t.Logf("read %+v %+v", ev, cnt)
    86  		}
    87  	}
    88  
    89  	// If the counts drop below 0, generateTrace will return an error.
    90  	if err := generateTrace(params, c); err != nil {
    91  		t.Fatalf("generateTrace failed: %v", err)
    92  	}
    93  }
    94  
    95  func TestGoroutineFilter(t *testing.T) {
    96  	// Test that we handle state changes to selected goroutines
    97  	// caused by events on goroutines that are not selected.
    98  
    99  	var s stacks
   100  
   101  	w := trace.NewWriter()
   102  	w.Emit(trace.EvBatch, 0, 0)  // start of per-P batch event [pid, timestamp]
   103  	w.Emit(trace.EvFrequency, 1) // [ticks per second]
   104  
   105  	// goroutine 10: blocked
   106  	w.Emit(trace.EvGoCreate, 1, 10, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
   107  	w.Emit(trace.EvGoWaiting, 1, 10)                                   // [timestamp, goroutine id]
   108  
   109  	// goroutine 20: runnable->running->unblock 10
   110  	w.Emit(trace.EvGoCreate, 1, 20, s.add("pkg.f2"), s.add("main.f2"))
   111  	w.Emit(trace.EvGoStartLocal, 1, 20)                    // [timestamp, goroutine id]
   112  	w.Emit(trace.EvGoUnblockLocal, 1, 10, s.add("pkg.f2")) // [timestamp, goroutine id, stack]
   113  	w.Emit(trace.EvGoEnd, 1)                               // [timestamp]
   114  
   115  	// goroutine 10: runnable->running->block
   116  	w.Emit(trace.EvGoStartLocal, 1, 10)         // [timestamp, goroutine id]
   117  	w.Emit(trace.EvGoBlock, 1, s.add("pkg.f3")) // [timestamp, stack]
   118  
   119  	res, err := trace.Parse(w, "")
   120  	if err != nil {
   121  		t.Fatalf("failed to parse test trace: %v", err)
   122  	}
   123  	res.Stacks = s // use fake stacks
   124  
   125  	params := &traceParams{
   126  		parsed:  res,
   127  		endTime: int64(1<<63 - 1),
   128  		gs:      map[uint64]bool{10: true},
   129  	}
   130  
   131  	c := viewerDataTraceConsumer(ioutil.Discard, 0, 1<<63-1)
   132  	if err := generateTrace(params, c); err != nil {
   133  		t.Fatalf("generateTrace failed: %v", err)
   134  	}
   135  }
   136  
   137  func TestPreemptedMarkAssist(t *testing.T) {
   138  	w := trace.NewWriter()
   139  	w.Emit(trace.EvBatch, 0, 0)  // start of per-P batch event [pid, timestamp]
   140  	w.Emit(trace.EvFrequency, 1) // [ticks per second]
   141  
   142  	var s stacks
   143  	// goroutine 9999: running -> mark assisting -> preempted -> assisting -> running -> block
   144  	w.Emit(trace.EvGoCreate, 1, 9999, s.add("pkg.f1"), s.add("main.f1")) // [timestamp, new goroutine id, new stack id, stack id]
   145  	w.Emit(trace.EvGoStartLocal, 1, 9999)                                // [timestamp, goroutine id]
   146  	w.Emit(trace.EvGCMarkAssistStart, 1, s.add("main.f1"))               // [timestamp, stack]
   147  	w.Emit(trace.EvGoPreempt, 1, s.add("main.f1"))                       // [timestamp, stack]
   148  	w.Emit(trace.EvGoStartLocal, 1, 9999)                                // [timestamp, goroutine id]
   149  	w.Emit(trace.EvGCMarkAssistDone, 1)                                  // [timestamp]
   150  	w.Emit(trace.EvGoBlock, 1, s.add("main.f2"))                         // [timestamp, stack]
   151  
   152  	res, err := trace.Parse(w, "")
   153  	if err != nil {
   154  		t.Fatalf("failed to parse test trace: %v", err)
   155  	}
   156  	res.Stacks = s // use fake stacks
   157  
   158  	params := &traceParams{
   159  		parsed:  res,
   160  		endTime: int64(1<<63 - 1),
   161  	}
   162  
   163  	c := viewerDataTraceConsumer(ioutil.Discard, 0, 1<<63-1)
   164  
   165  	marks := 0
   166  	c.consumeViewerEvent = func(ev *ViewerEvent, _ bool) {
   167  		if strings.Contains(ev.Name, "MARK ASSIST") {
   168  			marks++
   169  		}
   170  	}
   171  	if err := generateTrace(params, c); err != nil {
   172  		t.Fatalf("generateTrace failed: %v", err)
   173  	}
   174  
   175  	if marks != 2 {
   176  		t.Errorf("Got %v MARK ASSIST events, want %v", marks, 2)
   177  	}
   178  }
   179  
   180  func TestFoo(t *testing.T) {
   181  	prog0 := func() {
   182  		ctx, task := rtrace.NewTask(context.Background(), "ohHappyDay")
   183  		rtrace.Log(ctx, "", "log before task ends")
   184  		task.End()
   185  		rtrace.Log(ctx, "", "log after task ends") // log after task ends
   186  	}
   187  	if err := traceProgram(t, prog0, "TestFoo"); err != nil {
   188  		t.Fatalf("failed to trace the program: %v", err)
   189  	}
   190  	res, err := parseTrace()
   191  	if err != nil {
   192  		t.Fatalf("failed to parse the trace: %v", err)
   193  	}
   194  	annotRes, _ := analyzeAnnotations()
   195  	var task *taskDesc
   196  	for _, t := range annotRes.tasks {
   197  		if t.name == "ohHappyDay" {
   198  			task = t
   199  			break
   200  		}
   201  	}
   202  	if task == nil {
   203  		t.Fatal("failed to locate expected task event")
   204  	}
   205  
   206  	params := &traceParams{
   207  		parsed:    res,
   208  		mode:      modeTaskOriented,
   209  		startTime: task.firstTimestamp() - 1,
   210  		endTime:   task.lastTimestamp() + 1,
   211  		tasks:     []*taskDesc{task},
   212  	}
   213  
   214  	c := viewerDataTraceConsumer(ioutil.Discard, 0, 1<<63-1)
   215  
   216  	var logBeforeTaskEnd, logAfterTaskEnd bool
   217  	c.consumeViewerEvent = func(ev *ViewerEvent, _ bool) {
   218  		if ev.Name == "log before task ends" {
   219  			logBeforeTaskEnd = true
   220  		}
   221  		if ev.Name == "log after task ends" {
   222  			logAfterTaskEnd = true
   223  		}
   224  	}
   225  	if err := generateTrace(params, c); err != nil {
   226  		t.Fatalf("generateTrace failed: %v", err)
   227  	}
   228  	if !logBeforeTaskEnd {
   229  		t.Error("failed to find 'log before task ends'")
   230  	}
   231  	if !logAfterTaskEnd {
   232  		t.Error("failed to find 'log after task ends'")
   233  	}
   234  
   235  }
   236  

View as plain text