flightrecorder_test.go

     1  // Copyright 2025 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  package trace_test
     6  
     7  import (
     8  	"bytes"
     9  	"context"
    10  	inttrace "internal/trace"
    11  	"internal/trace/testtrace"
    12  	"io"
    13  	"runtime/trace"
    14  	"slices"
    15  	"sync"
    16  	"sync/atomic"
    17  	"testing"
    18  	"time"
    19  )
    20  
    21  func TestFlightRecorderDoubleStart(t *testing.T) {
    22  	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
    23  	if err := fr.Start(); err != nil {
    24  		t.Fatalf("unexpected error on Start: %v", err)
    25  	}
    26  	if err := fr.Start(); err == nil {
    27  		t.Fatalf("expected error from double Start: %v", err)
    28  	}
    29  	fr.Stop()
    30  }
    31  
    32  func TestFlightRecorderEnabled(t *testing.T) {
    33  	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
    34  
    35  	if fr.Enabled() {
    36  		t.Fatal("flight recorder is enabled, but never started")
    37  	}
    38  	if err := fr.Start(); err != nil {
    39  		t.Fatalf("unexpected error on Start: %v", err)
    40  	}
    41  	if !fr.Enabled() {
    42  		t.Fatal("flight recorder is not enabled, but started")
    43  	}
    44  	fr.Stop()
    45  	if fr.Enabled() {
    46  		t.Fatal("flight recorder is enabled, but stopped")
    47  	}
    48  }
    49  
    50  func TestFlightRecorderWriteToDisabled(t *testing.T) {
    51  	var buf bytes.Buffer
    52  
    53  	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
    54  	if n, err := fr.WriteTo(&buf); err == nil {
    55  		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
    56  	}
    57  	if err := fr.Start(); err != nil {
    58  		t.Fatalf("unexpected error on Start: %v", err)
    59  	}
    60  	fr.Stop()
    61  	if n, err := fr.WriteTo(&buf); err == nil {
    62  		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
    63  	}
    64  }
    65  
    66  func TestFlightRecorderConcurrentWriteTo(t *testing.T) {
    67  	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
    68  	if err := fr.Start(); err != nil {
    69  		t.Fatalf("unexpected error on Start: %v", err)
    70  	}
    71  
    72  	// Start two goroutines to write snapshots.
    73  	//
    74  	// Most of the time one will fail and one will succeed, but we don't require this.
    75  	// Due to a variety of factors, it's definitely possible for them both to succeed.
    76  	// However, at least one should succeed.
    77  	var bufs [2]bytes.Buffer
    78  	var wg sync.WaitGroup
    79  	var successes atomic.Uint32
    80  	for i := range bufs {
    81  		wg.Add(1)
    82  		go func() {
    83  			defer wg.Done()
    84  
    85  			n, err := fr.WriteTo(&bufs[i])
    86  			// TODO(go.dev/issue/63185) was an exported error. Consider refactoring.
    87  			if err != nil && err.Error() == "call to WriteTo for trace.FlightRecorder already in progress" {
    88  				if n != 0 {
    89  					t.Errorf("(goroutine %d) WriteTo bytes written is non-zero for early bail out: %d", i, n)
    90  				}
    91  				return
    92  			}
    93  			if err != nil {
    94  				t.Errorf("(goroutine %d) failed to write snapshot for unexpected reason: %v", i, err)
    95  			}
    96  			successes.Add(1)
    97  
    98  			if n == 0 {
    99  				t.Errorf("(goroutine %d) wrote invalid trace of zero bytes in size", i)
   100  			}
   101  			if n != int64(bufs[i].Len()) {
   102  				t.Errorf("(goroutine %d) trace length doesn't match WriteTo result: got %d, want %d", i, n, int64(bufs[i].Len()))
   103  			}
   104  		}()
   105  	}
   106  	wg.Wait()
   107  
   108  	// Stop tracing.
   109  	fr.Stop()
   110  
   111  	// Make sure at least one succeeded to write.
   112  	if successes.Load() == 0 {
   113  		t.Fatal("expected at least one success to write a snapshot, got zero")
   114  	}
   115  
   116  	// Validate the traces that came out.
   117  	for i := range bufs {
   118  		buf := &bufs[i]
   119  		if buf.Len() == 0 {
   120  			continue
   121  		}
   122  		testReader(t, buf, testtrace.ExpectSuccess())
   123  	}
   124  }
   125  
   126  func TestFlightRecorder(t *testing.T) {
   127  	testFlightRecorder(t, trace.NewFlightRecorder(trace.FlightRecorderConfig{}), func(snapshot func()) {
   128  		snapshot()
   129  	})
   130  }
   131  
   132  func TestFlightRecorderStartStop(t *testing.T) {
   133  	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
   134  	for i := 0; i < 5; i++ {
   135  		testFlightRecorder(t, fr, func(snapshot func()) {
   136  			snapshot()
   137  		})
   138  	}
   139  }
   140  
   141  func TestFlightRecorderLog(t *testing.T) {
   142  	tr := testFlightRecorder(t, trace.NewFlightRecorder(trace.FlightRecorderConfig{}), func(snapshot func()) {
   143  		trace.Log(context.Background(), "message", "hello")
   144  		snapshot()
   145  	})
   146  
   147  	// Prepare to read the trace snapshot.
   148  	r, err := inttrace.NewReader(bytes.NewReader(tr))
   149  	if err != nil {
   150  		t.Fatalf("unexpected error creating trace reader: %v", err)
   151  	}
   152  
   153  	// Find the log message in the trace.
   154  	found := false
   155  	for {
   156  		ev, err := r.ReadEvent()
   157  		if err == io.EOF {
   158  			break
   159  		}
   160  		if err != nil {
   161  			t.Fatalf("unexpected error reading trace: %v", err)
   162  		}
   163  		if !found && ev.Kind() == inttrace.EventLog {
   164  			log := ev.Log()
   165  			found = log.Category == "message" && log.Message == "hello"
   166  		}
   167  	}
   168  	if !found {
   169  		t.Errorf("failed to find expected log message (%q, %q) in snapshot", "message", "hello")
   170  	}
   171  }
   172  
   173  func TestFlightRecorderGenerationCount(t *testing.T) {
   174  	test := func(t *testing.T, fr *trace.FlightRecorder) {
   175  		tr := testFlightRecorder(t, fr, func(snapshot func()) {
   176  			// Sleep to let a few generations pass.
   177  			time.Sleep(3 * time.Second)
   178  			snapshot()
   179  		})
   180  
   181  		// Prepare to read the trace snapshot.
   182  		r, err := inttrace.NewReader(bytes.NewReader(tr))
   183  		if err != nil {
   184  			t.Fatalf("unexpected error creating trace reader: %v", err)
   185  		}
   186  
   187  		// Make sure there are Sync events: at the start and end.
   188  		var syncs []int
   189  		evs := 0
   190  		for {
   191  			ev, err := r.ReadEvent()
   192  			if err == io.EOF {
   193  				break
   194  			}
   195  			if err != nil {
   196  				t.Fatalf("unexpected error reading trace: %v", err)
   197  			}
   198  			if ev.Kind() == inttrace.EventSync {
   199  				syncs = append(syncs, evs)
   200  			}
   201  			evs++
   202  		}
   203  		const wantMaxSyncs = 3
   204  		if len(syncs) > wantMaxSyncs {
   205  			t.Errorf("expected at most %d sync events, found %d at %d",
   206  				wantMaxSyncs, len(syncs), syncs)
   207  		}
   208  		ends := []int{syncs[0], syncs[len(syncs)-1]}
   209  		if wantEnds := []int{0, evs - 1}; !slices.Equal(wantEnds, ends) {
   210  			t.Errorf("expected a sync event at each end of the trace, found sync events at %d instead of %d",
   211  				ends, wantEnds)
   212  		}
   213  	}
   214  	t.Run("MinAge", func(t *testing.T) {
   215  		fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MinAge: time.Millisecond})
   216  		test(t, fr)
   217  	})
   218  	t.Run("MaxBytes", func(t *testing.T) {
   219  		fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MaxBytes: 16})
   220  		test(t, fr)
   221  	})
   222  }
   223  
   224  type flightRecorderTestFunc func(snapshot func())
   225  
   226  func testFlightRecorder(t *testing.T, fr *trace.FlightRecorder, f flightRecorderTestFunc) []byte {
   227  	if trace.IsEnabled() {
   228  		t.Skip("cannot run flight recorder tests when tracing is enabled")
   229  	}
   230  
   231  	// Start the flight recorder.
   232  	if err := fr.Start(); err != nil {
   233  		t.Fatalf("unexpected error on Start: %v", err)
   234  	}
   235  
   236  	// Set up snapshot callback.
   237  	var buf bytes.Buffer
   238  	callback := func() {
   239  		n, err := fr.WriteTo(&buf)
   240  		if err != nil {
   241  			t.Errorf("unexpected failure during flight recording: %v", err)
   242  			return
   243  		}
   244  		if n < 16 {
   245  			t.Errorf("expected a trace size of at least 16 bytes, got %d", n)
   246  		}
   247  		if n != int64(buf.Len()) {
   248  			t.Errorf("WriteTo result doesn't match trace size: got %d, want %d", n, int64(buf.Len()))
   249  		}
   250  	}
   251  
   252  	// Call the test function.
   253  	f(callback)
   254  
   255  	// Stop the flight recorder.
   256  	fr.Stop()
   257  
   258  	// Get the trace bytes; we don't want to use the Buffer as a Reader directly
   259  	// since we may want to consume this data more than once.
   260  	traceBytes := buf.Bytes()
   261  
   262  	// Parse the trace to make sure it's not broken.
   263  	testReader(t, bytes.NewReader(traceBytes), testtrace.ExpectSuccess())
   264  	return traceBytes
   265  }
   266  
   267  func testReader(t *testing.T, tr io.Reader, exp *testtrace.Expectation) {
   268  	r, err := inttrace.NewReader(tr)
   269  	if err != nil {
   270  		if err := exp.Check(err); err != nil {
   271  			t.Error(err)
   272  		}
   273  		return
   274  	}
   275  	v := testtrace.NewValidator()
   276  	v.SkipClockSnapshotChecks()
   277  	for {
   278  		ev, err := r.ReadEvent()
   279  		if err == io.EOF {
   280  			break
   281  		}
   282  		if err != nil {
   283  			if err := exp.Check(err); err != nil {
   284  				t.Error(err)
   285  			}
   286  			return
   287  		}
   288  		if err := v.Event(ev); err != nil {
   289  			t.Error(err)
   290  		}
   291  	}
   292  	if err := exp.Check(nil); err != nil {
   293  		t.Error(err)
   294  	}
   295  }
   296  
   297  func TestTraceAndFlightRecorder(t *testing.T) {
   298  	var tBuf, frBuf bytes.Buffer
   299  	if err := trace.Start(&tBuf); err != nil {
   300  		t.Errorf("unable to start execution tracer: %s", err)
   301  	}
   302  	fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MaxBytes: 16})
   303  	fr.Start()
   304  	fr.WriteTo(&frBuf)
   305  	fr.Stop()
   306  	trace.Stop()
   307  	if tBuf.Len() == 0 || frBuf.Len() == 0 {
   308  		t.Errorf("None of these should be equal to zero: %d %d", tBuf.Len(), frBuf.Len())
   309  	}
   310  	if tBuf.Len() <= frBuf.Len() {
   311  		t.Errorf("trace should be longer than the flight recorder: trace=%d flight record=%d", tBuf.Len(), frBuf.Len())
   312  	}
   313  }
   314
View as plain text