src/runtime/trace/flightrecorder_test.go - go - Git at Google

 // Copyright 2025 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_test

 import (
 	"bytes"
 	"context"
 	inttrace "internal/trace"
 	"internal/trace/testtrace"
 	"io"
 	"runtime/trace"
 	"slices"
 	"sync"
 	"sync/atomic"
 	"testing"
 	"time"
 )

 func TestFlightRecorderDoubleStart(t *testing.T) {
 	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
 	if err := fr.Start(); err != nil {
 		t.Fatalf("unexpected error on Start: %v", err)
 	}
 	if err := fr.Start(); err == nil {
 		t.Fatalf("expected error from double Start: %v", err)
 	}
 	fr.Stop()
 }

 func TestFlightRecorderEnabled(t *testing.T) {
 	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})

 	if fr.Enabled() {
 		t.Fatal("flight recorder is enabled, but never started")
 	}
 	if err := fr.Start(); err != nil {
 		t.Fatalf("unexpected error on Start: %v", err)
 	}
 	if !fr.Enabled() {
 		t.Fatal("flight recorder is not enabled, but started")
 	}
 	fr.Stop()
 	if fr.Enabled() {
 		t.Fatal("flight recorder is enabled, but stopped")
 	}
 }

 func TestFlightRecorderWriteToDisabled(t *testing.T) {
 	var buf bytes.Buffer

 	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
 	if n, err := fr.WriteTo(&buf); err == nil {
 		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
 	}
 	if err := fr.Start(); err != nil {
 		t.Fatalf("unexpected error on Start: %v", err)
 	}
 	fr.Stop()
 	if n, err := fr.WriteTo(&buf); err == nil {
 		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
 	}
 }

 func TestFlightRecorderConcurrentWriteTo(t *testing.T) {
 	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
 	if err := fr.Start(); err != nil {
 		t.Fatalf("unexpected error on Start: %v", err)
 	}

 	// Start two goroutines to write snapshots.
 	//
 	// Most of the time one will fail and one will succeed, but we don't require this.
 	// Due to a variety of factors, it's definitely possible for them both to succeed.
 	// However, at least one should succeed.
 	var bufs [2]bytes.Buffer
 	var wg sync.WaitGroup
 	var successes atomic.Uint32
 	for i := range bufs {
 		wg.Add(1)
 		go func() {
 			defer wg.Done()

 			n, err := fr.WriteTo(&bufs[i])
 			// TODO(go.dev/issue/63185) was an exported error. Consider refactoring.
 			if err != nil && err.Error() == "call to WriteTo for trace.FlightRecorder already in progress" {
 				if n != 0 {
 					t.Errorf("(goroutine %d) WriteTo bytes written is non-zero for early bail out: %d", i, n)
 				}
 				return
 			}
 			if err != nil {
 				t.Errorf("(goroutine %d) failed to write snapshot for unexpected reason: %v", i, err)
 			}
 			successes.Add(1)

 			if n == 0 {
 				t.Errorf("(goroutine %d) wrote invalid trace of zero bytes in size", i)
 			}
 			if n != int64(bufs[i].Len()) {
 				t.Errorf("(goroutine %d) trace length doesn't match WriteTo result: got %d, want %d", i, n, int64(bufs[i].Len()))
 			}
 		}()
 	}
 	wg.Wait()

 	// Stop tracing.
 	fr.Stop()

 	// Make sure at least one succeeded to write.
 	if successes.Load() == 0 {
 		t.Fatal("expected at least one success to write a snapshot, got zero")
 	}

 	// Validate the traces that came out.
 	for i := range bufs {
 		buf := &bufs[i]
 		if buf.Len() == 0 {
 			continue
 		}
 		testReader(t, buf, testtrace.ExpectSuccess())
 	}
 }

 func TestFlightRecorder(t *testing.T) {
 	testFlightRecorder(t, trace.NewFlightRecorder(trace.FlightRecorderConfig{}), func(snapshot func()) {
 		snapshot()
 	})
 }

 func TestFlightRecorderStartStop(t *testing.T) {
 	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
 	for i := 0; i < 5; i++ {
 		testFlightRecorder(t, fr, func(snapshot func()) {
 			snapshot()
 		})
 	}
 }

 func TestFlightRecorderLog(t *testing.T) {
 	tr := testFlightRecorder(t, trace.NewFlightRecorder(trace.FlightRecorderConfig{}), func(snapshot func()) {
 		trace.Log(context.Background(), "message", "hello")
 		snapshot()
 	})

 	// Prepare to read the trace snapshot.
 	r, err := inttrace.NewReader(bytes.NewReader(tr))
 	if err != nil {
 		t.Fatalf("unexpected error creating trace reader: %v", err)
 	}

 	// Find the log message in the trace.
 	found := false
 	for {
 		ev, err := r.ReadEvent()
 		if err == io.EOF {
 			break
 		}
 		if err != nil {
 			t.Fatalf("unexpected error reading trace: %v", err)
 		}
 		if !found && ev.Kind() == inttrace.EventLog {
 			log := ev.Log()
 			found = log.Category == "message" && log.Message == "hello"
 		}
 	}
 	if !found {
 		t.Errorf("failed to find expected log message (%q, %q) in snapshot", "message", "hello")
 	}
 }

 func TestFlightRecorderGenerationCount(t *testing.T) {
 	test := func(t *testing.T, fr *trace.FlightRecorder) {
 		tr := testFlightRecorder(t, fr, func(snapshot func()) {
 			// Sleep to let a few generations pass.
 			time.Sleep(3 * time.Second)
 			snapshot()
 		})

 		// Prepare to read the trace snapshot.
 		r, err := inttrace.NewReader(bytes.NewReader(tr))
 		if err != nil {
 			t.Fatalf("unexpected error creating trace reader: %v", err)
 		}

 		// Make sure there are Sync events: at the start and end.
 		var syncs []int
 		evs := 0
 		for {
 			ev, err := r.ReadEvent()
 			if err == io.EOF {
 				break
 			}
 			if err != nil {
 				t.Fatalf("unexpected error reading trace: %v", err)
 			}
 			if ev.Kind() == inttrace.EventSync {
 				syncs = append(syncs, evs)
 			}
 			evs++
 		}
 		const wantMaxSyncs = 3
 		if len(syncs) > wantMaxSyncs {
 			t.Errorf("expected at most %d sync events, found %d at %d",
 				wantMaxSyncs, len(syncs), syncs)
 		}
 		ends := []int{syncs[0], syncs[len(syncs)-1]}
 		if wantEnds := []int{0, evs - 1}; !slices.Equal(wantEnds, ends) {
 			t.Errorf("expected a sync event at each end of the trace, found sync events at %d instead of %d",
 				ends, wantEnds)
 		}
 	}
 	t.Run("MinAge", func(t *testing.T) {
 		fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MinAge: time.Millisecond})
 		test(t, fr)
 	})
 	t.Run("MaxBytes", func(t *testing.T) {
 		fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MaxBytes: 16})
 		test(t, fr)
 	})
 }

 type flightRecorderTestFunc func(snapshot func())

 func testFlightRecorder(t *testing.T, fr *trace.FlightRecorder, f flightRecorderTestFunc) []byte {
 	if trace.IsEnabled() {
 		t.Skip("cannot run flight recorder tests when tracing is enabled")
 	}

 	// Start the flight recorder.
 	if err := fr.Start(); err != nil {
 		t.Fatalf("unexpected error on Start: %v", err)
 	}

 	// Set up snapshot callback.
 	var buf bytes.Buffer
 	callback := func() {
 		n, err := fr.WriteTo(&buf)
 		if err != nil {
 			t.Errorf("unexpected failure during flight recording: %v", err)
 			return
 		}
 		if n < 16 {
 			t.Errorf("expected a trace size of at least 16 bytes, got %d", n)
 		}
 		if n != int64(buf.Len()) {
 			t.Errorf("WriteTo result doesn't match trace size: got %d, want %d", n, int64(buf.Len()))
 		}
 	}

 	// Call the test function.
 	f(callback)

 	// Stop the flight recorder.
 	fr.Stop()

 	// Get the trace bytes; we don't want to use the Buffer as a Reader directly
 	// since we may want to consume this data more than once.
 	traceBytes := buf.Bytes()

 	// Parse the trace to make sure it's not broken.
 	testReader(t, bytes.NewReader(traceBytes), testtrace.ExpectSuccess())
 	return traceBytes
 }

 func testReader(t *testing.T, tr io.Reader, exp *testtrace.Expectation) {
 	r, err := inttrace.NewReader(tr)
 	if err != nil {
 		if err := exp.Check(err); err != nil {
 			t.Error(err)
 		}
 		return
 	}
 	v := testtrace.NewValidator()
 	v.SkipClockSnapshotChecks()
 	for {
 		ev, err := r.ReadEvent()
 		if err == io.EOF {
 			break
 		}
 		if err != nil {
 			if err := exp.Check(err); err != nil {
 				t.Error(err)
 			}
 			return
 		}
 		if err := v.Event(ev); err != nil {
 			t.Error(err)
 		}
 	}
 	if err := exp.Check(nil); err != nil {
 		t.Error(err)
 	}
 }

 func TestTraceAndFlightRecorder(t *testing.T) {
 	var tBuf, frBuf bytes.Buffer
 	if err := trace.Start(&tBuf); err != nil {
 		t.Errorf("unable to start execution tracer: %s", err)
 	}
 	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MaxBytes: 16})
 	fr.Start()
 	fr.WriteTo(&frBuf)
 	fr.Stop()
 	trace.Stop()
 	if tBuf.Len() == 0 || frBuf.Len() == 0 {
 		t.Errorf("None of these should be equal to zero: %d %d", tBuf.Len(), frBuf.Len())
 	}
 	if tBuf.Len() <= frBuf.Len() {
 		t.Errorf("trace should be longer than the flight recorder: trace=%d flight record=%d", tBuf.Len(), frBuf.Len())
 	}
 }
	// Copyright 2025 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_test

	import (
	"bytes"
	"context"
	inttrace "internal/trace"
	"internal/trace/testtrace"
	"io"
	"runtime/trace"
	"slices"
	"sync"
	"sync/atomic"
	"testing"
	"time"
	)

	func TestFlightRecorderDoubleStart(t *testing.T) {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
	if err := fr.Start(); err != nil {
	t.Fatalf("unexpected error on Start: %v", err)
	}
	if err := fr.Start(); err == nil {
	t.Fatalf("expected error from double Start: %v", err)
	}
	fr.Stop()
	}

	func TestFlightRecorderEnabled(t *testing.T) {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})

	if fr.Enabled() {
	t.Fatal("flight recorder is enabled, but never started")
	}
	if err := fr.Start(); err != nil {
	t.Fatalf("unexpected error on Start: %v", err)
	}
	if !fr.Enabled() {
	t.Fatal("flight recorder is not enabled, but started")
	}
	fr.Stop()
	if fr.Enabled() {
	t.Fatal("flight recorder is enabled, but stopped")
	}
	}

	func TestFlightRecorderWriteToDisabled(t *testing.T) {
	var buf bytes.Buffer

	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
	if n, err := fr.WriteTo(&buf); err == nil {
	t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
	}
	if err := fr.Start(); err != nil {
	t.Fatalf("unexpected error on Start: %v", err)
	}
	fr.Stop()
	if n, err := fr.WriteTo(&buf); err == nil {
	t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
	}
	}

	func TestFlightRecorderConcurrentWriteTo(t *testing.T) {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
	if err := fr.Start(); err != nil {
	t.Fatalf("unexpected error on Start: %v", err)
	}

	// Start two goroutines to write snapshots.
	//
	// Most of the time one will fail and one will succeed, but we don't require this.
	// Due to a variety of factors, it's definitely possible for them both to succeed.
	// However, at least one should succeed.
	var bufs [2]bytes.Buffer
	var wg sync.WaitGroup
	var successes atomic.Uint32
	for i := range bufs {
	wg.Add(1)
	go func() {
	defer wg.Done()

	n, err := fr.WriteTo(&bufs[i])
	// TODO(go.dev/issue/63185) was an exported error. Consider refactoring.
	if err != nil && err.Error() == "call to WriteTo for trace.FlightRecorder already in progress" {
	if n != 0 {
	t.Errorf("(goroutine %d) WriteTo bytes written is non-zero for early bail out: %d", i, n)
	}
	return
	}
	if err != nil {
	t.Errorf("(goroutine %d) failed to write snapshot for unexpected reason: %v", i, err)
	}
	successes.Add(1)

	if n == 0 {
	t.Errorf("(goroutine %d) wrote invalid trace of zero bytes in size", i)
	}
	if n != int64(bufs[i].Len()) {
	t.Errorf("(goroutine %d) trace length doesn't match WriteTo result: got %d, want %d", i, n, int64(bufs[i].Len()))
	}
	}()
	}
	wg.Wait()

	// Stop tracing.
	fr.Stop()

	// Make sure at least one succeeded to write.
	if successes.Load() == 0 {
	t.Fatal("expected at least one success to write a snapshot, got zero")
	}

	// Validate the traces that came out.
	for i := range bufs {
	buf := &bufs[i]
	if buf.Len() == 0 {
	continue
	}
	testReader(t, buf, testtrace.ExpectSuccess())
	}
	}

	func TestFlightRecorder(t *testing.T) {
	testFlightRecorder(t, trace.NewFlightRecorder(trace.FlightRecorderConfig{}), func(snapshot func()) {
	snapshot()
	})
	}

	func TestFlightRecorderStartStop(t *testing.T) {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
	for i := 0; i < 5; i++ {
	testFlightRecorder(t, fr, func(snapshot func()) {
	snapshot()
	})
	}
	}

	func TestFlightRecorderLog(t *testing.T) {
	tr := testFlightRecorder(t, trace.NewFlightRecorder(trace.FlightRecorderConfig{}), func(snapshot func()) {
	trace.Log(context.Background(), "message", "hello")
	snapshot()
	})

	// Prepare to read the trace snapshot.
	r, err := inttrace.NewReader(bytes.NewReader(tr))
	if err != nil {
	t.Fatalf("unexpected error creating trace reader: %v", err)
	}

	// Find the log message in the trace.
	found := false
	for {
	ev, err := r.ReadEvent()
	if err == io.EOF {
	break
	}
	if err != nil {
	t.Fatalf("unexpected error reading trace: %v", err)
	}
	if !found && ev.Kind() == inttrace.EventLog {
	log := ev.Log()
	found = log.Category == "message" && log.Message == "hello"
	}
	}
	if !found {
	t.Errorf("failed to find expected log message (%q, %q) in snapshot", "message", "hello")
	}
	}

	func TestFlightRecorderGenerationCount(t *testing.T) {
	test := func(t testing.T, fr trace.FlightRecorder) {
	tr := testFlightRecorder(t, fr, func(snapshot func()) {
	// Sleep to let a few generations pass.
	time.Sleep(3 * time.Second)
	snapshot()
	})

	// Prepare to read the trace snapshot.
	r, err := inttrace.NewReader(bytes.NewReader(tr))
	if err != nil {
	t.Fatalf("unexpected error creating trace reader: %v", err)
	}

	// Make sure there are Sync events: at the start and end.
	var syncs []int
	evs := 0
	for {
	ev, err := r.ReadEvent()
	if err == io.EOF {
	break
	}
	if err != nil {
	t.Fatalf("unexpected error reading trace: %v", err)
	}
	if ev.Kind() == inttrace.EventSync {
	syncs = append(syncs, evs)
	}
	evs++
	}
	const wantMaxSyncs = 3
	if len(syncs) > wantMaxSyncs {
	t.Errorf("expected at most %d sync events, found %d at %d",
	wantMaxSyncs, len(syncs), syncs)
	}
	ends := []int{syncs[0], syncs[len(syncs)-1]}
	if wantEnds := []int{0, evs - 1}; !slices.Equal(wantEnds, ends) {
	t.Errorf("expected a sync event at each end of the trace, found sync events at %d instead of %d",
	ends, wantEnds)
	}
	}
	t.Run("MinAge", func(t *testing.T) {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MinAge: time.Millisecond})
	test(t, fr)
	})
	t.Run("MaxBytes", func(t *testing.T) {
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MaxBytes: 16})
	test(t, fr)
	})
	}

	type flightRecorderTestFunc func(snapshot func())

	func testFlightRecorder(t testing.T, fr trace.FlightRecorder, f flightRecorderTestFunc) []byte {
	if trace.IsEnabled() {
	t.Skip("cannot run flight recorder tests when tracing is enabled")
	}

	// Start the flight recorder.
	if err := fr.Start(); err != nil {
	t.Fatalf("unexpected error on Start: %v", err)
	}

	// Set up snapshot callback.
	var buf bytes.Buffer
	callback := func() {
	n, err := fr.WriteTo(&buf)
	if err != nil {
	t.Errorf("unexpected failure during flight recording: %v", err)
	return
	}
	if n < 16 {
	t.Errorf("expected a trace size of at least 16 bytes, got %d", n)
	}
	if n != int64(buf.Len()) {
	t.Errorf("WriteTo result doesn't match trace size: got %d, want %d", n, int64(buf.Len()))
	}
	}

	// Call the test function.
	f(callback)

	// Stop the flight recorder.
	fr.Stop()

	// Get the trace bytes; we don't want to use the Buffer as a Reader directly
	// since we may want to consume this data more than once.
	traceBytes := buf.Bytes()

	// Parse the trace to make sure it's not broken.
	testReader(t, bytes.NewReader(traceBytes), testtrace.ExpectSuccess())
	return traceBytes
	}

	func testReader(t testing.T, tr io.Reader, exp testtrace.Expectation) {
	r, err := inttrace.NewReader(tr)
	if err != nil {
	if err := exp.Check(err); err != nil {
	t.Error(err)
	}
	return
	}
	v := testtrace.NewValidator()
	v.SkipClockSnapshotChecks()
	for {
	ev, err := r.ReadEvent()
	if err == io.EOF {
	break
	}
	if err != nil {
	if err := exp.Check(err); err != nil {
	t.Error(err)
	}
	return
	}
	if err := v.Event(ev); err != nil {
	t.Error(err)
	}
	}
	if err := exp.Check(nil); err != nil {
	t.Error(err)
	}
	}

	func TestTraceAndFlightRecorder(t *testing.T) {
	var tBuf, frBuf bytes.Buffer
	if err := trace.Start(&tBuf); err != nil {
	t.Errorf("unable to start execution tracer: %s", err)
	}
	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MaxBytes: 16})
	fr.Start()
	fr.WriteTo(&frBuf)
	fr.Stop()
	trace.Stop()
	if tBuf.Len() == 0 \|\| frBuf.Len() == 0 {
	t.Errorf("None of these should be equal to zero: %d %d", tBuf.Len(), frBuf.Len())
	}
	if tBuf.Len() <= frBuf.Len() {
	t.Errorf("trace should be longer than the flight recorder: trace=%d flight record=%d", tBuf.Len(), frBuf.Len())
	}
	}