runtime/trace: add a trace validation test for different trace orders

This adds a test which validates the traces generated by the execution
tracer and the flight recorder depending on the order where they are
stopped and started. This test uncovered that under certain
circumstances, the traces which were produced would possibly be
missing the trace header. All traces have the trace headers included
now. Clock snapshot checks have been disabled for Windows and WASM.

Change-Id: I5be719d228300469891fc56817fbce4ba5453fff
Reviewed-on: https://go-review.googlesource.com/c/go/+/675975
Auto-Submit: Carlos Amedee <carlos@golang.org>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Michael Knyszek <mknyszek@google.com>
This commit is contained in:
Carlos Amedee 2025-05-23 16:41:51 -04:00 committed by Gopher Robot
parent 0e1b14bc2e
commit c8c3d661b0
2 changed files with 170 additions and 0 deletions

View file

@ -155,6 +155,14 @@ func (t *traceMultiplexer) startLocked() error {
t.subscribersMu.Unlock() t.subscribersMu.Unlock()
go func() { go func() {
header := runtime_readTrace()
if traceStartWriter != nil {
traceStartWriter.Write(header)
}
if flightRecorder != nil {
flightRecorder.Write(header)
}
for { for {
data := runtime_readTrace() data := runtime_readTrace()
if data == nil { if data == nil {
@ -167,9 +175,18 @@ func (t *traceMultiplexer) startLocked() error {
// Pick up any changes. // Pick up any changes.
t.subscribersMu.Lock() t.subscribersMu.Lock()
frIsNew := flightRecorder != t.flightRecorder && t.flightRecorder != nil
trIsNew := traceStartWriter != t.traceStartWriter && t.traceStartWriter != nil
flightRecorder = t.flightRecorder flightRecorder = t.flightRecorder
traceStartWriter = t.traceStartWriter traceStartWriter = t.traceStartWriter
t.subscribersMu.Unlock() t.subscribersMu.Unlock()
if trIsNew {
traceStartWriter.Write(header)
}
if frIsNew {
flightRecorder.Write(header)
}
} else { } else {
if traceStartWriter != nil { if traceStartWriter != nil {
traceStartWriter.Write(data) traceStartWriter.Write(data)

View file

@ -0,0 +1,153 @@
// 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"
inttrace "internal/trace"
"internal/trace/testtrace"
"io"
"runtime"
"runtime/trace"
"slices"
"testing"
)
func TestSubscribers(t *testing.T) {
validate := func(t *testing.T, source string, tr io.Reader) {
// Prepare to read the trace snapshot.
r, err := inttrace.NewReader(tr)
if err != nil {
t.Fatalf("unexpected error creating trace reader for %s: %v", source, err)
return
}
v := testtrace.NewValidator()
// These platforms can't guarantee a monotonically increasing clock reading in a short trace.
if runtime.GOOS == "windows" || runtime.GOARCH == "wasm" {
v.SkipClockSnapshotChecks()
}
// 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 for %s: %v", source, err)
}
if err := v.Event(ev); err != nil {
t.Fatalf("event validation failed: %s", err)
}
if ev.Kind() == inttrace.EventSync {
syncs = append(syncs, evs)
}
evs++
}
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 for %s",
ends, wantEnds, source)
}
}
validateTraces := func(t *testing.T, tReader, frReader io.Reader) {
validate(t, "tracer", tReader)
validate(t, "flightRecorder", frReader)
}
startFlightRecorder := func(t *testing.T) *trace.FlightRecorder {
fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{})
if err := fr.Start(); err != nil {
t.Fatalf("unexpected error creating flight recorder: %v", err)
}
return fr
}
startTrace := func(t *testing.T, w io.Writer) {
if err := trace.Start(w); err != nil {
t.Fatalf("unexpected error starting flight recorder: %v", err)
}
}
stopFlightRecorder := func(t *testing.T, fr *trace.FlightRecorder, w io.Writer) {
if _, err := fr.WriteTo(w); err != nil {
t.Fatalf("unexpected error writing trace from flight recorder: %v", err)
}
fr.Stop()
}
stopTrace := func() {
trace.Stop()
}
t.Run("start(flight)_start(trace)_stop(trace)_stop(flight)", func(t *testing.T) {
if trace.IsEnabled() {
t.Skip("skipping because trace is already enabled")
}
frBuf := new(bytes.Buffer)
tBuf := new(bytes.Buffer)
fr := startFlightRecorder(t)
defer fr.Stop()
startTrace(t, tBuf)
defer trace.Stop()
stopTrace()
stopFlightRecorder(t, fr, frBuf)
validateTraces(t, tBuf, frBuf)
})
t.Run("start(trace)_start(flight)_stop(trace)_stop(flight)", func(t *testing.T) {
if trace.IsEnabled() {
t.Skip("skipping because trace is already enabled")
}
frBuf := new(bytes.Buffer)
tBuf := new(bytes.Buffer)
startTrace(t, tBuf)
defer trace.Stop()
fr := startFlightRecorder(t)
defer fr.Stop()
stopTrace()
stopFlightRecorder(t, fr, frBuf)
validateTraces(t, tBuf, frBuf)
})
t.Run("start(flight)_stop(flight)_start(trace)_stop(trace)", func(t *testing.T) {
if trace.IsEnabled() {
t.Skip("skipping because trace is already enabled")
}
frBuf := new(bytes.Buffer)
tBuf := new(bytes.Buffer)
fr := startFlightRecorder(t)
defer fr.Stop()
stopFlightRecorder(t, fr, frBuf)
startTrace(t, tBuf)
defer trace.Stop()
stopTrace()
validateTraces(t, tBuf, frBuf)
})
t.Run("start(flight)_stop(flight)_start(trace)_stop(trace)", func(t *testing.T) {
if trace.IsEnabled() {
t.Skip("skipping because trace is already enabled")
}
frBuf := new(bytes.Buffer)
tBuf := new(bytes.Buffer)
fr := startFlightRecorder(t)
defer fr.Stop()
stopFlightRecorder(t, fr, frBuf)
startTrace(t, tBuf)
defer trace.Stop()
stopTrace()
validateTraces(t, tBuf, frBuf)
})
t.Run("start(flight)_start(trace)_stop(flight)_stop(trace)", func(t *testing.T) {
if trace.IsEnabled() {
t.Skip("skipping because trace is already enabled")
}
frBuf := new(bytes.Buffer)
tBuf := new(bytes.Buffer)
fr := startFlightRecorder(t)
defer fr.Stop()
startTrace(t, tBuf)
defer trace.Stop()
stopFlightRecorder(t, fr, frBuf)
stopTrace()
validateTraces(t, tBuf, frBuf)
})
}