src/internal/trace/summary_test.go

// Copyright 2023 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package trace

import (
	tracev2 "internal/trace/v2"
	"internal/trace/v2/testtrace"
	"io"
	"testing"
)

func TestSummarizeGoroutinesTrace(t *testing.T) {
	summaries := summarizeTraceTest(t, "v2/testdata/tests/go122-gc-stress.test").Goroutines
	var (
		hasSchedWaitTime    bool
		hasSyncBlockTime    bool
		hasGCMarkAssistTime bool
	)

	assertContainsGoroutine(t, summaries, "runtime.gcBgMarkWorker")
	assertContainsGoroutine(t, summaries, "main.main.func1")

	for _, summary := range summaries {
		basicGoroutineSummaryChecks(t, summary)
		hasSchedWaitTime = hasSchedWaitTime || summary.SchedWaitTime > 0
		if dt, ok := summary.BlockTimeByReason["sync"]; ok && dt > 0 {
			hasSyncBlockTime = true
		}
		if dt, ok := summary.RangeTime["GC mark assist"]; ok && dt > 0 {
			hasGCMarkAssistTime = true
		}
	}
	if !hasSchedWaitTime {
		t.Error("missing sched wait time")
	}
	if !hasSyncBlockTime {
		t.Error("missing sync block time")
	}
	if !hasGCMarkAssistTime {
		t.Error("missing GC mark assist time")
	}
}

func TestSummarizeGoroutinesRegionsTrace(t *testing.T) {
	summaries := summarizeTraceTest(t, "v2/testdata/tests/go122-annotations.test").Goroutines
	type region struct {
		startKind tracev2.EventKind
		endKind   tracev2.EventKind
	}
	wantRegions := map[string]region{
		// N.B. "pre-existing region" never even makes it into the trace.
		//
		// TODO(mknyszek): Add test case for end-without-a-start, which can happen at
		// a generation split only.
		"":                     {tracev2.EventStateTransition, tracev2.EventStateTransition}, // Task inheritance marker.
		"task0 region":         {tracev2.EventRegionBegin, tracev2.EventBad},
		"region0":              {tracev2.EventRegionBegin, tracev2.EventRegionEnd},
		"region1":              {tracev2.EventRegionBegin, tracev2.EventRegionEnd},
		"unended region":       {tracev2.EventRegionBegin, tracev2.EventStateTransition},
		"post-existing region": {tracev2.EventRegionBegin, tracev2.EventBad},
	}
	for _, summary := range summaries {
		basicGoroutineSummaryChecks(t, summary)
		for _, region := range summary.Regions {
			want, ok := wantRegions[region.Name]
			if !ok {
				continue
			}
			checkRegionEvents(t, want.startKind, want.endKind, summary.ID, region)
			delete(wantRegions, region.Name)
		}
	}
	if len(wantRegions) != 0 {
		t.Errorf("failed to find regions: %#v", wantRegions)
	}
}

