runtime: add traceallocfree GODEBUG for alloc/free events in traces

This change adds expensive alloc/free events to traces, guarded by a
GODEBUG that can be set at run time by mutating the GODEBUG environment
variable. This supersedes the alloc/free trace deleted in a previous CL.

There are two parts to this CL.

The first part is adding a mechanism for exposing experimental events
through the tracer and trace parser. This boils down to a new
ExperimentalEvent event type in the parser API which simply reveals the
raw event data for the event. Each experimental event can also be
associated with "experimental data" which is associated with a
particular generation. This experimental data is just exposed as a bag
of bytes that supplements the experimental events.

In the runtime, this CL organizes experimental events by experiment.
An experiment is defined by a set of experimental events and a single
special batch type. Batches of this special type are exposed through the
parser's API as the aforementioned "experimental data".

The second part of this CL is defining the AllocFree experiment, which
defines 9 new experimental events covering heap object alloc/frees, span
alloc/frees, and goroutine stack alloc/frees. It also generates special
batches that contain a type table: a mapping of IDs to type information.

Change-Id: I965c00e3dcfdf5570f365ff89d0f70d8aeca219c
Reviewed-on: https://go-review.googlesource.com/c/go/+/583377
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>

8 files changed, 271 insertions, 21 deletions

diff --git a/src/internal/trace/v2/base.go b/src/internal/trace/v2/base.go
index bcc4414936..31e3c70f66 100644
--- a/src/internal/trace/v2/base.go
+++ b/src/internal/trace/v2/base.go
@@ -61,6 +61,10 @@ type evTable struct {
 	extraStrings   []string
 	extraStringIDs map[string]extraStringID
 	nextExtra      extraStringID
+
+	// expData contains extra unparsed data that is accessible
+	// only to ExperimentEvent via an EventExperimental event.
+	expData map[event.Experiment]*ExperimentalData
 }
 
 // addExtraString adds an extra string to the evTable and returns
diff --git a/src/internal/trace/v2/batch.go b/src/internal/trace/v2/batch.go
index d7afc06eec..57c230fe02 100644
--- a/src/internal/trace/v2/batch.go
+++ b/src/internal/trace/v2/batch.go
@@ -23,22 +23,23 @@ type batch struct {
 	m    ThreadID
 	time timestamp
 	data []byte
+	exp  event.Experiment
 }
 
 func (b *batch) isStringsBatch() bool {
-	return len(b.data) > 0 && event.Type(b.data[0]) == go122.EvStrings
+	return b.exp == event.NoExperiment && len(b.data) > 0 && event.Type(b.data[0]) == go122.EvStrings
 }
 
 func (b *batch) isStacksBatch() bool {
-	return len(b.data) > 0 && event.Type(b.data[0]) == go122.EvStacks
+	return b.exp == event.NoExperiment && len(b.data) > 0 && event.Type(b.data[0]) == go122.EvStacks
 }
 
 func (b *batch) isCPUSamplesBatch() bool {
-	return len(b.data) > 0 && event.Type(b.data[0]) == go122.EvCPUSamples
+	return b.exp == event.NoExperiment && len(b.data) > 0 && event.Type(b.data[0]) == go122.EvCPUSamples
 }
 
 func (b *batch) isFreqBatch() bool {
-	return len(b.data) > 0 && event.Type(b.data[0]) == go122.EvFrequency
+	return b.exp == event.NoExperiment && len(b.data) > 0 && event.Type(b.data[0]) == go122.EvFrequency
 }
 
 // readBatch reads the next full batch from r.
