flightrecorder_test.go

Documentation: golang.org/x/exp/trace

     1  // Copyright 2023 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  //go:build go1.22
     6  
     7  package trace_test
     8  
     9  import (
    10  	"bytes"
    11  	"context"
    12  	"io"
    13  	"runtime/trace"
    14  	"sync"
    15  	"sync/atomic"
    16  	"testing"
    17  	"time"
    18  
    19  	"golang.org/x/exp/trace/internal/testtrace"
    20  
    21  	. "golang.org/x/exp/trace"
    22  )
    23  
    24  func TestFlightRecorderDoubleStart(t *testing.T) {
    25  	fr := NewFlightRecorder()
    26  
    27  	if err := fr.Start(); err != nil {
    28  		t.Fatalf("unexpected error on Start: %v", err)
    29  	}
    30  	if err := fr.Start(); err == nil {
    31  		t.Fatalf("expected error from double Start: %v", err)
    32  	}
    33  	if err := fr.Stop(); err != nil {
    34  		t.Fatalf("unexpected error on Stop: %v", err)
    35  	}
    36  }
    37  
    38  func TestFlightRecorderDoubleStop(t *testing.T) {
    39  	fr := NewFlightRecorder()
    40  
    41  	if err := fr.Start(); err != nil {
    42  		t.Fatalf("unexpected error on Start: %v", err)
    43  	}
    44  	if err := fr.Stop(); err != nil {
    45  		t.Fatalf("unexpected error on Stop: %v", err)
    46  	}
    47  	if err := fr.Stop(); err == nil {
    48  		t.Fatalf("expected error from double Stop: %v", err)
    49  	}
    50  }
    51  
    52  func TestFlightRecorderEnabled(t *testing.T) {
    53  	fr := NewFlightRecorder()
    54  
    55  	if fr.Enabled() {
    56  		t.Fatal("flight recorder is enabled, but never started")
    57  	}
    58  	if err := fr.Start(); err != nil {
    59  		t.Fatalf("unexpected error on Start: %v", err)
    60  	}
    61  	if !fr.Enabled() {
    62  		t.Fatal("flight recorder is not enabled, but started")
    63  	}
    64  	if err := fr.Stop(); err != nil {
    65  		t.Fatalf("unexpected error on Stop: %v", err)
    66  	}
    67  	if fr.Enabled() {
    68  		t.Fatal("flight recorder is enabled, but stopped")
    69  	}
    70  }
    71  
    72  func TestFlightRecorderWriteToDisabled(t *testing.T) {
    73  	var buf bytes.Buffer
    74  
    75  	fr := NewFlightRecorder()
    76  	if n, err := fr.WriteTo(&buf); err == nil {
    77  		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
    78  	}
    79  	if err := fr.Start(); err != nil {
    80  		t.Fatalf("unexpected error on Start: %v", err)
    81  	}
    82  	if err := fr.Stop(); err != nil {
    83  		t.Fatalf("unexpected error on Stop: %v", err)
    84  	}
    85  	if n, err := fr.WriteTo(&buf); err == nil {
    86  		t.Fatalf("successfully wrote %d bytes from disabled flight recorder", n)
    87  	}
    88  }
    89  
    90  func TestFlightRecorderConcurrentWriteTo(t *testing.T) {
    91  	fr := NewFlightRecorder()
    92  	if err := fr.Start(); err != nil {
    93  		t.Fatalf("unexpected error on Start: %v", err)
    94  	}
    95  
    96  	// Start two goroutines to write snapshots.
    97  	//
    98  	// Most of the time one will fail and one will succeed, but we don't require this.
    99  	// Due to a variety of factors, it's definitely possible for them both to succeed.
   100  	// However, at least one should succeed.
   101  	var bufs [2]bytes.Buffer
   102  	var wg sync.WaitGroup
   103  	var successes atomic.Uint32
   104  	for i := range bufs {
   105  		wg.Add(1)
   106  		go func() {
   107  			defer wg.Done()
   108  
   109  			n, err := fr.WriteTo(&bufs[i])
   110  			if err == ErrSnapshotActive {
   111  				if n != 0 {
   112  					t.Errorf("(goroutine %d) WriteTo bytes written is non-zero for early bail out: %d", i, n)
   113  				}
   114  				return
   115  			}
   116  			if err != nil {
   117  				t.Errorf("(goroutine %d) failed to write snapshot for unexpected reason: %v", i, err)
   118  			}
   119  			successes.Add(1)
   120  
   121  			if n == 0 {
   122  				t.Errorf("(goroutine %d) wrote invalid trace of zero bytes in size", i)
   123  			}
   124  			if n != bufs[i].Len() {
   125  				t.Errorf("(goroutine %d) trace length doesn't match WriteTo result: got %d, want %d", i, n, bufs[i].Len())
   126  			}
   127  		}()
   128  	}
   129  	wg.Wait()
   130  
   131  	// Stop tracing.
   132  	if err := fr.Stop(); err != nil {
   133  		t.Fatalf("unexpected error on Stop: %v", err)
   134  	}
   135  
   136  	// Make sure at least one succeeded to write.
   137  	if successes.Load() == 0 {
   138  		t.Fatal("expected at least one success to write a snapshot, got zero")
   139  	}
   140  
   141  	// Validate the traces that came out.
   142  	for i := range bufs {
   143  		buf := &bufs[i]
   144  		if buf.Len() == 0 {
   145  			continue
   146  		}
   147  		testReader(t, buf, testtrace.ExpectSuccess())
   148  	}
   149  }
   150  
   151  func TestFlightRecorder(t *testing.T) {
   152  	testFlightRecorder(t, NewFlightRecorder(), func(snapshot func()) {
   153  		snapshot()
   154  	})
   155  }
   156  
   157  func TestFlightRecorderStartStop(t *testing.T) {
   158  	fr := NewFlightRecorder()
   159  	for i := 0; i < 5; i++ {
   160  		testFlightRecorder(t, fr, func(snapshot func()) {
   161  			snapshot()
   162  		})
   163  	}
   164  }
   165  
   166  func TestFlightRecorderLog(t *testing.T) {
   167  	tr := testFlightRecorder(t, NewFlightRecorder(), func(snapshot func()) {
   168  		trace.Log(context.Background(), "message", "hello")
   169  		snapshot()
   170  	})
   171  
   172  	// Prepare to read the trace snapshot.
   173  	r, err := NewReader(bytes.NewReader(tr))
   174  	if err != nil {
   175  		t.Fatalf("unexpected error creating trace reader: %v", err)
   176  	}
   177  
   178  	// Find the log message in the trace.
   179  	found := false
   180  	for {
   181  		ev, err := r.ReadEvent()
   182  		if err == io.EOF {
   183  			break
   184  		}
   185  		if err != nil {
   186  			t.Fatalf("unexpected error reading trace: %v", err)
   187  		}
   188  		if !found && ev.Kind() == EventLog {
   189  			log := ev.Log()
   190  			found = log.Category == "message" && log.Message == "hello"
   191  		}
   192  	}
   193  	if !found {
   194  		t.Errorf("failed to find expected log message (%q, %q) in snapshot", "message", "hello")
   195  	}
   196  }
   197  
   198  func TestFlightRecorderOneGeneration(t *testing.T) {
   199  	test := func(t *testing.T, fr *FlightRecorder) {
   200  		tr := testFlightRecorder(t, fr, func(snapshot func()) {
   201  			// Sleep to let a few generations pass.
   202  			time.Sleep(3 * time.Second)
   203  			snapshot()
   204  		})
   205  
   206  		// Prepare to read the trace snapshot.
   207  		r, err := NewReader(bytes.NewReader(tr))
   208  		if err != nil {
   209  			t.Fatalf("unexpected error creating trace reader: %v", err)
   210  		}
   211  
   212  		// Make sure there's only exactly one Sync event.
   213  		sync := 0
   214  		for {
   215  			ev, err := r.ReadEvent()
   216  			if err == io.EOF {
   217  				break
   218  			}
   219  			if err != nil {
   220  				t.Fatalf("unexpected error reading trace: %v", err)
   221  			}
   222  			if ev.Kind() == EventSync {
   223  				sync++
   224  			}
   225  		}
   226  		if sync != 1 {
   227  			t.Errorf("expected one sync event, found %d", sync)
   228  		}
   229  	}
   230  	t.Run("SetPeriod", func(t *testing.T) {
   231  		// Set the period to 0 so that we're always throwing away old generations.
   232  		// This should always result in exactly one generation.
   233  		// Note: this is always going to result in taking the second generation
   234  		// flushed, which is the much less useful one. That's OK, because in practice
   235  		// SetPeriod shouldn't ever be called with a value this low.
   236  		fr := NewFlightRecorder()
   237  		fr.SetPeriod(0)
   238  		test(t, fr)
   239  	})
   240  	t.Run("SetSize", func(t *testing.T) {
   241  		// Set the size to 0 so that we're always throwing away old generations.
   242  		// This should always result in exactly one generation.
   243  		// Note: this is always going to result in taking the second generation
   244  		// flushed, which is the much less useful one. That's OK, because in practice
   245  		// SetPeriod shouldn't ever be called with a value this low.
   246  		fr := NewFlightRecorder()
   247  		fr.SetSize(0)
   248  		test(t, fr)
   249  	})
   250  }
   251  
   252  type flightRecorderTestFunc func(snapshot func())
   253  
   254  func testFlightRecorder(t *testing.T, fr *FlightRecorder, f flightRecorderTestFunc) []byte {
   255  	if trace.IsEnabled() {
   256  		t.Skip("cannot run flight recorder tests when tracing is enabled")
   257  	}
   258  
   259  	// Start the flight recorder.
   260  	if err := fr.Start(); err != nil {
   261  		t.Fatalf("unexpected error on Start: %v", err)
   262  	}
   263  
   264  	// Set up snapshot callback.
   265  	var buf bytes.Buffer
   266  	callback := func() {
   267  		n, err := fr.WriteTo(&buf)
   268  		if err != nil {
   269  			t.Errorf("unexpected failure during flight recording: %v", err)
   270  			return
   271  		}
   272  		if n < 16 {
   273  			t.Errorf("expected a trace size of at least 16 bytes, got %d", n)
   274  		}
   275  		if n != buf.Len() {
   276  			t.Errorf("WriteTo result doesn't match trace size: got %d, want %d", n, buf.Len())
   277  		}
   278  	}
   279  
   280  	// Call the test function.
   281  	f(callback)
   282  
   283  	// Stop the flight recorder.
   284  	if err := fr.Stop(); err != nil {
   285  		t.Fatalf("unexpected error on Stop: %v", err)
   286  	}
   287  
   288  	// Get the trace bytes; we don't want to use the Buffer as a Reader directly
   289  	// since we may want to consume this data more than once.
   290  	traceBytes := buf.Bytes()
   291  
   292  	// Parse the trace to make sure it's not broken.
   293  	testReader(t, bytes.NewReader(traceBytes), testtrace.ExpectSuccess())
   294  	return traceBytes
   295  }
   296
View as plain text