func TestSummarizeTasksTrace(t *testing.T) {
	summaries := summarizeTraceTest(t, "v2/testdata/tests/go122-annotations-stress.test").Tasks
	type task struct {
		name       string
		parent     *tracev2.TaskID
		children   []tracev2.TaskID
		logs       []tracev2.Log
		goroutines []tracev2.GoID
	}
	parent := func(id tracev2.TaskID) *tracev2.TaskID {
		p := new(tracev2.TaskID)
		*p = id
		return p
	}
	wantTasks := map[tracev2.TaskID]task{
		tracev2.BackgroundTask: {
			// The background task (0) is never any task's parent.
			logs: []tracev2.Log{
				{Task: tracev2.BackgroundTask, Category: "log", Message: "before do"},
				{Task: tracev2.BackgroundTask, Category: "log", Message: "before do"},
			},
			goroutines: []tracev2.GoID{1},
		},
		1: {
			// This started before tracing started and has no parents.
			// Task 2 is technically a child, but we lost that information.
			children: []tracev2.TaskID{3, 7, 16},
			logs: []tracev2.Log{
				{Task: 1, Category: "log", Message: "before do"},
				{Task: 1, Category: "log", Message: "before do"},
			},
			goroutines: []tracev2.GoID{1},
		},
		2: {
			// This started before tracing started and its parent is technically (1), but that information was lost.
			children: []tracev2.TaskID{8, 17},
			logs: []tracev2.Log{
				{Task: 2, Category: "log", Message: "before do"},
				{Task: 2, Category: "log", Message: "before do"},
			},
			goroutines: []tracev2.GoID{1},
		},
		3: {
			parent:   parent(1),
			children: []tracev2.TaskID{10, 19},
			logs: []tracev2.Log{
				{Task: 3, Category: "log", Message: "before do"},
				{Task: 3, Category: "log", Message: "before do"},
			},
			goroutines: []tracev2.GoID{1},
		},
		4: {
			// Explicitly, no parent.
			children: []tracev2.TaskID{12, 21},
			logs: []tracev2.Log{
				{Task: 4, Category: "log", Message: "before do"},
				{Task: 4, Category: "log", Message: "before do"},
			},
			goroutines: []tracev2.GoID{1},
		},
		12: {
			parent:   parent(4),
			children: []tracev2.TaskID{13},
			logs: []tracev2.Log{
				// TODO(mknyszek): This is computed asynchronously in the trace,
				// which makes regenerating this test very annoying, since it will
				// likely break this test. Resolve this by making the order not matter.
				{Task: 12, Category: "log2", Message: "do"},
				{Task: 12, Category: "log", Message: "fanout region4"},
				{Task: 12, Category: "log", Message: "fanout region0"},
				{Task: 12, Category: "log", Message: "fanout region1"},
				{Task: 12, Category: "log", Message: "fanout region2"},
				{Task: 12, Category: "log", Message: "before do"},
				{Task: 12, Category: "log", Message: "fanout region3"},
			},
			goroutines: []tracev2.GoID{1, 5, 6, 7, 8, 9},
		},
		13: {
			// Explicitly, no children.
			parent: parent(12),
			logs: []tracev2.Log{
				{Task: 13, Category: "log2", Message: "do"},
			},
			goroutines: []tracev2.GoID{7},
		},
	}
	for id, summary := range summaries {
		want, ok := wantTasks[id]
		if !ok {
			continue
		}
		if id != summary.ID {
			t.Errorf("ambiguous task %d (or %d?): field likely set incorrectly", id, summary.ID)
		}

		// Check parent.
		if want.parent != nil {
			if summary.Parent == nil {
				t.Errorf("expected parent %d for task %d without a parent", *want.parent, id)
			} else if summary.Parent.ID != *want.parent {
				t.Errorf("bad parent for task %d: want %d, got %d", id, *want.parent, summary.Parent.ID)
			}
		} else if summary.Parent != nil {
			t.Errorf("unexpected parent %d for task %d", summary.Parent.ID, id)
		}

		// Check children.
		gotChildren := make(map[tracev2.TaskID]struct{})
		for _, child := range summary.Children {
			gotChildren[child.ID] = struct{}{}
		}
		for _, wantChild := range want.children {
			if _, ok := gotChildren[wantChild]; ok {
				delete(gotChildren, wantChild)
			} else {
				t.Errorf("expected child task %d for task %d not found", wantChild, id)
			}
		}
		if len(gotChildren) != 0 {
			for child := range gotChildren {
				t.Errorf("unexpected child task %d for task %d", child, id)
			}
		}

		// Check logs.
		if len(want.logs) != len(summary.Logs) {
			t.Errorf("wanted %d logs for task %d, got %d logs instead", len(want.logs), id, len(summary.Logs))
		} else {
			for i := range want.logs {
				if want.logs[i] != summary.Logs[i].Log() {
					t.Errorf("log mismatch: want %#v, got %#v", want.logs[i], summary.Logs[i].Log())
				}
			}
		}

		// Check goroutines.
		if len(want.goroutines) != len(summary.Goroutines) {
			t.Errorf("wanted %d goroutines for task %d, got %d goroutines instead", len(want.goroutines), id, len(summary.Goroutines))
		} else {
			for _, goid := range want.goroutines {
				g, ok := summary.Goroutines[goid]
				if !ok {
					t.Errorf("want goroutine %d for task %d, not found", goid, id)
					continue
				}
				if g.ID != goid {
					t.Errorf("goroutine summary for %d does not match task %d listing of %d", g.ID, id, goid)
				}
			}
		}

		// Marked as seen.
		delete(wantTasks, id)
	}
	if len(wantTasks) != 0 {
		t.Errorf("failed to find tasks: %#v", wantTasks)
	}
}

