runtime/trace: dump test traces on validation failure

We currently dump traces for internal/trace tests on validation failure,
but not for the runtime/trace package.

This change moves some of the machinery to do this into the testtrace
package and then uses it from the runtime/trace package.

For #75665.

Change-Id: Ibe2d4f3945c1fd21dcbccf56820865f8d2ea41f9
Reviewed-on: https://go-review.googlesource.com/c/go/+/710755
Reviewed-by: Michael Pratt <mpratt@google.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
This commit is contained in:
Michael Anthony Knyszek 2025-10-09 20:30:18 +00:00 committed by Gopher Robot
parent 7b81a1e107
commit ee4d2c312d
6 changed files with 107 additions and 87 deletions

View file

@ -803,7 +803,7 @@ var depsRules = `
FMT, testing FMT, testing
< internal/cgrouptest; < internal/cgrouptest;
regexp, internal/trace, internal/trace/raw, internal/txtar, testing regexp, internal/testenv, internal/trace, internal/trace/raw, internal/txtar, testing
< internal/trace/testtrace; < internal/trace/testtrace;
C, CGO C, CGO

View file

@ -7,19 +7,14 @@ package trace_test
import ( import (
"bytes" "bytes"
"flag" "flag"
"fmt"
"io" "io"
"os"
"path/filepath" "path/filepath"
"runtime" "runtime"
"strings"
"testing" "testing"
"time" "time"
"internal/trace" "internal/trace"
"internal/trace/raw"
"internal/trace/testtrace" "internal/trace/testtrace"
"internal/trace/version"
) )
var ( var (
@ -131,52 +126,6 @@ func testReader(t *testing.T, tr io.Reader, v *testtrace.Validator, exp *testtra
} }
} }
func dumpTraceToText(t *testing.T, b []byte) string {
t.Helper()
br, err := raw.NewReader(bytes.NewReader(b))
if err != nil {
t.Fatalf("dumping trace: %v", err)
}
var sb strings.Builder
tw, err := raw.NewTextWriter(&sb, version.Current)
if err != nil {
t.Fatalf("dumping trace: %v", err)
}
for {
ev, err := br.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
t.Fatalf("dumping trace: %v", err)
}
if err := tw.WriteEvent(ev); err != nil {
t.Fatalf("dumping trace: %v", err)
}
}
return sb.String()
}
func dumpTraceToFile(t *testing.T, testName string, stress bool, b []byte) string {
t.Helper()
desc := "default"
if stress {
desc = "stress"
}
name := fmt.Sprintf("%s.%s.trace.", testName, desc)
f, err := os.CreateTemp("", name)
if err != nil {
t.Fatalf("creating temp file: %v", err)
}
defer f.Close()
if _, err := io.Copy(f, bytes.NewReader(b)); err != nil {
t.Fatalf("writing trace dump to %q: %v", f.Name(), err)
}
return f.Name()
}
func TestTraceGenSync(t *testing.T) { func TestTraceGenSync(t *testing.T) {
type sync struct { type sync struct {
Time trace.Time Time trace.Time

View file

@ -0,0 +1,87 @@
// 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 testtrace
import (
"bytes"
"fmt"
"internal/testenv"
"internal/trace/raw"
"internal/trace/version"
"io"
"os"
"strings"
"testing"
)
// MustHaveSyscallEvents skips the current test if the current
// platform does not support true system call events.
func Dump(t *testing.T, testName string, traceBytes []byte, forceToFile bool) {
onBuilder := testenv.Builder() != ""
onOldBuilder := !strings.Contains(testenv.Builder(), "gotip") && !strings.Contains(testenv.Builder(), "go1")
if onBuilder && !forceToFile {
// Dump directly to the test log on the builder, since this
// data is critical for debugging and this is the only way
// we can currently make sure it's retained.
s := dumpTraceToText(t, traceBytes)
if onOldBuilder && len(s) > 1<<20+512<<10 {
// The old build infrastructure truncates logs at ~2 MiB.
// Let's assume we're the only failure and give ourselves
// up to 1.5 MiB to dump the trace.
//
// TODO(mknyszek): Remove this when we've migrated off of
// the old infrastructure.
t.Logf("text trace too large to dump (%d bytes)", len(s))
} else {
t.Log(s)
}
} else {
// We asked to dump the trace or failed. Write the trace to a file.
t.Logf("wrote trace to file: %s", dumpTraceToFile(t, testName, traceBytes))
}
}
func dumpTraceToText(t *testing.T, b []byte) string {
t.Helper()
br, err := raw.NewReader(bytes.NewReader(b))
if err != nil {
t.Fatalf("dumping trace: %v", err)
}
var sb strings.Builder
tw, err := raw.NewTextWriter(&sb, version.Current)
if err != nil {
t.Fatalf("dumping trace: %v", err)
}
for {
ev, err := br.ReadEvent()
if err == io.EOF {
break
}
if err != nil {
t.Fatalf("dumping trace: %v", err)
}
if err := tw.WriteEvent(ev); err != nil {
t.Fatalf("dumping trace: %v", err)
}
}
return sb.String()
}
func dumpTraceToFile(t *testing.T, testName string, b []byte) string {
t.Helper()
name := fmt.Sprintf("%s.trace.", testName)
f, err := os.CreateTemp(t.ArtifactDir(), name)
if err != nil {
t.Fatalf("creating temp file: %v", err)
}
defer f.Close()
if _, err := io.Copy(f, bytes.NewReader(b)); err != nil {
t.Fatalf("writing trace dump to %q: %v", f.Name(), err)
}
return f.Name()
}

View file

@ -668,26 +668,14 @@ func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace
} }
// Dump some more information on failure. // Dump some more information on failure.
if t.Failed() && onBuilder { if t.Failed() || *dumpTraces {
// Dump directly to the test log on the builder, since this suffix := func(stress bool) string {
// data is critical for debugging and this is the only way if stress {
// we can currently make sure it's retained. return "stress"
t.Log("found bad trace; dumping to test log...") }
s := dumpTraceToText(t, tb) return "default"
if onOldBuilder && len(s) > 1<<20+512<<10 {
// The old build infrastructure truncates logs at ~2 MiB.
// Let's assume we're the only failure and give ourselves
// up to 1.5 MiB to dump the trace.
//
// TODO(mknyszek): Remove this when we've migrated off of
// the old infrastructure.
t.Logf("text trace too large to dump (%d bytes)", len(s))
} else {
t.Log(s)
} }
} else if t.Failed() || *dumpTraces { testtrace.Dump(t, fmt.Sprintf("%s.%s", testName, suffix(stress)), tb, *dumpTraces)
// We asked to dump the trace or failed. Write the trace to a file.
t.Logf("wrote trace to file: %s", dumpTraceToFile(t, testName, stress, tb))
} }
} }
t.Run("Default", func(t *testing.T) { t.Run("Default", func(t *testing.T) {

View file

@ -119,7 +119,7 @@ func TestFlightRecorderConcurrentWriteTo(t *testing.T) {
if buf.Len() == 0 { if buf.Len() == 0 {
continue continue
} }
testReader(t, buf, testtrace.ExpectSuccess()) testReader(t, buf.Bytes(), testtrace.ExpectSuccess())
} }
} }
@ -260,12 +260,12 @@ func testFlightRecorder(t *testing.T, fr *trace.FlightRecorder, f flightRecorder
traceBytes := buf.Bytes() traceBytes := buf.Bytes()
// Parse the trace to make sure it's not broken. // Parse the trace to make sure it's not broken.
testReader(t, bytes.NewReader(traceBytes), testtrace.ExpectSuccess()) testReader(t, traceBytes, testtrace.ExpectSuccess())
return traceBytes return traceBytes
} }
func testReader(t *testing.T, tr io.Reader, exp *testtrace.Expectation) { func testReader(t *testing.T, tb []byte, exp *testtrace.Expectation) {
r, err := inttrace.NewReader(tr) r, err := inttrace.NewReader(bytes.NewReader(tb))
if err != nil { if err != nil {
if err := exp.Check(err); err != nil { if err := exp.Check(err); err != nil {
t.Error(err) t.Error(err)
@ -292,6 +292,9 @@ func testReader(t *testing.T, tr io.Reader, exp *testtrace.Expectation) {
if err := exp.Check(nil); err != nil { if err := exp.Check(nil); err != nil {
t.Error(err) t.Error(err)
} }
if t.Failed() || *dumpTraces {
testtrace.Dump(t, "trace", tb, *dumpTraces)
}
} }
func TestTraceAndFlightRecorder(t *testing.T) { func TestTraceAndFlightRecorder(t *testing.T) {

View file

@ -7,13 +7,16 @@ package trace_test
import ( import (
"bytes" "bytes"
"flag" "flag"
"os"
. "runtime/trace" . "runtime/trace"
"testing" "testing"
"time" "time"
) )
var saveTraces = flag.Bool("savetraces", false, "save traces collected by tests") var dumpTraces = flag.Bool("dump-traces", false, "dump traces to a file, even on success")
// This file just contains smoke tests and tests of runtime/trace logic only.
// It doesn't validate the resulting traces. See the internal/trace package for
// more comprehensive end-to-end tests.
func TestTraceStartStop(t *testing.T) { func TestTraceStartStop(t *testing.T) {
if IsEnabled() { if IsEnabled() {
@ -32,7 +35,6 @@ func TestTraceStartStop(t *testing.T) {
if size != buf.Len() { if size != buf.Len() {
t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len()) t.Fatalf("trace writes after stop: %v -> %v", size, buf.Len())
} }
saveTrace(t, buf, "TestTraceStartStop")
} }
func TestTraceDoubleStart(t *testing.T) { func TestTraceDoubleStart(t *testing.T) {
@ -50,12 +52,3 @@ func TestTraceDoubleStart(t *testing.T) {
Stop() Stop()
Stop() Stop()
} }
func saveTrace(t *testing.T, buf *bytes.Buffer, name string) {
if !*saveTraces {
return
}
if err := os.WriteFile(name+".trace", buf.Bytes(), 0600); err != nil {
t.Errorf("failed to write trace file: %s", err)
}
}