runtime/pprof: add debug=4 goroutine profile with labels and reduced STW

This adds two new goroutine profile modes, debug=3 and debug=4, that
emit in the same output format as debug=0 and debug=1, but contain one
entry per goroutine along with extended per-goroutine information such
as goroutine ID, creator ID, state, wait minutes, and creation location.

Previously the debug=2 mode was the only way to get this per-goroutine
information, however this mode has a significantly different underlying
implementation that mean it a) requires a pontentially lengthy STW pause,
and B) does not include labels.

These new modes make the level of detailed, per-goroutine informaiton
previously only available in debug=2 available in a new format that
also includes labels and does not incur the same duration of stop-the-world
pause during collection.

The difference in latency observed by running goroutines is demonstrated
by the included benchmark:

                       │    debug=2     │          debug=4
                       │ max_latency_ns │ max_latency_ns  vs base
goroutines=100x3-14      1013.17k ± 47%   84.06k ±   27%  -91.70% (p=0.002 n=6)
goroutines=100x10-14      769.23k ±  7%   80.29k ±   22%  -89.56% (p=0.002 n=6)
goroutines=100x50-14      2172.4k ±  9%   181.8k ±   46%  -91.63% (p=0.002 n=6)
goroutines=1000x3-14      7133.9k ±  3%   195.7k ±   42%  -97.26% (p=0.002 n=6)
goroutines=1000x10-14    11787.6k ± 48%   494.4k ±   77%  -95.81% (p=0.002 n=6)
goroutines=1000x50-14    20234.0k ± 87%   174.8k ±  137%  -99.14% (p=0.002 n=6)
goroutines=10000x3-14    68611.0k ± 49%   168.5k ± 2768%  -99.75% (p=0.002 n=6)
goroutines=10000x10-14    60.261M ± 95%   3.460M ±  166%  -94.26% (p=0.002 n=6)
goroutines=10000x50-14   284.144M ± 40%   4.672M ±   89%  -98.36% (p=0.002 n=6)
goroutines=25000x3-14    171.290M ± 48%   4.287M ±  394%  -97.50% (p=0.002 n=6)
goroutines=25000x10-14   150.827M ± 92%   6.424M ±  158%  -95.74% (p=0.002 n=6)
goroutines=25000x50-14   708.238M ± 34%   2.249M ±  410%  -99.68% (p=0.002 n=6)
geomean                    25.08M         624.2k          -97.51%

The new debug=4 format is added a new format rather than altering
debug=2 in-place to use the lower latency collection method as the
concurrent collection method would require some behavior changes to
debug=2 that are likely to significant to be made in place, chriefly
that debug=2 includes argument values in its output, which are not
collected by the concurrent collection method, and are not included in
any other format, and that adding labels to the debug=2 format could
break existing parsers.

Author: dt

src/internal/profilerecord/profilerecord.go

@@ -8,10 +8,16 @@
 // TODO: Consider moving this to internal/runtime, see golang.org/issue/65355.
 package profilerecord
 
+import "unsafe"
+
 type StackRecord struct {
 	Stack []uintptr
 }
 
+func (r StackRecord) GetStack() []uintptr           { return r.Stack }
+func (r StackRecord) GetLabels() unsafe.Pointer     { return nil }
+func (r StackRecord) GetGoroutine() GoroutineRecord { return GoroutineRecord{} }
+
 type MemProfileRecord struct {
 	AllocBytes, FreeBytes     int64
 	AllocObjects, FreeObjects int64
@@ -26,3 +32,18 @@ type BlockProfileRecord struct {
 	Cycles int64
 	Stack  []uintptr
 }
+
+type GoroutineRecord struct {
+	ID         uint64
+	State      uint32
+	WaitReason uint8
+	CreatorID  uint64
+	CreationPC uintptr
+	WaitSince  int64 // approx time when the g became blocked, in nanoseconds
+	Labels     unsafe.Pointer
+	Stack      []uintptr
+}
+
+func (r GoroutineRecord) GetStack() []uintptr           { return r.Stack }
+func (r GoroutineRecord) GetLabels() unsafe.Pointer     { return r.Labels }
+func (r GoroutineRecord) GetGoroutine() GoroutineRecord { return r }

src/runtime/mprof.go

@@ -1246,25 +1246,15 @@ func pprof_threadCreateInternal(p []profilerecord.StackRecord) (n int, ok bool)
 }
 
 //go:linkname pprof_goroutineProfileWithLabels