func assertContainsGoroutine(t *testing.T, summaries map[tracev2.GoID]*GoroutineSummary, name string) {
	for _, summary := range summaries {
		if summary.Name == name {
			return
		}
	}
	t.Errorf("missing goroutine %s", name)
}

func basicGoroutineSummaryChecks(t *testing.T, summary *GoroutineSummary) {
	if summary.ID == tracev2.NoGoroutine {
		t.Error("summary found for no goroutine")
		return
	}
	if (summary.StartTime != 0 && summary.CreationTime > summary.StartTime) ||
		(summary.StartTime != 0 && summary.EndTime != 0 && summary.StartTime > summary.EndTime) {
		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)
	}
	if (summary.PC != 0 && summary.Name == "") || (summary.PC == 0 && summary.Name != "") {
		t.Errorf("bad name and/or PC for G %d: pc=0x%x name=%q", summary.ID, summary.PC, summary.Name)
	}
	basicGoroutineExecStatsChecks(t, &summary.GoroutineExecStats)
	for _, region := range summary.Regions {
		basicGoroutineExecStatsChecks(t, &region.GoroutineExecStats)
	}
}

func summarizeTraceTest(t *testing.T, testPath string) *Summary {
	trace, _, err := testtrace.ParseFile(testPath)
	if err != nil {
		t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
	}
	// Create the analysis state.
	s := NewSummarizer()

	// Create a reader.
	r, err := tracev2.NewReader(trace)
	if err != nil {
		t.Fatalf("failed to create trace reader for %s: %v", testPath, err)
	}
	// Process the trace.
	for {
		ev, err := r.ReadEvent()
		if err == io.EOF {
			break
		}
		if err != nil {
			t.Fatalf("failed to process trace %s: %v", testPath, err)
		}
		s.Event(&ev)
	}
	return s.Finalize()
}

