| // 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, ®ion.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) |
| } |
| } |
| } |