@@ -51,8 +52,18 @@ func readBatch(r interface {
 	if err != nil {
 		return batch{}, 0, err
 	}
-	if typ := event.Type(b); typ != go122.EvEventBatch {
-		return batch{}, 0, fmt.Errorf("expected batch event (%s), got %s", go122.EventString(go122.EvEventBatch), go122.EventString(typ))
+	if typ := event.Type(b); typ != go122.EvEventBatch && typ != go122.EvExperimentalBatch {
+		return batch{}, 0, fmt.Errorf("expected batch event, got %s", go122.EventString(typ))
+	}
+
+	// Read the experiment of we have one.
+	exp := event.NoExperiment
+	if event.Type(b) == go122.EvExperimentalBatch {
+		e, err := r.ReadByte()
+		if err != nil {
+			return batch{}, 0, err
+		}
+		exp = event.Experiment(e)
 	}
 
 	// Read the batch header: gen (generation), thread (M) ID, base timestamp
@@ -95,5 +106,6 @@ func readBatch(r interface {
 		m:    ThreadID(m),
 		time: timestamp(ts),
 		data: data.Bytes(),
+		exp:  exp,
 	}, gen, nil
 }
diff --git a/src/internal/trace/v2/event.go b/src/internal/trace/v2/event.go
index a1eb220dbd..c58d3bcba2 100644
--- a/src/internal/trace/v2/event.go
+++ b/src/internal/trace/v2/event.go
@@ -76,8 +76,13 @@ const (
 	// EventLog represents a runtime/trace.Log call.
 	EventLog
 
-	// Transitions in state for some resource.
+	// EventStateTransition represents a state change for some resource.
 	EventStateTransition
+
+	// EventExperimental is an experimental event that is unvalidated and exposed in a raw form.
+	// Users are expected to understand the format and perform their own validation. These events
+	// may always be safely ignored.
+	EventExperimental
 )
 
 // String returns a string form of the EventKind.
@@ -103,6 +108,7 @@ var eventKindStrings = [...]string{
 	EventRegionEnd:       "RegionEnd",
 	EventLog:             "Log",
 	EventStateTransition: "StateTransition",
+	EventExperimental:    "Experimental",
 }
 
 const maxTime = Time(math.MaxInt64)
@@ -300,6 +306,42 @@ type StackFrame struct {
 	Line uint64
 }
 
+// ExperimentalEvent presents a raw view of an experimental event's arguments and thier names.
+type ExperimentalEvent struct {
+	// Name is the name of the event.
+	Name string
+
+	// ArgNames is the names of the event's arguments in order.
+	// This may refer to a globally shared slice. Copy before mutating.
+	ArgNames []string
+
+	// Args contains the event's arguments.
+	Args []uint64
+
+	// Data is additional unparsed data that is associated with the experimental event.
+	// Data is likely to be shared across many ExperimentalEvents, so callers that parse
+	// Data are encouraged to cache the parse result and look it up by the value of Data.
+	Data *ExperimentalData
+}
+
+// ExperimentalData represents some raw and unparsed sidecar data present in the trace that is
+// associated with certain kinds of experimental events. For example, this data may contain
+// tables needed to interpret ExperimentalEvent arguments, or the ExperimentEvent could just be
+// a placeholder for a differently encoded event that's actually present in the experimental data.
+type ExperimentalData struct {
+	// Batches contain the actual experimental data, along with metadata about each batch.
+	Batches []ExperimentalBatch
+}
+
+// ExperimentalBatch represents a packet of unparsed data along with metadata about that packet.
+type ExperimentalBatch struct {
+	// Thread is the ID of the thread that produced a packet of data.
+	Thread ThreadID
+
+	// Data is a packet of unparsed data all produced by one thread.
+	Data []byte
+}
+
 // Event represents a single event in the trace.
 type Event struct {
 	table *evTable
@@ -613,6 +655,23 @@ func (e Event) StateTransition() StateTransition {
 	return s
 }
 
+// Experimental returns a view of the raw event for an experimental event.
+//
+// Panics if Kind != EventExperimental.
+func (e Event) Experimental() ExperimentalEvent {
+	if e.Kind() != EventExperimental {
+		panic("Experimental called on non-Experimental event")
+	}
+	spec := go122.Specs()[e.base.typ]
+	argNames := spec.Args[1:]
+	return ExperimentalEvent{
+		Name:     spec.Name,
+		ArgNames: argNames, // Skip timestamp; already handled.
+		Args:     e.base.args[1 : 1+len(argNames)],
+		Data:     e.table.expData[spec.Experiment],
+	}
+}
+
 const evSync = ^event.Type(0)
 
 var go122Type2Kind = [...]EventKind{
@@ -657,6 +716,15 @@ var go122Type2Kind = [...]EventKind{
 	go122.EvGoSwitchDestroy:     EventStateTransition,
 	go122.EvGoCreateBlocked:     EventStateTransition,
 	go122.EvGoStatusStack:       EventStateTransition,
+	go122.EvSpan:                EventExperimental,
+	go122.EvSpanAlloc:           EventExperimental,
+	go122.EvSpanFree:            EventExperimental,
+	go122.EvHeapObject:          EventExperimental,
+	go122.EvHeapObjectAlloc:     EventExperimental,
+	go122.EvHeapObjectFree:      EventExperimental,
+	go122.EvGoroutineStack:      EventExperimental,
+	go122.EvGoroutineStackAlloc: EventExperimental,
+	go122.EvGoroutineStackFree:  EventExperimental,
 	evSync:                      EventSync,
 }
 
@@ -733,6 +801,9 @@ func (e Event) String() string {
 				return true
 			})
 		}
+	case EventExperimental:
+		r := e.Experimental()
+		fmt.Fprintf(&sb, " Name=%s ArgNames=%v Args=%v", r.Name, r.ArgNames, r.Args)
 	}
 	if stk := e.Stack(); stk != NoStack {
 		fmt.Fprintln(&sb)
diff --git a/src/internal/trace/v2/event/event.go b/src/internal/trace/v2/event/event.go
index 111dde604c..adcb8811d8 100644
--- a/src/internal/trace/v2/event/event.go
+++ b/src/internal/trace/v2/event/event.go
@@ -28,6 +28,15 @@ type Spec struct {
 	// in the ArgTypes variable.
 	Args []string
 
+	// StringIDs indicates which of the arguments are string IDs.
+	StringIDs []int
+
+	// StackIDs indicates which of the arguments are stack IDs.
+	//
+	// The list is not sorted. The first index always refers to
+	// the main stack for the current execution context of the event.
+	StackIDs []int
+
 	// StartEv indicates the event type of the corresponding "start"
 	// event, if this event is an "end," for a pair of events that
 	// represent a time range.
@@ -44,16 +53,9 @@ type Spec struct {
 
 	// HasData is true if the event has trailer consisting of a
 	// varint length followed by unencoded bytes of some data.
-	HasData bool
-
-	// StringIDs indicates which of the arguments are string IDs.
-	StringIDs []int
-
-	// StackIDs indicates which of the arguments are stack IDs.
 	//
-	// The list is not sorted. The first index always refers to
-	// the main stack for the current execution context of the event.
-	StackIDs []int
+	// An event may not be both a timed event and have data.
+	HasData bool
 
 	// IsStack indicates that the event represents a complete
 	// stack trace. Specifically, it means that after the arguments
@@ -61,6 +63,11 @@ type Spec struct {
 	// group of 4 represents the PC, file ID, func ID, and line number
 	// in that order.
 	IsStack bool
+
+	// Experiment indicates the ID of an experiment this event is associated
+	// with. If Experiment is not NoExperiment, then the event is experimental
+	// and will be exposed as an EventExperiment.
+	Experiment Experiment
 }
 
 // ArgTypes is a list of valid argument types for use in Args.
@@ -87,3 +94,9 @@ func Names(specs []Spec) map[string]Type {
 	}
 	return nameToType
 }
+
+// Experiment is an experiment ID that events may be associated with.
+type Experiment uint
+
+// NoExperiment is the reserved ID 0 indicating no experiment.
+const NoExperiment Experiment = 0
diff --git a/src/internal/trace/v2/event/go122/event.go b/src/internal/trace/v2/event/go122/event.go
index 5bb9bf1837..df25bfc318 100644
--- a/src/internal/trace/v2/event/go122/event.go
+++ b/src/internal/trace/v2/event/go122/event.go
@@ -73,8 +73,39 @@ const (
 	EvGoSwitchDestroy // goroutine switch and destroy [timestamp, goroutine ID, goroutine seq]
 	EvGoCreateBlocked // goroutine creation (starts blocked) [timestamp, new goroutine ID, new stack ID, stack ID]
 
-	// GoStatus with stack.
+	// GoStatus with stack. Added in Go 1.23.
 	EvGoStatusStack // goroutine status at the start of a generation, with a stack [timestamp, goroutine ID, M ID, status, stack ID]
+
+	// Batch event for an experimental batch with a custom format. Added in Go 1.23.
+	EvExperimentalBatch // start of extra data [experiment ID, generation, M ID, timestamp, batch length, batch data...]
+)
+
+// Experiments.
+const (
+	// AllocFree is the alloc-free events experiment.
+	AllocFree event.Experiment = 1 + iota
+)
+
+// Experimental events.
+const (
+	_ event.Type = 127 + iota
+
+	// Experimental events for AllocFree.
+
+	// Experimental heap span events. Added in Go 1.23.
+	EvSpan      // heap span exists [timestamp, id, npages, type/class]
+	EvSpanAlloc // heap span alloc [timestamp, id, npages, type/class]
+	EvSpanFree  // heap span free [timestamp, id]
+
+	// Experimental heap object events. Added in Go 1.23.
+	EvHeapObject      // heap object exists [timestamp, id, type]
+	EvHeapObjectAlloc // heap object alloc [timestamp, id, type]
+	EvHeapObjectFree  // heap object free [timestamp, id]
+
+	// Experimental goroutine stack events. Added in Go 1.23.
+	EvGoroutineStack      // stack exists [timestamp, id, order]
+	EvGoroutineStackAlloc // stack alloc [timestamp, id, order]
+	EvGoroutineStackFree  // stack free [timestamp, id]
 )
 
 // EventString returns the name of a Go 1.22 event.
@@ -125,6 +156,11 @@ var specs = [...]event.Spec{
 		Name: "Frequency",
 		Args: []string{"freq"},
 	},
+	EvExperimentalBatch: event.Spec{
+		Name:    "ExperimentalBatch",
+		Args:    []string{"exp", "gen", "m", "time"},
+		HasData: true, // Easier to represent for raw readers.
+	},
 
 	// "Timed" Events.
 	EvProcsChange: event.Spec{
@@ -362,6 +398,63 @@ var specs = [...]event.Spec{
 		IsTimedEvent: true,
 		StackIDs:     []int{4},
 	},
+
+	// Experimental events.
+
+	EvSpan: event.Spec{
+		Name:         "Span",
+		Args:         []string{"dt", "id", "npages_value", "kindclass"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvSpanAlloc: event.Spec{
+		Name:         "SpanAlloc",
+		Args:         []string{"dt", "id", "npages_value", "kindclass"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvSpanFree: event.Spec{
+		Name:         "SpanFree",
+		Args:         []string{"dt", "id"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvHeapObject: event.Spec{
+		Name:         "HeapObject",
+		Args:         []string{"dt", "id", "type"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvHeapObjectAlloc: event.Spec{
+		Name:         "HeapObjectAlloc",
+		Args:         []string{"dt", "id", "type"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvHeapObjectFree: event.Spec{
+		Name:         "HeapObjectFree",
+		Args:         []string{"dt", "id"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvGoroutineStack: event.Spec{
+		Name:         "GoroutineStack",
+		Args:         []string{"dt", "id", "order"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvGoroutineStackAlloc: event.Spec{
+		Name:         "GoroutineStackAlloc",
+		Args:         []string{"dt", "id", "order"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
+	EvGoroutineStackFree: event.Spec{
+		Name:         "GoroutineStackFree",
+		Args:         []string{"dt", "id"},
+		IsTimedEvent: true,
+		Experiment:   AllocFree,
+	},
 }
 
 type GoStatus uint8
diff --git a/src/internal/trace/v2/generation.go b/src/internal/trace/v2/generation.go
index 34ea4a147b..c6f1568179 100644
--- a/src/internal/trace/v2/generation.go
+++ b/src/internal/trace/v2/generation.go
@@ -150,6 +150,10 @@ func processBatch(g *generation, b batch) error {
 			return fmt.Errorf("found multiple frequency events")
 		}
 		g.freq = freq
+	case b.exp != event.NoExperiment:
+		if err := addExperimentalData(g.expData, b); err != nil {
+			return err
+		}
 	default:
 		g.batches[b.m] = append(g.batches[b.m], b)
 	}
@@ -412,3 +416,20 @@ func parseFreq(b batch) (frequency, error) {
 	// Convert to nanoseconds per timestamp unit.
 	return frequency(1.0 / (float64(f) / 1e9)), nil
 }
+
+// addExperimentalData takes an experimental batch and adds it to the ExperimentalData
+// for the experiment its a part of.
+func addExperimentalData(expData map[event.Experiment]*ExperimentalData, b batch) error {
+	if b.exp == event.NoExperiment {
+		return fmt.Errorf("internal error: addExperimentalData called on non-experimental batch")
+	}
+	ed, ok := expData[b.exp]
+	if !ok {
+		ed = new(ExperimentalData)
+	}
+	ed.Batches = append(ed.Batches, ExperimentalBatch{
+		Thread: b.m,
+		Data:   b.data,
+	})
+	return nil
+}
diff --git a/src/internal/trace/v2/order.go b/src/internal/trace/v2/order.go
index b2aa551455..3d201513eb 100644
--- a/src/internal/trace/v2/order.go
+++ b/src/internal/trace/v2/order.go
@@ -143,6 +143,23 @@ var orderingDispatch = [256]orderingHandleFunc{
 
 	// GoStatus event with a stack. Added in Go 1.23.
 	go122.EvGoStatusStack: (*ordering).advanceGoStatus,
+
+	// Experimental events.
+
+	// Experimental heap span events. Added in Go 1.23.
+	go122.EvSpan:      (*ordering).advanceAllocFree,
+	go122.EvSpanAlloc: (*ordering).advanceAllocFree,
+	go122.EvSpanFree:  (*ordering).advanceAllocFree,
+
+	// Experimental heap object events. Added in Go 1.23.
+	go122.EvHeapObject:      (*ordering).advanceAllocFree,
+	go122.EvHeapObjectAlloc: (*ordering).advanceAllocFree,
+	go122.EvHeapObjectFree:  (*ordering).advanceAllocFree,
+
+	// Experimental goroutine stack events. Added in Go 1.23.
+	go122.EvGoroutineStack:      (*ordering).advanceAllocFree,
+	go122.EvGoroutineStackAlloc: (*ordering).advanceAllocFree,
+	go122.EvGoroutineStackFree:  (*ordering).advanceAllocFree,
 }
 
 func (o *ordering) advanceProcStatus(ev *baseEvent, evt *evTable, m ThreadID, gen uint64, curCtx schedCtx) (schedCtx, bool, error) {
@@ -1058,6 +1075,15 @@ func (o *ordering) advanceGoRangeEnd(ev *baseEvent, evt *evTable, m ThreadID, ge
 	return curCtx, true, nil
 }
 
+func (o *ordering) advanceAllocFree(ev *baseEvent, evt *evTable, m ThreadID, gen uint64, curCtx schedCtx) (schedCtx, bool, error) {
+	// Handle simple instantaneous events that may or may not have a P.
+	if err := validateCtx(curCtx, event.SchedReqs{Thread: event.MustHave, Proc: event.MayHave, Goroutine: event.MayHave}); err != nil {
+		return curCtx, false, err
+	}
+	o.queue.push(Event{table: evt, ctx: curCtx, base: *ev})
+	return curCtx, true, nil
+}
+
 // Next returns the next event in the ordering.
 func (o *ordering) Next() (Event, bool) {
 	return o.queue.pop()
diff --git a/src/internal/trace/v2/trace_test.go b/src/internal/trace/v2/trace_test.go
index 66707856ef..9b74cc0d81 100644
--- a/src/internal/trace/v2/trace_test.go
+++ b/src/internal/trace/v2/trace_test.go
@@ -544,7 +544,7 @@ func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace
 
 	testPath := filepath.Join("./testdata/testprog", progName)
 	testName := progName
-	runTest := func(t *testing.T, stress bool) {
+	runTest := func(t *testing.T, stress bool, extraGODEBUG string) {
 		// Run the program and capture the trace, which is always written to stdout.
 		cmd := testenv.Command(t, testenv.GoToolPath(t), "run")
 		if race.Enabled {
@@ -558,6 +558,10 @@ func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace
 			// Advance a generation constantly to stress the tracer.
 			godebug += ",traceadvanceperiod=0"
 		}
+		if extraGODEBUG != "" {
+			// Add extra GODEBUG flags.
+			godebug += "," + extraGODEBUG
+		}
 		cmd.Env = append(cmd.Env, "GODEBUG="+godebug)
 
 		// Capture stdout and stderr.
@@ -608,12 +612,18 @@ func testTraceProg(t *testing.T, progName string, extra func(t *testing.T, trace
 		}
 	}
 	t.Run("Default", func(t *testing.T) {
-		runTest(t, false)
+		runTest(t, false, "")
 	})
 	t.Run("Stress", func(t *testing.T) {
 		if testing.Short() {
-			t.Skip("skipping trace reader stress tests in short mode")
+			t.Skip("skipping trace stress tests in short mode")
+		}
+		runTest(t, true, "")
+	})
+	t.Run("AllocFree", func(t *testing.T) {
+		if testing.Short() {
+			t.Skip("skipping trace alloc/free tests in short mode")
 		}
-		runTest(t, true)
+		runTest(t, false, "traceallocfree=1")
 	})
 }