func checkRegionEvents(t *testing.T, wantStart, wantEnd tracev2.EventKind, goid tracev2.GoID, region *UserRegionSummary) {
	switch wantStart {
	case tracev2.EventBad:
		if region.Start != nil {
			t.Errorf("expected nil region start event, got\n%s", region.Start.String())
		}
	case tracev2.EventStateTransition, tracev2.EventRegionBegin:
		if region.Start == nil {
			t.Error("expected non-nil region start event, got nil")
		}
		kind := region.Start.Kind()
		if kind != wantStart {
			t.Errorf("wanted region start event %s, got %s", wantStart, kind)
		}
		if kind == tracev2.EventRegionBegin {
			if region.Start.Region().Type != region.Name {
				t.Errorf("region name mismatch: event has %s, summary has %s", region.Start.Region().Type, region.Name)
			}
		} else {
			st := region.Start.StateTransition()
			if st.Resource.Kind != tracev2.ResourceGoroutine {
				t.Errorf("found region start event for the wrong resource: %s", st.Resource)
			}
			if st.Resource.Goroutine() != goid {
				t.Errorf("found region start event for the wrong resource: wanted goroutine %d, got %s", goid, st.Resource)
			}
			if old, _ := st.Goroutine(); old != tracev2.GoNotExist && old != tracev2.GoUndetermined {
				t.Errorf("expected transition from GoNotExist or GoUndetermined, got transition from %s instead", old)
			}
		}
	default:
		t.Errorf("unexpected want start event type: %s", wantStart)
	}

	switch wantEnd {
	case tracev2.EventBad:
		if region.End != nil {
			t.Errorf("expected nil region end event, got\n%s", region.End.String())
		}
	case tracev2.EventStateTransition, tracev2.EventRegionEnd:
		if region.End == nil {
			t.Error("expected non-nil region end event, got nil")
		}
		kind := region.End.Kind()
		if kind != wantEnd {
			t.Errorf("wanted region end event %s, got %s", wantEnd, kind)
		}
		if kind == tracev2.EventRegionEnd {
			if region.End.Region().Type != region.Name {
				t.Errorf("region name mismatch: event has %s, summary has %s", region.End.Region().Type, region.Name)
			}
		} else {
			st := region.End.StateTransition()
			if st.Resource.Kind != tracev2.ResourceGoroutine {
				t.Errorf("found region end event for the wrong resource: %s", st.Resource)
			}
			if st.Resource.Goroutine() != goid {
				t.Errorf("found region end event for the wrong resource: wanted goroutine %d, got %s", goid, st.Resource)
			}
			if _, new := st.Goroutine(); new != tracev2.GoNotExist {
				t.Errorf("expected transition to GoNotExist, got transition to %s instead", new)
			}
		}
	default:
		t.Errorf("unexpected want end event type: %s", wantEnd)
	}
}

func basicGoroutineExecStatsChecks(t *testing.T, stats *GoroutineExecStats) {
	if stats.ExecTime < 0 {
		t.Error("found negative ExecTime")
	}
	if stats.SchedWaitTime < 0 {
		t.Error("found negative SchedWaitTime")
	}
	if stats.SyscallTime < 0 {
		t.Error("found negative SyscallTime")
	}
	if stats.SyscallBlockTime < 0 {
		t.Error("found negative SyscallBlockTime")
	}
	if stats.TotalTime < 0 {
		t.Error("found negative TotalTime")
	}
	for reason, dt := range stats.BlockTimeByReason {
		if dt < 0 {
			t.Errorf("found negative BlockTimeByReason for %s", reason)
		}
	}
	for name, dt := range stats.RangeTime {
		if dt < 0 {
			t.Errorf("found negative RangeTime for range %s", name)
		}
	}
}

func TestRelatedGoroutinesV2Trace(t *testing.T) {
	testPath := "v2/testdata/tests/go122-gc-stress.test"
	trace, _, err := testtrace.ParseFile(testPath)
	if err != nil {
		t.Fatalf("malformed test %s: bad trace file: %v", testPath, err)
	}

	// Create a reader.
	r, err := tracev2.NewReader(trace)
	if err != nil {
		t.Fatalf("failed to create trace reader for %s: %v", testPath, err)
	}

	// Collect all the events.
	var events []tracev2.Event
	for {
		ev, err := r.ReadEvent()
		if err == io.EOF {
			break
		}
		if err != nil {
			t.Fatalf("failed to process trace %s: %v", testPath, err)
		}
		events = append(events, ev)
	}

	// Test the function.
	targetg := tracev2.GoID(86)
	got := RelatedGoroutinesV2(events, targetg)
	want := map[tracev2.GoID]struct{}{
		tracev2.GoID(86):  struct{}{}, // N.B. Result includes target.
		tracev2.GoID(71):  struct{}{},
		tracev2.GoID(25):  struct{}{},
		tracev2.GoID(122): struct{}{},
	}
	for goid := range got {
		if _, ok := want[goid]; ok {
			delete(want, goid)
		} else {
			t.Errorf("unexpected goroutine %d found in related goroutines for %d in test %s", goid, targetg, testPath)
		}
	}
	if len(want) != 0 {
		for goid := range want {
			t.Errorf("failed to find related goroutine %d for goroutine %d in test %s", goid, targetg, testPath)
		}
	}
}