summary_test.go

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