Black Lives Matter. Support the Equal Justice Initiative.

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

View as plain text