trace_test.go

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