golang.org/x/exp@v0.0.0-20240506185415-9bf2ced13842/trace/flightrecorder.go (about)

     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
     8  
     9  import (
    10  	"bytes"
    11  	"encoding/binary"
    12  	"errors"
    13  	"fmt"
    14  	"io"
    15  	"math/bits"
    16  	"runtime/trace"
    17  	"slices"
    18  	"sync"
    19  	"time"
    20  	_ "unsafe" // for go:linkname
    21  
    22  	"golang.org/x/exp/trace/internal/event/go122"
    23  )
    24  
    25  // FlightRecorder represents a flight recording configuration.
    26  //
    27  // Flight recording holds execution trace data in a circular buffer representing
    28  // the most recent execution data.
    29  //
    30  // Only one flight recording may be active at any given time.
    31  type FlightRecorder struct {
    32  	err error
    33  
    34  	// State specific to the recorder.
    35  	header [16]byte
    36  	active rawGeneration
    37  	ringMu sync.Mutex
    38  	ring   []rawGeneration
    39  
    40  	// Externally-set options.
    41  	targetSize   int
    42  	targetPeriod time.Duration
    43  
    44  	enabled bool       // whether the flight recorder is enabled.
    45  	writing sync.Mutex // protects concurrent calls to WriteTo
    46  
    47  	// The values of targetSize and targetPeriod we've committed to since the last Start.
    48  	wantSize int
    49  	wantDur  time.Duration
    50  }
    51  
    52  // NewFlightRecorder creates a new flight recording configuration.
    53  func NewFlightRecorder() *FlightRecorder {
    54  	return &FlightRecorder{
    55  		// These are just some optimistic, reasonable defaults.
    56  		//
    57  		// In reality we're also bound by whatever the runtime defaults are, because
    58  		// we currently have no way to change them.
    59  		//
    60  		// TODO(mknyszek): Consider adding a function that allows mutating one or
    61  		// both of these values' equivalents in the runtime.
    62  		targetSize:   10 << 20, // 10 MiB.
    63  		targetPeriod: 10 * time.Second,
    64  	}
    65  }
    66  
    67  // SetPeriod sets the approximate time duration that the flight recorder's circular buffer
    68  // represents.
    69  //
    70  // Note that SetPeriod does not make any guarantees on the amount of time the trace
    71  // produced by WriteTo will represent.
    72  // This is just a hint to the runtime to enable some control the resulting trace.
    73  //
    74  // The initial period is implementation defined, but can be assumed to be on the order
    75  // of seconds.
    76  //
    77  // Adjustments to this value will not apply to an active flight recorder, and will not apply
    78  // if tracing is already enabled via trace.Start. All tracing must be stopped and started
    79  // again to change this value.
    80  func (r *FlightRecorder) SetPeriod(d time.Duration) {
    81  	r.targetPeriod = d
    82  }
    83  
    84  // SetSize sets the approximate size of the flight recorder's circular buffer.
    85  //
    86  // This generally takes precedence over the duration passed to SetPeriod.
    87  // However, it does not make any guarantees on the size of the data WriteTo will write.
    88  // This is just a hint to the runtime to enable some control over the memory overheads
    89  // of tracing.
    90  //
    91  // The initial size is implementation defined.
    92  //
    93  // Adjustments to this value will not apply to an active flight recorder, and will not apply
    94  // if tracing is already enabled via trace.Start. All tracing must be stopped and started
    95  // again to change this value.
    96  func (r *FlightRecorder) SetSize(bytes int) {
    97  	r.targetSize = bytes
    98  }
    99  
   100  // A recorder receives bytes from the runtime tracer, processes it.
   101  type recorder struct {
   102  	r *FlightRecorder
   103  
   104  	headerReceived bool
   105  }
   106  
   107  func (w *recorder) Write(p []byte) (n int, err error) {
   108  	r := w.r
   109  
   110  	defer func() {
   111  		if err != nil {
   112  			// Propagate errors to the flightrecorder.
   113  			if r.err == nil {
   114  				r.err = err
   115  			}
   116  			trace.Stop() // Stop the tracer, preventing further writes.
   117  		}
   118  	}()
   119  
   120  	rd := bytes.NewReader(p)
   121  
   122  	if !w.headerReceived {
   123  		if len(p) < len(r.header) {
   124  			return 0, fmt.Errorf("expected at least %d bytes in the first write", len(r.header))
   125  		}
   126  		rd.Read(r.header[:])
   127  		w.headerReceived = true
   128  	}
   129  
   130  	b, gen, err := readBatch(rd) // Every write from the runtime is guaranteed to be a complete batch.
   131  	if err == io.EOF {
   132  		if rd.Len() > 0 {
   133  			return len(p) - rd.Len(), errors.New("short read")
   134  		}
   135  		return len(p), nil
   136  	}
   137  	if err != nil {
   138  		return len(p) - rd.Len(), err
   139  	}
   140  
   141  	// Check if we're entering a new generation.
   142  	if r.active.gen != 0 && r.active.gen+1 == gen {
   143  		r.ringMu.Lock()
   144  
   145  		// Validate r.active.freq before we use it. It's required for a generation
   146  		// to not be considered broken, and without it, we can't correctly handle
   147  		// SetPeriod.
   148  		if r.active.freq == 0 {
   149  			return len(p) - rd.Len(), fmt.Errorf("broken trace: failed to find frequency event in generation %d", r.active.gen)
   150  		}
   151  
   152  		// Get the current trace clock time.
   153  		now := traceTimeNow(r.active.freq)
   154  
   155  		// Add the current generation to the ring. Make sure we always have at least one
   156  		// complete generation by putting the active generation onto the new list, regardless
   157  		// of whatever our settings are.
   158  		//
   159  		// N.B. Let's completely replace the ring here, so that WriteTo can just make a copy
   160  		// and not worry about aliasing. This creates allocations, but at a very low rate.
   161  		newRing := []rawGeneration{r.active}
   162  		size := r.active.size
   163  		for i := len(r.ring) - 1; i >= 0; i-- {
   164  			// Stop adding older generations if the new ring already exceeds the thresholds.
   165  			// This ensures we keep generations that cross a threshold, but not any that lie
   166  			// entirely outside it.
   167  			if size > r.wantSize || now.Sub(newRing[len(newRing)-1].minTraceTime()) > r.wantDur {
   168  				break
   169  			}
   170  			size += r.ring[i].size
   171  			newRing = append(newRing, r.ring[i])
   172  		}
   173  		slices.Reverse(newRing)
   174  		r.ring = newRing
   175  		r.ringMu.Unlock()
   176  
   177  		// Start a new active generation.
   178  		r.active = rawGeneration{}
   179  	}
   180  
   181  	// Obtain the frequency if this is a frequency batch.
   182  	if b.isFreqBatch() {
   183  		freq, err := parseFreq(b)
   184  		if err != nil {
   185  			return len(p) - rd.Len(), err
   186  		}
   187  		r.active.freq = freq
   188  	}
   189  
   190  	// Append the batch to the current generation.
   191  	if r.active.gen == 0 {
   192  		r.active.gen = gen
   193  	}
   194  	if r.active.minTime == 0 || r.active.minTime > b.time {
   195  		r.active.minTime = b.time
   196  	}
   197  	r.active.size += 1
   198  	r.active.size += uvarintSize(gen)
   199  	r.active.size += uvarintSize(uint64(b.m))
   200  	r.active.size += uvarintSize(uint64(b.time))
   201  	r.active.size += uvarintSize(uint64(len(b.data)))
   202  	r.active.size += len(b.data)
   203  	r.active.batches = append(r.active.batches, b)
   204  
   205  	return len(p) - rd.Len(), nil
   206  }
   207  
   208  // Start begins flight recording. Only one flight recorder or one call to [runtime/trace.Start]
   209  // may be active at any given time. Returns an error if starting the flight recorder would
   210  // violate this rule.
   211  func (r *FlightRecorder) Start() error {
   212  	if r.enabled {
   213  		return fmt.Errorf("cannot enable a enabled flight recorder")
   214  	}
   215  
   216  	r.wantSize = r.targetSize
   217  	r.wantDur = r.targetPeriod
   218  	r.err = nil
   219  
   220  	// Start tracing, data is sent to a recorder which forwards it to our own
   221  	// storage.
   222  	if err := trace.Start(&recorder{r: r}); err != nil {
   223  		return err
   224  	}
   225  
   226  	r.enabled = true
   227  	return nil
   228  }
   229  
   230  // Stop ends flight recording. It waits until any concurrent [FlightRecorder.WriteTo] calls exit.
   231  // Returns an error if the flight recorder is inactive.
   232  func (r *FlightRecorder) Stop() error {
   233  	if !r.enabled {
   234  		return fmt.Errorf("cannot disable a disabled flight recorder")
   235  	}
   236  	r.enabled = false
   237  	trace.Stop()
   238  
   239  	// Reset all state. No need to lock because the reader has already exited.
   240  	r.active = rawGeneration{}
   241  	r.ring = nil
   242  	return r.err
   243  }
   244  
   245  // Enabled returns true if the flight recorder is active. Specifically, it will return true if
   246  // Start did not return an error, and Stop has not yet been called.
   247  // It is safe to call from multiple goroutines simultaneously.
   248  func (r *FlightRecorder) Enabled() bool {
   249  	return r.enabled
   250  }
   251  
   252  // ErrSnapshotActive indicates that a call to WriteTo was made while one was already in progress.
   253  // If the caller of WriteTo sees this error, they should use the result from the other call to WriteTo.
   254  var ErrSnapshotActive = fmt.Errorf("call to WriteTo for trace.FlightRecorder already in progress")
   255  
   256  // WriteTo takes a snapshots of the circular buffer's contents and writes the execution data to w.
   257  // Returns the number of bytes written and an error.
   258  // An error is returned upon failure to write to w or if the flight recorder is inactive.
   259  // Only one goroutine may execute WriteTo at a time, but it is safe to call from multiple goroutines.
   260  // If a goroutine calls WriteTo while another goroutine is currently executing it, WriteTo will return
   261  // ErrSnapshotActive to that goroutine.
   262  func (r *FlightRecorder) WriteTo(w io.Writer) (total int, err error) {
   263  	if !r.enabled {
   264  		return 0, fmt.Errorf("cannot snapshot a disabled flight recorder")
   265  	}
   266  	if !r.writing.TryLock() {
   267  		return 0, ErrSnapshotActive
   268  	}
   269  	defer r.writing.Unlock()
   270  
   271  	// Force a global buffer flush twice.
   272  	//
   273  	// This is pretty unfortunate, but because the signal that a generation is done is that a new
   274  	// generation appears in the trace *or* the trace stream ends, the recorder goroutine will
   275  	// have no idea when to add a generation to the ring if we just flush once. If we flush twice,
   276  	// at least the first one will end up on the ring, which is the one we wanted anyway.
   277  	//
   278  	// In a runtime-internal implementation this is a non-issue. The runtime is fully aware
   279  	// of what generations are complete, so only one flush is necessary.
   280  	runtime_traceAdvance(false)
   281  	runtime_traceAdvance(false)
   282  
   283  	// Now that everything has been flushed and written, grab whatever we have.
   284  	//
   285  	// N.B. traceAdvance blocks until the tracer goroutine has actually written everything
   286  	// out, which means the generation we just flushed must have been already been observed
   287  	// by the recorder goroutine. Because we flushed twice, the first flush is guaranteed to
   288  	// have been both completed *and* processed by the recorder goroutine.
   289  	r.ringMu.Lock()
   290  	gens := r.ring
   291  	r.ringMu.Unlock()
   292  
   293  	// Write the header.
   294  	total, err = w.Write(r.header[:])
   295  	if err != nil {
   296  		return total, err
   297  	}
   298  
   299  	// Helper for writing varints.
   300  	var varintBuf [binary.MaxVarintLen64]byte
   301  	writeUvarint := func(u uint64) error {
   302  		v := binary.PutUvarint(varintBuf[:], u)
   303  		n, err := w.Write(varintBuf[:v])
   304  		total += n
   305  		return err
   306  	}
   307  
   308  	// Write all the data.
   309  	for _, gen := range gens {
   310  		for _, batch := range gen.batches {
   311  			// Rewrite the batch header event with four arguments: gen, M ID, timestamp, and data length.
   312  			n, err := w.Write([]byte{byte(go122.EvEventBatch)})
   313  			total += n
   314  			if err != nil {
   315  				return total, err
   316  			}
   317  			if err := writeUvarint(gen.gen); err != nil {
   318  				return total, err
   319  			}
   320  			if err := writeUvarint(uint64(batch.m)); err != nil {
   321  				return total, err
   322  			}
   323  			if err := writeUvarint(uint64(batch.time)); err != nil {
   324  				return total, err
   325  			}
   326  			if err := writeUvarint(uint64(len(batch.data))); err != nil {
   327  				return total, err
   328  			}
   329  
   330  			// Write batch data.
   331  			n, err = w.Write(batch.data)
   332  			total += n
   333  			if err != nil {
   334  				return total, err
   335  			}
   336  		}
   337  	}
   338  	return total, nil
   339  }
   340  
   341  type rawGeneration struct {
   342  	gen     uint64
   343  	size    int
   344  	minTime timestamp
   345  	freq    frequency
   346  	batches []batch
   347  }
   348  
   349  func (r *rawGeneration) minTraceTime() Time {
   350  	return r.freq.mul(r.minTime)
   351  }
   352  
   353  func traceTimeNow(freq frequency) Time {
   354  	// TODO(mknyszek): It's unfortunate that we have to rely on runtime-internal details
   355  	// like this. This would be better off in the runtime.
   356  	return freq.mul(timestamp(runtime_traceClockNow()))
   357  }
   358  
   359  func uvarintSize(x uint64) int {
   360  	return 1 + bits.Len64(x)/7
   361  }
   362  
   363  //go:linkname runtime_traceAdvance runtime.traceAdvance
   364  func runtime_traceAdvance(stopTrace bool)
   365  
   366  //go:linkname runtime_traceClockNow runtime.traceClockNow
   367  func runtime_traceClockNow() int64