Source file src/internal/trace/summary_test.go

Documentation: internal/trace

     1  // Copyright 2023 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  package trace_test
     6  
     7  import (
     8  	"internal/trace"
     9  	"internal/trace/testtrace"
    10  	"io"
    11  	"testing"
    12  )
    13  
    14  func TestSummarizeGoroutinesTrace(t *testing.T) {
    15  	summaries := summarizeTraceTest(t, "testdata/tests/go122-gc-stress.test").Goroutines
    16  	var (
    17  		hasSchedWaitTime    bool
    18  		hasSyncBlockTime    bool
    19  		hasGCMarkAssistTime bool
    20  	)
    21  
    22  	assertContainsGoroutine(t, summaries, "runtime.gcBgMarkWorker")
    23  	assertContainsGoroutine(t, summaries, "main.main.func1")
    24  
    25  	for _, summary := range summaries {
    26  		basicGoroutineSummaryChecks(t, summary)
    27  		hasSchedWaitTime = hasSchedWaitTime || summary.SchedWaitTime > 0
    28  		if dt, ok := summary.BlockTimeByReason["sync"]; ok && dt > 0 {
    29  			hasSyncBlockTime = true
    30  		}
    31  		if dt, ok := summary.RangeTime["GC mark assist"]; ok && dt > 0 {
    32  			hasGCMarkAssistTime = true
    33  		}
    34  	}
    35  	if !hasSchedWaitTime {
    36  		t.Error("missing sched wait time")
    37  	}
    38  	if !hasSyncBlockTime {
    39  		t.Error("missing sync block time")
    40  	}
    41  	if !hasGCMarkAssistTime {
    42  		t.Error("missing GC mark assist time")
    43  	}
    44  }
    45  
    46  func TestSummarizeGoroutinesRegionsTrace(t *testing.T) {
    47  	summaries := summarizeTraceTest(t, "testdata/tests/go122-annotations.test").Goroutines
    48  	type region struct {
    49  		startKind trace.EventKind
    50  		endKind   trace.EventKind
    51  	}
    52  	wantRegions := map[string]region{
    53  		// N.B. "pre-existing region" never even makes it into the trace.
    54  		//
    55  		// TODO(mknyszek): Add test case for end-without-a-start, which can happen at
    56  		// a generation split only.
    57  		"":                     {trace.EventStateTransition, trace.EventStateTransition}, // Task inheritance marker.
    58  		"task0 region":         {trace.EventRegionBegin, trace.EventBad},
    59  		"region0":              {trace.EventRegionBegin, trace.EventRegionEnd},
    60  		"region1":              {trace.EventRegionBegin, trace.EventRegionEnd},
    61  		"unended region":       {trace.EventRegionBegin, trace.EventStateTransition},
    62  		"post-existing region": {trace.EventRegionBegin, trace.EventBad},
    63  	}
    64  	for _, summary := range summaries {
    65  		basicGoroutineSummaryChecks(t, summary)
    66  		for _, region := range summary.Regions {
    67  			want, ok := wantRegions[region.Name]
    68  			if !ok {
    69  				continue
    70  			}
    71  			checkRegionEvents(t, want.startKind, want.endKind, summary.ID, region)
    72  			delete(wantRegions, region.Name)
    73  		}
    74  	}
    75  	if len(wantRegions) != 0 {
    76  		t.Errorf("failed to find regions: %#v", wantRegions)
    77  	}
    78  }
    79  
    80  func TestSummarizeTasksTrace(t *testing.T) {
    81  	summaries := summarizeTraceTest(t, "testdata/tests/go122-annotations-stress.test").Tasks
    82  	type task struct {
    83  		name       string
    84  		parent     *trace.TaskID
    85  		children   []trace.TaskID
    86  		logs       []trace.Log
    87  		goroutines []trace.GoID
    88  	}
    89  	parent := func(id trace.TaskID) *trace.TaskID {
    90  		p := new(trace.TaskID)
    91  		*p = id
    92  		return p
    93  	}
    94  	wantTasks := map[trace.TaskID]task{
    95  		trace.BackgroundTask: {
    96  			// The background task (0) is never any task's parent.
    97  			logs: []trace.Log{
    98  				{Task: trace.BackgroundTask, Category: "log", Message: "before do"},
    99  				{Task: trace.BackgroundTask, Category: "log", Message: "before do"},
   100  			},
   101  			goroutines: []trace.GoID{1},
   102  		},
   103  		1: {
   104  			// This started before tracing started and has no parents.
   105  			// Task 2 is technically a child, but we lost that information.
   106  			children: []trace.TaskID{3, 7, 16},
   107  			logs: []trace.Log{
   108  				{Task: 1, Category: "log", Message: "before do"},
   109  				{Task: 1, Category: "log", Message: "before do"},
   110  			},
   111  			goroutines: []trace.GoID{1},
   112  		},
   113  		2: {
   114  			// This started before tracing started and its parent is technically (1), but that information was lost.
   115  			children: []trace.TaskID{8, 17},
   116  			logs: []trace.Log{
   117  				{Task: 2, Category: "log", Message: "before do"},
   118  				{Task: 2, Category: "log", Message: "before do"},
   119  			},
   120  			goroutines: []trace.GoID{1},
   121  		},
   122  		3: {
   123  			parent:   parent(1),
   124  			children: []trace.TaskID{10, 19},
   125  			logs: []trace.Log{
   126  				{Task: 3, Category: "log", Message: "before do"},
   127  				{Task: 3, Category: "log", Message: "before do"},
   128  			},
   129  			goroutines: []trace.GoID{1},
   130  		},
   131  		4: {
   132  			// Explicitly, no parent.
   133  			children: []trace.TaskID{12, 21},
   134  			logs: []trace.Log{
   135  				{Task: 4, Category: "log", Message: "before do"},
   136  				{Task: 4, Category: "log", Message: "before do"},
   137  			},
   138  			goroutines: []trace.GoID{1},
   139  		},
   140  		12: {
   141  			parent:   parent(4),
   142  			children: []trace.TaskID{13},
   143  			logs: []trace.Log{
   144  				// TODO(mknyszek): This is computed asynchronously in the trace,
   145  				// which makes regenerating this test very annoying, since it will
   146  				// likely break this test. Resolve this by making the order not matter.
   147  				{Task: 12, Category: "log2", Message: "do"},
   148  				{Task: 12, Category: "log", Message: "fanout region4"},
   149  				{Task: 12, Category: "log", Message: "fanout region0"},
   150  				{Task: 12, Category: "log", Message: "fanout region1"},
   151  				{Task: 12, Category: "log", Message: "fanout region2"},
   152  				{Task: 12, Category: "log", Message: "before do"},
   153  				{Task: 12, Category: "log", Message: "fanout region3"},
   154  			},
   155  			goroutines: []trace.GoID{1, 5, 6, 7, 8, 9},
   156  		},
   157  		13: {
   158  			// Explicitly, no children.
   159  			parent: parent(12),
   160  			logs: []trace.Log{
   161  				{Task: 13, Category: "log2", Message: "do"},
   162  			},
   163  			goroutines: []trace.GoID{7},
   164  		},
   165  	}
   166  	for id, summary := range summaries {
   167  		want, ok := wantTasks[id]
   168  		if !ok {
   169  			continue
   170  		}
   171  		if id != summary.ID {
   172  			t.Errorf("ambiguous task %d (or %d?): field likely set incorrectly", id, summary.ID)
   173  		}
   174  
   175  		// Check parent.
   176  		if want.parent != nil {
   177  			if summary.Parent == nil {
   178  				t.Errorf("expected parent %d for task %d without a parent", *want.parent, id)
   179  			} else if summary.Parent.ID != *want.parent {
   180  				t.Errorf("bad parent for task %d: want %d, got %d", id, *want.parent, summary.Parent.ID)
   181  			}
   182  		} else if summary.Parent != nil {
   183  			t.Errorf("unexpected parent %d for task %d", summary.Parent.ID, id)
   184  		}
   185  
   186  		// Check children.
   187  		gotChildren := make(map[trace.TaskID]struct{})
   188  		for _, child := range summary.Children {
   189  			gotChildren[child.ID] = struct{}{}
   190  		}
   191  		for _, wantChild := range want.children {
   192  			if _, ok := gotChildren[wantChild]; ok {
   193  				delete(gotChildren, wantChild)
   194  			} else {
   195  				t.Errorf("expected child task %d for task %d not found", wantChild, id)
   196  			}
   197  		}
   198  		if len(gotChildren) != 0 {
   199  			for child := range gotChildren {
   200  				t.Errorf("unexpected child task %d for task %d", child, id)
   201  			}
   202  		}
   203  
   204  		// Check logs.
   205  		if len(want.logs) != len(summary.Logs) {
   206  			t.Errorf("wanted %d logs for task %d, got %d logs instead", len(want.logs), id, len(summary.Logs))
   207  		} else {
   208  			for i := range want.logs {
   209  				if want.logs[i] != summary.Logs[i].Log() {
   210  					t.Errorf("log mismatch: want %#v, got %#v", want.logs[i], summary.Logs[i].Log())
   211  				}
   212  			}
   213  		}
   214  
   215  		// Check goroutines.
   216  		if len(want.goroutines) != len(summary.Goroutines) {
   217  			t.Errorf("wanted %d goroutines for task %d, got %d goroutines instead", len(want.goroutines), id, len(summary.Goroutines))
   218  		} else {
   219  			for _, goid := range want.goroutines {
   220  				g, ok := summary.Goroutines[goid]
   221  				if !ok {
   222  					t.Errorf("want goroutine %d for task %d, not found", goid, id)
   223  					continue
   224  				}
   225  				if g.ID != goid {
   226  					t.Errorf("goroutine summary for %d does not match task %d listing of %d", g.ID, id, goid)
   227  				}
   228  			}
   229  		}
   230  
   231  		// Marked as seen.
   232  		delete(wantTasks, id)
   233  	}
   234  	if len(wantTasks) != 0 {
   235  		t.Errorf("failed to find tasks: %#v", wantTasks)
   236  	}
   237  }
   238  
   239  func assertContainsGoroutine(t *testing.T, summaries map[trace.GoID]*trace.GoroutineSummary, name string) {
   240  	for _, summary := range summaries {
   241  		if summary.Name == name {
   242  			return
   243  		}
   244  	}
   245  	t.Errorf("missing goroutine %s", name)
   246  }
   247  
   248  func basicGoroutineSummaryChecks(t *testing.T, summary *trace.GoroutineSummary) {
   249  	if summary.ID == trace.NoGoroutine {
   250  		t.Error("summary found for no goroutine")
   251  		return
   252  	}
   253  	if (summary.StartTime != 0 && summary.CreationTime > summary.StartTime) ||
   254  		(summary.StartTime != 0 && summary.EndTime != 0 && summary.StartTime > summary.EndTime) {
   255  		t.Errorf("bad summary creation/start/end times for G %d: creation=%d start=%d end=%d", summary.ID, summary.CreationTime, summary.StartTime, summary.EndTime)
   256  	}
   257  	if (summary.PC != 0 && summary.Name == "") || (summary.PC == 0 && summary.Name != "") {
   258  		t.Errorf("bad name and/or PC for G %d: pc=0x%x name=%q", summary.ID, summary.PC, summary.Name)
   259  	}
   260  	basicGoroutineExecStatsChecks(t, &summary.GoroutineExecStats)
   261  	for _, region := range summary.Regions {
   262  		basicGoroutineExecStatsChecks(t, &region.GoroutineExecStats)
   263  	}
   264  }
   265  
   266  func summarizeTraceTest(t *testing.T, testPath string) *trace.Summary {
   267  	trc, _, err := testtrace.ParseFile(testPath)
   268  	if err != nil {
   269  		t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
   270  	}
   271  	// Create the analysis state.
   272  	s := trace.NewSummarizer()
   273  
   274  	// Create a reader.
   275  	r, err := trace.NewReader(trc)
   276  	if err != nil {
   277  		t.Fatalf("failed to create trace reader for %s: %v", testPath, err)
   278  	}
   279  	// Process the trace.
   280  	for {
   281  		ev, err := r.ReadEvent()
   282  		if err == io.EOF {
   283  			break
   284  		}
   285  		if err != nil {
   286  			t.Fatalf("failed to process trace %s: %v", testPath, err)
   287  		}
   288  		s.Event(&ev)
   289  	}
   290  	return s.Finalize()
   291  }
   292  
   293  func checkRegionEvents(t *testing.T, wantStart, wantEnd trace.EventKind, goid trace.GoID, region *trace.UserRegionSummary) {
   294  	switch wantStart {
   295  	case trace.EventBad:
   296  		if region.Start != nil {
   297  			t.Errorf("expected nil region start event, got\n%s", region.Start.String())
   298  		}
   299  	case trace.EventStateTransition, trace.EventRegionBegin:
   300  		if region.Start == nil {
   301  			t.Error("expected non-nil region start event, got nil")
   302  		}
   303  		kind := region.Start.Kind()
   304  		if kind != wantStart {
   305  			t.Errorf("wanted region start event %s, got %s", wantStart, kind)
   306  		}
   307  		if kind == trace.EventRegionBegin {
   308  			if region.Start.Region().Type != region.Name {
   309  				t.Errorf("region name mismatch: event has %s, summary has %s", region.Start.Region().Type, region.Name)
   310  			}
   311  		} else {
   312  			st := region.Start.StateTransition()
   313  			if st.Resource.Kind != trace.ResourceGoroutine {
   314  				t.Errorf("found region start event for the wrong resource: %s", st.Resource)
   315  			}
   316  			if st.Resource.Goroutine() != goid {
   317  				t.Errorf("found region start event for the wrong resource: wanted goroutine %d, got %s", goid, st.Resource)
   318  			}
   319  			if old, _ := st.Goroutine(); old != trace.GoNotExist && old != trace.GoUndetermined {
   320  				t.Errorf("expected transition from GoNotExist or GoUndetermined, got transition from %s instead", old)
   321  			}
   322  		}
   323  	default:
   324  		t.Errorf("unexpected want start event type: %s", wantStart)
   325  	}
   326  
   327  	switch wantEnd {
   328  	case trace.EventBad:
   329  		if region.End != nil {
   330  			t.Errorf("expected nil region end event, got\n%s", region.End.String())
   331  		}
   332  	case trace.EventStateTransition, trace.EventRegionEnd:
   333  		if region.End == nil {
   334  			t.Error("expected non-nil region end event, got nil")
   335  		}
   336  		kind := region.End.Kind()
   337  		if kind != wantEnd {
   338  			t.Errorf("wanted region end event %s, got %s", wantEnd, kind)
   339  		}
   340  		if kind == trace.EventRegionEnd {
   341  			if region.End.Region().Type != region.Name {
   342  				t.Errorf("region name mismatch: event has %s, summary has %s", region.End.Region().Type, region.Name)
   343  			}
   344  		} else {
   345  			st := region.End.StateTransition()
   346  			if st.Resource.Kind != trace.ResourceGoroutine {
   347  				t.Errorf("found region end event for the wrong resource: %s", st.Resource)
   348  			}
   349  			if st.Resource.Goroutine() != goid {
   350  				t.Errorf("found region end event for the wrong resource: wanted goroutine %d, got %s", goid, st.Resource)
   351  			}
   352  			if _, new := st.Goroutine(); new != trace.GoNotExist {
   353  				t.Errorf("expected transition to GoNotExist, got transition to %s instead", new)
   354  			}
   355  		}
   356  	default:
   357  		t.Errorf("unexpected want end event type: %s", wantEnd)
   358  	}
   359  }
   360  
   361  func basicGoroutineExecStatsChecks(t *testing.T, stats *trace.GoroutineExecStats) {
   362  	if stats.ExecTime < 0 {
   363  		t.Error("found negative ExecTime")
   364  	}
   365  	if stats.SchedWaitTime < 0 {
   366  		t.Error("found negative SchedWaitTime")
   367  	}
   368  	if stats.SyscallTime < 0 {
   369  		t.Error("found negative SyscallTime")
   370  	}
   371  	if stats.SyscallBlockTime < 0 {
   372  		t.Error("found negative SyscallBlockTime")
   373  	}
   374  	if stats.TotalTime < 0 {
   375  		t.Error("found negative TotalTime")
   376  	}
   377  	for reason, dt := range stats.BlockTimeByReason {
   378  		if dt < 0 {
   379  			t.Errorf("found negative BlockTimeByReason for %s", reason)
   380  		}
   381  	}
   382  	for name, dt := range stats.RangeTime {
   383  		if dt < 0 {
   384  			t.Errorf("found negative RangeTime for range %s", name)
   385  		}
   386  	}
   387  }
   388  
   389  func TestRelatedGoroutinesV2Trace(t *testing.T) {
   390  	testPath := "testdata/tests/go122-gc-stress.test"
   391  	trc, _, err := testtrace.ParseFile(testPath)
   392  	if err != nil {
   393  		t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
   394  	}
   395  
   396  	// Create a reader.
   397  	r, err := trace.NewReader(trc)
   398  	if err != nil {
   399  		t.Fatalf("failed to create trace reader for %s: %v", testPath, err)
   400  	}
   401  
   402  	// Collect all the events.
   403  	var events []trace.Event
   404  	for {
   405  		ev, err := r.ReadEvent()
   406  		if err == io.EOF {
   407  			break
   408  		}
   409  		if err != nil {
   410  			t.Fatalf("failed to process trace %s: %v", testPath, err)
   411  		}
   412  		events = append(events, ev)
   413  	}
   414  
   415  	// Test the function.
   416  	targetg := trace.GoID(86)
   417  	got := trace.RelatedGoroutinesV2(events, targetg)
   418  	want := map[trace.GoID]struct{}{
   419  		trace.GoID(86):  struct{}{}, // N.B. Result includes target.
   420  		trace.GoID(71):  struct{}{},
   421  		trace.GoID(25):  struct{}{},
   422  		trace.GoID(122): struct{}{},
   423  	}
   424  	for goid := range got {
   425  		if _, ok := want[goid]; ok {
   426  			delete(want, goid)
   427  		} else {
   428  			t.Errorf("unexpected goroutine %d found in related goroutines for %d in test %s", goid, targetg, testPath)
   429  		}
   430  	}
   431  	if len(want) != 0 {
   432  		for goid := range want {
   433  			t.Errorf("failed to find related goroutine %d for goroutine %d in test %s", goid, targetg, testPath)
   434  		}
   435  	}
   436  }
   437  

View as plain text