path: root/src/cmd/trace/v2/jsontrace_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 (
	"bytes"
	"encoding/json"
	tracev1 "internal/trace"
	"io"
	"net/http/httptest"
	"os"
	"path/filepath"
	"slices"
	"strconv"
	"strings"
	"testing"
	"time"

	"internal/trace/traceviewer/format"
	"internal/trace/v2/raw"
)

func TestJSONTraceHandler(t *testing.T) {
	testPaths, err := filepath.Glob("./testdata/*.test")
	if err != nil {
		t.Fatalf("discovering tests: %v", err)
	}
	for _, testPath := range testPaths {
		t.Run(filepath.Base(testPath), func(t *testing.T) {
			parsed := getTestTrace(t, testPath)
			data := recordJSONTraceHandlerResponse(t, parsed)
			// TODO(mknyszek): Check that there's one at most goroutine per proc at any given time.
			checkExecutionTimes(t, data)
			checkPlausibleHeapMetrics(t, data)
			// TODO(mknyszek): Check for plausible thread and goroutine metrics.
			checkMetaNamesEmitted(t, data, "process_name", []string{"STATS", "PROCS"})
			checkMetaNamesEmitted(t, data, "thread_name", []string{"GC", "Network", "Timers", "Syscalls", "Proc 0"})
			checkProcStartStop(t, data)
			checkSyscalls(t, data)
			checkNetworkUnblock(t, data)
			// TODO(mknyszek): Check for flow events.
		})
	}
}

func checkSyscalls(t *testing.T, data format.Data) {
	data = filterViewerTrace(data,
		filterEventName("syscall"),
		filterStackRootFunc("main.blockingSyscall"))
	if len(data.Events) <= 1 {
		t.Errorf("got %d events, want > 1", len(data.Events))
	}
	data = filterViewerTrace(data, filterBlocked("yes"))
	if len(data.Events) != 1 {
		t.Errorf("got %d events, want 1", len(data.Events))
	}
}

type eventFilterFn func(*format.Event, *format.Data) bool

func filterEventName(name string) eventFilterFn {
	return func(e *format.Event, _ *format.Data) bool {
		return e.Name == name
	}
}

// filterGoRoutineName returns an event filter that returns true if the event's
// goroutine name is equal to name.
func filterGoRoutineName(name string) eventFilterFn {
	return func(e *format.Event, _ *format.Data) bool {
		return parseGoroutineName(e) == name
	}
}

// parseGoroutineName returns the goroutine name from the event's name field.
// E.g. if e.Name is "G42 main.cpu10", this returns "main.cpu10".
func parseGoroutineName(e *format.Event) string {
	parts := strings.SplitN(e.Name, " ", 2)
	if len(parts) != 2 || !strings.HasPrefix(parts[0], "G") {
		return ""
	}
	return parts[1]
}

// filterBlocked returns an event filter that returns true if the event's
// "blocked" argument is equal to blocked.
func filterBlocked(blocked string) eventFilterFn {
	return func(e *format.Event, _ *format.Data) bool {
		m, ok := e.Arg.(map[string]any)
		if !ok {
			return false
		}
		return m["blocked"] == blocked
	}
}

// filterStackRootFunc returns an event filter that returns true if the function
// at the root of the stack trace is named name.
func filterStackRootFunc(name string) eventFilterFn {
	return func(e *format.Event, data *format.Data) bool {
		frames := stackFrames(data, e.Stack)
		rootFrame := frames[len(frames)-1]
		return strings.HasPrefix(rootFrame, name+":")
	}
}

// filterViewerTrace returns a copy of data with only the events that pass all
// of the given filters.
func filterViewerTrace(data format.Data, fns ...eventFilterFn) (filtered format.Data) {
	filtered = data
	filtered.Events = nil
	for _, e := range data.Events {
		keep := true
		for _, fn := range fns {
			keep = keep && fn(e, &filtered)
		}
		if keep {
			filtered.Events = append(filtered.Events, e)
		}
	}
	return
}

func stackFrames(data *format.Data, stackID int) (frames []string) {
	for {
		frame, ok := data.Frames[strconv.Itoa(stackID)]
		if !ok {
			return
		}
		frames = append(frames, frame.Name)
		stackID = frame.Parent
	}
}

func checkProcStartStop(t *testing.T, data format.Data) {
	procStarted := map[uint64]bool{}
	for _, e := range data.Events {
		if e.Name == "proc start" {
			if procStarted[e.TID] == true {
				t.Errorf("proc started twice: %d", e.TID)
			}
			procStarted[e.TID] = true
		}
		if e.Name == "proc stop" {
			if procStarted[e.TID] == false {
				t.Errorf("proc stopped twice: %d", e.TID)
			}
			procStarted[e.TID] = false
		}
	}
	if got, want := len(procStarted), 8; got != want {
		t.Errorf("wrong number of procs started/stopped got=%d want=%d", got, want)
	}
}

