package trace_test import ( "bytes" "context" "fmt" "internal/trace" "reflect" . "runtime/trace" "strings" "sync" "testing" ) func BenchmarkStartRegion(b *testing.B) { b.ReportAllocs() ctx, task := NewTask(context.Background(), "benchmark") defer task.End() b.RunParallel(func(pb *testing.PB) { for pb.Next() { StartRegion(ctx, "region").End() } }) } func BenchmarkNewTask(b *testing.B) { b.ReportAllocs() pctx, task := NewTask(context.Background(), "benchmark") defer task.End() b.RunParallel(func(pb *testing.PB) { for pb.Next() { _, task := NewTask(pctx, "task") task.End() } }) } func TestUserTaskRegion(t *testing.T) { if IsEnabled() { t.Skip("skipping because -test.trace is set") } bgctx, cancel := context.WithCancel(context.Background()) defer cancel() preExistingRegion := StartRegion(bgctx, "pre-existing region") buf := new(bytes.Buffer) if err := Start(buf); err != nil { t.Fatalf("failed to start tracing: %v", err) } // Beginning of traced execution var wg sync.WaitGroup ctx, task := NewTask(bgctx, "task0") // EvUserTaskCreate("task0") wg.Add(1) go func() { defer wg.Done() defer task.End() // EvUserTaskEnd("task0") WithRegion(ctx, "region0", func() { // EvUserRegionCreate("region0", start) WithRegion(ctx, "region1", func() { Log(ctx, "key0", "0123456789abcdef") // EvUserLog("task0", "key0", "0....f") }) // EvUserRegion("region0", end) }) }() wg.Wait() preExistingRegion.End() postExistingRegion := StartRegion(bgctx, "post-existing region") // End of traced execution Stop() postExistingRegion.End() saveTrace(t, buf, "TestUserTaskRegion") res, err := trace.Parse(buf, "") if err == trace.ErrTimeOrder { // golang.org/issues/16755 t.Skipf("skipping trace: %v", err) } if err != nil { t.Fatalf("Parse failed: %v", err) } // Check whether we see all user annotation related records in order type testData struct { typ byte strs []string args []uint64 setLink bool } var got []testData tasks := map[uint64]string{} for _, e := range res.Events { t.Logf("%s", e) switch e.Type { case trace.EvUserTaskCreate: taskName := e.SArgs[0] got = append(got, testData{trace.EvUserTaskCreate, []string{taskName}, nil, e.Link != nil}) if e.Link != nil && e.Link.Type != trace.EvUserTaskEnd { t.Errorf("Unexpected linked event %q->%q", e, e.Link) } tasks[e.Args[0]] = taskName case trace.EvUserLog: key, val := e.SArgs[0], e.SArgs[1] taskName := tasks[e.Args[0]] got = append(got, testData{trace.EvUserLog, []string{taskName, key, val}, nil, e.Link != nil}) case trace.EvUserTaskEnd: taskName := tasks[e.Args[0]] got = append(got, testData{trace.EvUserTaskEnd, []string{taskName}, nil, e.Link != nil}) if e.Link != nil && e.Link.Type != trace.EvUserTaskCreate { t.Errorf("Unexpected linked event %q->%q", e, e.Link) } case trace.EvUserRegion: taskName := tasks[e.Args[0]] regionName := e.SArgs[0] got = append(got, testData{trace.EvUserRegion, []string{taskName, regionName}, []uint64{e.Args[1]}, e.Link != nil}) if e.Link != nil && (e.Link.Type != trace.EvUserRegion || e.Link.SArgs[0] != regionName) { t.Errorf("Unexpected linked event %q->%q", e, e.Link) } } } want := []testData{ {trace.EvUserTaskCreate, []string{"task0"}, nil, true}, {trace.EvUserRegion, []string{"task0", "region0"}, []uint64{0}, true}, {trace.EvUserRegion, []string{"task0", "region1"}, []uint64{0}, true}, {trace.EvUserLog, []string{"task0", "key0", "0123456789abcdef"}, nil, false}, {trace.EvUserRegion, []string{"task0", "region1"}, []uint64{1}, false}, {trace.EvUserRegion, []string{"task0", "region0"}, []uint64{1}, false}, {trace.EvUserTaskEnd, []string{"task0"}, nil, false}, // Currently, pre-existing region is not recorded to avoid allocations. // {trace.EvUserRegion, []string{"", "pre-existing region"}, []uint64{1}, false}, {trace.EvUserRegion, []string{"", "post-existing region"}, []uint64{0}, false}, } if !reflect.DeepEqual(got, want) { pretty := func(data []testData) string { var s strings.Builder for _, d := range data { s.WriteString(fmt.Sprintf("\t%+v\n", d)) } return s.String() } t.Errorf("Got user region related events\n%+v\nwant:\n%+v", pretty(got), pretty(want)) } }