-func pprof_goroutineProfileWithLabels(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
-	return goroutineProfileWithLabels(p, labels)
-}
-
-// labels may be nil. If labels is non-nil, it must have the same length as p.
-func goroutineProfileWithLabels(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
-	if labels != nil && len(labels) != len(p) {
-		labels = nil
-	}
-
-	return goroutineProfileWithLabelsConcurrent(p, labels)
+func pprof_goroutineProfileWithLabels(p []profilerecord.GoroutineRecord) (n int, ok bool) {
+	return goroutineProfileInternal(p)
 }
 
 var goroutineProfile = struct {
 	sema    uint32
 	active  bool
 	offset  atomic.Int64
-	records []profilerecord.StackRecord
-	labels  []unsafe.Pointer
+	records []profilerecord.GoroutineRecord
 }{
 	sema: 1,
 }
@@ -1302,7 +1292,9 @@ func (p *goroutineProfileStateHolder) CompareAndSwap(old, new goroutineProfileSt
 	return (*atomic.Uint32)(p).CompareAndSwap(uint32(old), uint32(new))
 }
 
-func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
+func goroutineProfileInternal(
+	p []profilerecord.GoroutineRecord,
+) (n int, ok bool) {
 	if len(p) == 0 {
 		// An empty slice is obviously too small. Return a rough
 		// allocation estimate without bothering to STW. As long as
@@ -1345,9 +1337,15 @@ func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels
 	systemstack(func() {
 		saveg(pc, sp, ourg, &p[0], pcbuf)
 	})
-	if labels != nil {
-		labels[0] = ourg.labels
-	}
+
+	p[0].ID = ourg.goid
+	p[0].CreatorID = ourg.parentGoid
+	p[0].CreationPC = ourg.gopc
+	p[0].Labels = ourg.labels
+	p[0].State = readgstatus(ourg) &^ _Gscan
+	p[0].WaitReason = uint8(ourg.waitreason)
+	p[0].WaitSince = ourg.waitsince
+
 	ourg.goroutineProfiled.Store(goroutineProfileSatisfied)
 	goroutineProfile.offset.Store(1)
 
@@ -1358,7 +1356,6 @@ func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels
 	// field set to goroutineProfileSatisfied.
 	goroutineProfile.active = true
 	goroutineProfile.records = p
-	goroutineProfile.labels = labels
 	startTheWorld(stw)
 
 	// Visit each goroutine that existed as of the startTheWorld call above.
@@ -1380,7 +1377,6 @@ func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels
 	endOffset := goroutineProfile.offset.Swap(0)
 	goroutineProfile.active = false
 	goroutineProfile.records = nil
-	goroutineProfile.labels = nil
 	startTheWorld(stw)
 
 	// Restore the invariant that every goroutine struct in allgs has its
@@ -1503,79 +1499,13 @@ func doRecordGoroutineProfile(gp1 *g, pcbuf []uintptr) {
 	// to avoid schedule delays.
 	systemstack(func() { saveg(^uintptr(0), ^uintptr(0), gp1, &goroutineProfile.records[offset], pcbuf) })
 
-	if goroutineProfile.labels != nil {
-		goroutineProfile.labels[offset] = gp1.labels
-	}
-}
-
-func goroutineProfileWithLabelsSync(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
-	gp := getg()
-
-	isOK := func(gp1 *g) bool {
-		// Checking isSystemGoroutine here makes GoroutineProfile
-		// consistent with both NumGoroutine and Stack.
-		return gp1 != gp && readgstatus(gp1) != _Gdead && !isSystemGoroutine(gp1, false)
-	}
-
-	pcbuf := makeProfStack() // see saveg() for explanation
-	stw := stopTheWorld(stwGoroutineProfile)
-
-	// World is stopped, no locking required.
-	n = 1
-	forEachGRace(func(gp1 *g) {
-		if isOK(gp1) {
-			n++
-		}
-	})
-
-	if n <= len(p) {
-		ok = true
-		r, lbl := p, labels
-
-		// Save current goroutine.
-		sp := sys.GetCallerSP()
-		pc := sys.GetCallerPC()
-		systemstack(func() {
-			saveg(pc, sp, gp, &r[0], pcbuf)
-		})
-		r = r[1:]
-
-		// If we have a place to put our goroutine labelmap, insert it there.
-		if labels != nil {
-			lbl[0] = gp.labels
-			lbl = lbl[1:]
-		}
-
-		// Save other goroutines.
-		forEachGRace(func(gp1 *g) {
-			if !isOK(gp1) {
-				return
-			}
-
-			if len(r) == 0 {
-				// Should be impossible, but better to return a
-				// truncated profile than to crash the entire process.
-				return
-			}
-			// saveg calls gentraceback, which may call cgo traceback functions.
-			// The world is stopped, so it cannot use cgocall (which will be
-			// blocked at exitsyscall). Do it on the system stack so it won't
-			// call into the schedular (see traceback.go:cgoContextPCs).
-			systemstack(func() { saveg(^uintptr(0), ^uintptr(0), gp1, &r[0], pcbuf) })
-			if labels != nil {
-				lbl[0] = gp1.labels
-				lbl = lbl[1:]
-			}
-			r = r[1:]
-		})
-	}
-
-	if raceenabled {
-		raceacquire(unsafe.Pointer(&labelSync))
-	}
-
-	startTheWorld(stw)
-	return n, ok
+	goroutineProfile.records[offset].Labels = gp1.labels
+	goroutineProfile.records[offset].ID = gp1.goid
+	goroutineProfile.records[offset].CreatorID = gp1.parentGoid
+	goroutineProfile.records[offset].CreationPC = gp1.gopc
+	goroutineProfile.records[offset].State = readgstatus(gp1) &^ _Gscan
+	goroutineProfile.records[offset].WaitReason = uint8(gp1.waitreason)
+	goroutineProfile.records[offset].WaitSince = gp1.waitsince
 }
 
 // GoroutineProfile returns n, the number of records in the active goroutine stack profile.
@@ -1585,7 +1515,7 @@ func goroutineProfileWithLabelsSync(p []profilerecord.StackRecord, labels []unsa
 // Most clients should use the [runtime/pprof] package instead
 // of calling GoroutineProfile directly.
 func GoroutineProfile(p []StackRecord) (n int, ok bool) {
-	records := make([]profilerecord.StackRecord, len(p))
+	records := make([]profilerecord.GoroutineRecord, len(p))
 	n, ok = goroutineProfileInternal(records)
 	if !ok {
 		return
@@ -1597,11 +1527,7 @@ func GoroutineProfile(p []StackRecord) (n int, ok bool) {
 	return
 }
 
-func goroutineProfileInternal(p []profilerecord.StackRecord) (n int, ok bool) {
-	return goroutineProfileWithLabels(p, nil)
-}
-
-func saveg(pc, sp uintptr, gp *g, r *profilerecord.StackRecord, pcbuf []uintptr) {
+func saveg(pc, sp uintptr, gp *g, r *profilerecord.GoroutineRecord, pcbuf []uintptr) {
 	// To reduce memory usage, we want to allocate a r.Stack that is just big
 	// enough to hold gp's stack trace. Naively we might achieve this by
 	// recording our stack trace into mp.profStack, and then allocating a

src/runtime/pprof/label.go

@@ -42,13 +42,28 @@ type labelMap struct {
 // String satisfies Stringer and returns key, value pairs in a consistent
 // order.
 func (l *labelMap) String() string {
-	if l == nil {
+	return labelsString(l)
+}
+
+func labelsString(l *labelMap, extra ...string) string {
+	if l == nil && len(extra) == 0 {
 		return ""
 	}
-	keyVals := make([]string, 0, len(l.list))
 
-	for _, lbl := range l.list {
-		keyVals = append(keyVals, fmt.Sprintf("%q:%q", lbl.key, lbl.value))
+	length := len(extra)
+	if l != nil {
+		length += len(l.list)
+	}
+	keyVals := make([]string, 0, length)
+
+	if l != nil {
+		for _, lbl := range l.list {
+			keyVals = append(keyVals, fmt.Sprintf("%q:%q", lbl.key, lbl.value))
+		}
+	}
+
+	for i := 0; i < len(extra)-1; i += 2 {
+		keyVals = append(keyVals, fmt.Sprintf("%q:%q", extra[i], extra[i+1]))
 	}
 
 	slices.Sort(keyVals)