func checkNetworkUnblock(t *testing.T, data format.Data) {
	count := 0
	var netBlockEv *format.Event
	for _, e := range data.Events {
		if e.TID == tracev1.NetpollP && e.Name == "unblock (network)" && e.Phase == "I" && e.Scope == "t" {
			count++
			netBlockEv = e
		}
	}
	if netBlockEv == nil {
		t.Error("failed to find a network unblock")
	}
	if count == 0 {
		t.Errorf("found zero network block events, want at least one")
	}
	// TODO(mknyszek): Check for the flow of this event to some slice event of a goroutine running.
}

func checkExecutionTimes(t *testing.T, data format.Data) {
	cpu10 := sumExecutionTime(filterViewerTrace(data, filterGoRoutineName("main.cpu10")))
	cpu20 := sumExecutionTime(filterViewerTrace(data, filterGoRoutineName("main.cpu20")))
	if cpu10 <= 0 || cpu20 <= 0 || cpu10 >= cpu20 {
		t.Errorf("bad execution times: cpu10=%v, cpu20=%v", cpu10, cpu20)
	}
}

func checkMetaNamesEmitted(t *testing.T, data format.Data, category string, want []string) {
	t.Helper()
	names := metaEventNameArgs(category, data)
	for _, wantName := range want {
		if !slices.Contains(names, wantName) {
			t.Errorf("%s: names=%v, want %q", category, names, wantName)
		}
	}
}

func metaEventNameArgs(category string, data format.Data) (names []string) {
	for _, e := range data.Events {
		if e.Name == category && e.Phase == "M" {
			names = append(names, e.Arg.(map[string]any)["name"].(string))
		}
	}
	return
}

func checkPlausibleHeapMetrics(t *testing.T, data format.Data) {
	hms := heapMetrics(data)
	var nonZeroAllocated, nonZeroNextGC bool
	for _, hm := range hms {
		if hm.Allocated > 0 {
			nonZeroAllocated = true
		}
		if hm.NextGC > 0 {
			nonZeroNextGC = true
		}
	}

	if !nonZeroAllocated {
		t.Errorf("nonZeroAllocated=%v, want true", nonZeroAllocated)
	}
	if !nonZeroNextGC {
		t.Errorf("nonZeroNextGC=%v, want true", nonZeroNextGC)
	}
}

func heapMetrics(data format.Data) (metrics []format.HeapCountersArg) {
	for _, e := range data.Events {
		if e.Phase == "C" && e.Name == "Heap" {
			j, _ := json.Marshal(e.Arg)
			var metric format.HeapCountersArg
			json.Unmarshal(j, &metric)
			metrics = append(metrics, metric)
		}
	}
	return
}

func recordJSONTraceHandlerResponse(t *testing.T, parsed *parsedTrace) format.Data {
	h := JSONTraceHandler(parsed)
	recorder := httptest.NewRecorder()
	r := httptest.NewRequest("GET", "/jsontrace", nil)
	h.ServeHTTP(recorder, r)

	var data format.Data
	if err := json.Unmarshal(recorder.Body.Bytes(), &data); err != nil {
		t.Fatal(err)
	}
	return data
}

func sumExecutionTime(data format.Data) (sum time.Duration) {
	for _, e := range data.Events {
		sum += time.Duration(e.Dur) * time.Microsecond
	}
	return
}

func getTestTrace(t *testing.T, testPath string) *parsedTrace {
	t.Helper()

	// First read in the text trace and write it out as bytes.
	f, err := os.Open(testPath)
	if err != nil {
		t.Fatalf("failed to open test %s: %v", testPath, err)
	}
	r, err := raw.NewTextReader(f)
	if err != nil {
		t.Fatalf("failed to read test %s: %v", testPath, err)
	}
	var trace bytes.Buffer
	w, err := raw.NewWriter(&trace, r.Version())
	if err != nil {
		t.Fatalf("failed to write out test %s: %v", testPath, err)
	}
	for {
		ev, err := r.ReadEvent()
		if err == io.EOF {
			break
		}
		if err != nil {
			t.Fatalf("failed to read test %s: %v", testPath, err)
		}
		if err := w.WriteEvent(ev); err != nil {
			t.Fatalf("failed to write out test %s: %v", testPath, err)
		}
	}

	// Parse the test trace.
	parsed, err := parseTrace(&trace, int64(trace.Len()))
	if err != nil {
		t.Fatalf("failed to parse trace: %v", err)
	}
	return parsed
}