runtime/pprof: add debug=3 goroutine profile with goid and labels

This adds a new goroutine profile debug mode, debug=3.

This mode emits in the same binary proto output format as debug=0, with
the only difference being that it does not aggregate matching
stack/label combinations into a single count, and instead emits a sample
per goroutine with additional synthesized labels to communicate some of
the details of each goroutine, specifically:
  - go::goroutine: the goroutine's ID
  - go::goroutine_created_by: ID of the goroutine's creator (if any)
  - go::goroutine_state: current state of the goroutine (e.g. runnable)
  - go::goroutine_wait_minutes: approximate minutes goroutine has spent
    waiting (if applicable)

These are synthesized as labels, side-by-side with any user-set labels
thus the 'go::' prefix to namespace these synthetic labels somewhat.
We aim to minimize collisions with user-set labels as while the format
does allow for multi-valued labels, meaning a collision would not
immediately overwrite a user-set label, the upstream proto does warn
that not all tools handle multi-valued labels well, so the namespace
prefix aims to avoid them if possible. The form 'go::' is chosen as the
upstream proto reserves 'pprof::', which seems to establish this format
as a convention.

Previously the debug=2 mode was the only way to get this kind of
per-goroutine information that is sometimes vital to understanding the
state of a process. However debug=2 had two major drawbacks:
 1) its collection incurs a potentially lengthy and disruptive
 stop-the-world pause due to it not (and perhaps being unable to)
 utilizing the concurrent collection mechanism used by debug=0/1, and
 2) it does not (currently) include user-set labels in the same profile.

This new mode that uses the same concurrent collection mechanism as 0/1,
with its minimal STW penalty, but also includes the per-goroutine
details that make debug=2 so useful. Changing debug=2, which already
included this per-goroutine detail, in-place to use the concurrent
collection mechanism could avoid introducing a new mode, but it is not
clear that this is possible with breaking changes to its output: debug=2
includes argument _values_ in its output would require collection in
both a concurrent and consistent manner. Thus the use of a new mode
instead.

The difference in service latency observed by running goroutines during
profile collection is demonstrated by BenchmarkGoroutineProfileLatencyImpact:

                       │        debug=2  │                   debug=3             │
                       │ max_latency_ns  │ max_latency_ns  vs base               │
goroutines=100x3-14         422.2k ± 13%   190.3k ±   38%  -54.93% (p=0.002 n=6)
goroutines=100x10-14        619.7k ± 10%   171.1k ±   43%  -72.38% (p=0.002 n=6)
goroutines=100x50-14       1423.6k ±  7%   174.3k ±   44%  -87.76% (p=0.002 n=6)
goroutines=1000x3-14       2424.8k ±  8%   298.6k ±  106%  -87.68% (p=0.002 n=6)
goroutines=1000x10-14      7378.4k ±  2%   268.2k ±  146%  -96.36% (p=0.002 n=6)
goroutines=1000x50-14     23372.5k ± 10%   330.1k ±  173%  -98.59% (p=0.002 n=6)
goroutines=10000x3-14      42.802M ± 47%   1.991M ±  105%  -95.35% (p=0.002 n=6)
goroutines=10000x10-14    36668.2k ± 95%   743.1k ±   72%  -97.97% (p=0.002 n=6)
goroutines=10000x50-14   120639.1k ±  2%   188.2k ± 2582%  -99.84% (p=0.002 n=6)
geomean                     6.760M         326.2k          -95.18%

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,39 +1246,20 @@ 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)
 }
 
 //go:linkname pprof_goroutineLeakProfileWithLabels
-func pprof_goroutineLeakProfileWithLabels(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
-	return goroutineLeakProfileWithLabelsConcurrent(p, labels)
-}
-
-// labels may be nil. If labels is non-nil, it must have the same length as p.
-func goroutineLeakProfileWithLabels(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
-	if labels != nil && len(labels) != len(p) {
-		labels = nil
-	}
-
-	return goroutineLeakProfileWithLabelsConcurrent(p, labels)
+func pprof_goroutineLeakProfileWithLabels(p []profilerecord.GoroutineRecord) (n int, ok bool) {
+	return goroutineLeakProfileInternal(p)
 }
 
 var goroutineProfile = struct {
 	sema    uint32
 	active  bool
 	offset  atomic.Int64
-	records []profilerecord.StackRecord
-	labels  []unsafe.Pointer
+	records []profilerecord.GoroutineRecord
 }{
 	sema: 1,
 }
@@ -1316,18 +1297,18 @@ func (p *goroutineProfileStateHolder) CompareAndSwap(old, new goroutineProfileSt
 	return (*atomic.Uint32)(p).CompareAndSwap(uint32(old), uint32(new))
 }
 
-func goroutineLeakProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
+func goroutineLeakProfileInternal(p []profilerecord.GoroutineRecord) (n int, ok bool) {
 	if len(p) == 0 {
 		// An empty slice is obviously too small. Return a rough
 		// allocation estimate.
 		return work.goroutineLeak.count, false
 	}
 
-	// Use the same semaphore as goroutineProfileWithLabelsConcurrent,
+	// Use the same semaphore as goroutineProfileInternal,
 	// because ultimately we still use goroutine profiles.
 	semacquire(&goroutineProfile.sema)
 
-	// Unlike in goroutineProfileWithLabelsConcurrent, we don't need to
+	// Unlike in goroutineProfileInternal, we don't need to
 	// save the current goroutine stack, because it is obviously not leaked.
 
 	pcbuf := makeProfStack() // see saveg() for explanation
@@ -1358,7 +1339,7 @@ func goroutineLeakProfileWithLabelsConcurrent(p []profilerecord.StackRecord, lab
 	return n, true
 }
 
-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
@@ -1401,9 +1382,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)
 
@@ -1414,7 +1401,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.
@@ -1436,7 +1422,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
@@ -1528,7 +1513,7 @@ func doRecordGoroutineProfile(gp1 *g, pcbuf []uintptr) {
 		// System goroutines should not appear in the profile.
 		// Check this here and not in tryRecordGoroutineProfile because isSystemGoroutine
 		// may change on a goroutine while it is executing, so while the scheduler might
-		// see a system goroutine, goroutineProfileWithLabelsConcurrent might not, and
+		// see a system goroutine, goroutineProfileInternal might not, and
 		// this inconsistency could cause invariants to be violated, such as trying to
 		// record the stack of a running goroutine below. In short, we still want system
 		// goroutines to participate in the same state machine on gp1.goroutineProfiled as
@@ -1545,7 +1530,7 @@ func doRecordGoroutineProfile(gp1 *g, pcbuf []uintptr) {
 	if offset >= len(goroutineProfile.records) {
 		// Should be impossible, but better to return a truncated profile than
 		// to crash the entire process at this point. Instead, deal with it in
-		// goroutineProfileWithLabelsConcurrent where we have more context.
+		// goroutineProfileInternal where we have more context.
 		return
 	}
 
@@ -1559,79 +1544,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.
@@ -1641,7 +1560,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
@@ -1653,11 +1572,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