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

This adds a new goroutine profile mode (debug=26257) that emits one
entry per goroutine in a format nearly identical to debug=2 that
additionally includes any pprof labels in the  header, following the [state]
segment, e.g:

    goroutine 123 [select, 2 minutes]{"svc": "users"}:

The implementation of this mode is however significantly different from
debug=2, and instead based on the same underlying mechanism as debug=1.
Unlike the collection of debug=2 profiles, which walks all stacks while
the world is stopped, the implementation of this mode uses the
concurrent collection integrated with the scheduler that backs debug=1.
As a result, this new mode reduces the duration of the stop-the-world
phase, particularly when profiling processes with many goroutines,
compared to debug=2, and demonstrated by the included benchmark:

                       │    debug=2     │          debug=26257
                       │ 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%

This concurrent collection approach and its relaxed consistency compared
to keeping the world stopped doesm mean the behavior of this new mode is
not exactly identical to debug=2. Additionally, currently this mode
always elides argument values when printing stacks, whereas debug=2
includes them most of the time. These behavior differences mean that
despite the performance benefits, the new implementation is not used for
the existing debug=2 mode, but rather only for the new mode making it an
opt-in alternative.

Author: dt

src/internal/profilerecord/profilerecord.go

@@ -26,3 +26,11 @@ type BlockProfileRecord struct {
 	Cycles int64
 	Stack  []uintptr
 }
+
+type GoroutineInfo struct {
+	ID         uint64
+	State      string
+	CreatorID  uint64
+	CreationPC uintptr
+	WaitSince  int64  // approx time when the g became blocked, in nanoseconds
+}

src/runtime/mprof.go

@@ -1320,7 +1320,7 @@ func goroutineProfileWithLabels(p []profilerecord.StackRecord, labels []unsafe.P
 		labels = nil
 	}
 
-	return goroutineProfileWithLabelsConcurrent(p, labels)
+	return goroutineProfileWithLabelsConcurrent(p, labels, nil)
 }
 
 var goroutineProfile = struct {
@@ -1329,10 +1329,48 @@ var goroutineProfile = struct {
 	offset  atomic.Int64
 	records []profilerecord.StackRecord
 	labels  []unsafe.Pointer
+	infos   []profilerecord.GoroutineInfo
 }{
 	sema: 1,
 }
 
+// goroutineStatusString converts goroutine status to human-readable string
+// Uses the same logic as goroutineheader() in traceback.go
+func goroutineStatusString(gp1 *g) string {
+	gpstatus := readgstatus(gp1)
+	gpstatus &^= _Gscan // drop the scan bit
+
+	// Basic string status
+	var status string
+	switch gpstatus {
+	case _Gidle:
+		status = "idle"
+	case _Grunnable:
+		status = "runnable"
+	case _Grunning:
+		status = "running"
+	case _Gsyscall:
+		status = "syscall"
+	case _Gwaiting:
+		status = "waiting"
+	case _Gdead:
+		status = "dead"
+	case _Gcopystack:
+		status = "copystack"
+	case _Gpreempted:
+		status = "preempted"
+	default:
+		status = "unknown"
+	}
+
+	// Override with wait reason if available (same logic as goroutineheader)
+	if gpstatus == _Gwaiting && gp1.waitreason != waitReasonZero {
+		status = gp1.waitreason.String()
+	}
+
+	return status
+}
+
 // goroutineProfileState indicates the status of a goroutine's stack for the
 // current in-progress goroutine profile. Goroutines' stacks are initially
 // "Absent" from the profile, and end up "Satisfied" by the time the profile is
@@ -1366,7 +1404,7 @@ 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 goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels []unsafe.Pointer, infos []profilerecord.GoroutineInfo) (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
@@ -1411,6 +1449,16 @@ func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels
 	if labels != nil {
 		labels[0] = ourg.labels
 	}
+
+	// If individual id collection is enabled, also store ID.
+	if len(infos) > 0 {
+		infos[0].ID = ourg.goid
+		infos[0].State = goroutineStatusString(ourg)
+		infos[0].CreatorID = ourg.parentGoid
+		infos[0].CreationPC = ourg.gopc
+		infos[0].WaitSince = ourg.waitsince
+	}
+
 	ourg.goroutineProfiled.Store(goroutineProfileSatisfied)
 	goroutineProfile.offset.Store(1)
 
@@ -1422,6 +1470,8 @@ func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels
 	goroutineProfile.active = true
 	goroutineProfile.records = p
 	goroutineProfile.labels = labels
+	goroutineProfile.infos = infos
+
 	// The finalizer goroutine needs special handling because it can vary over
 	// time between being a user goroutine (eligible for this profile) and a
 	// system goroutine (to be excluded). Pick one before restarting the world.
@@ -1453,6 +1503,7 @@ func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels
 	goroutineProfile.active = false
 	goroutineProfile.records = nil
 	goroutineProfile.labels = nil
+	goroutineProfile.infos = nil
 	startTheWorld(stw)
 
 	// Restore the invariant that every goroutine struct in allgs has its
@@ -1578,6 +1629,15 @@ func doRecordGoroutineProfile(gp1 *g, pcbuf []uintptr) {
 	if goroutineProfile.labels != nil {
 		goroutineProfile.labels[offset] = gp1.labels
 	}
+
+	// If goroutine info collection is enabled, store ID, state, and creation info.
+	if goroutineProfile.infos != nil && offset < len(goroutineProfile.infos) {
+		goroutineProfile.infos[offset].ID = gp1.goid
+		goroutineProfile.infos[offset].State = goroutineStatusString(gp1)
+		goroutineProfile.infos[offset].CreatorID = gp1.parentGoid
+		goroutineProfile.infos[offset].CreationPC = gp1.gopc
+		goroutineProfile.infos[offset].WaitSince = gp1.waitsince
+	}
 }
 
 func goroutineProfileWithLabelsSync(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
@@ -1733,3 +1793,8 @@ func Stack(buf []byte, all bool) int {
 	}
 	return n
 }
+
+//go:linkname pprof_goroutineStacksWithLabels
+func pprof_goroutineStacksWithLabels(stacks []profilerecord.StackRecord, labels []unsafe.Pointer, infos []profilerecord.GoroutineInfo) (n int, ok bool) {
+	return goroutineProfileWithLabelsConcurrent(stacks, labels, infos)
+}

src/runtime/pprof/pprof.go

@@ -749,6 +749,9 @@ func countGoroutine() int {
 
 // writeGoroutine writes the current runtime GoroutineProfile to w.
 func writeGoroutine(w io.Writer, debug int) error {
+	if debug == 26257 {
+		return writeGoroutineStacksWithLabels(w)
+	}
 	if debug >= 2 {
 		return writeGoroutineStacks(w)
 	}
@@ -776,6 +779,107 @@ func writeGoroutineStacks(w io.Writer) error {
 	return err
 }
 
+// writeGoroutineStacksWithLabels writes individual goroutine stack traces like
+// writeGoroutineStacks, but uses the concurrent, reduced-stop time approach of
+// goroutineProfileWithLabelsConcurrent. It includes the ID, state, and labels
+// for each goroutine, although as these are captured after the world is resumed
+// they are not guaranteed to be entirely consistent as of a single point in
+// time.
+func writeGoroutineStacksWithLabels(w io.Writer) error {
+	n, ok := pprof_goroutineStacksWithLabels(nil, nil, nil)
+
+	for {
+		// Allocate slices for individual goroutine data
+		stacks := make([]profilerecord.StackRecord, n+10)
+		labels := make([]unsafe.Pointer, n+10)
+		infos := make([]profilerecord.GoroutineInfo, n+10)
+
+		n, ok = pprof_goroutineStacksWithLabels(stacks, labels, infos)
+		if ok {
+			return printGoroutineStacksWithLabels(w, stacks[:n], labels[:n], infos[:n])
+		}
+		// Profile grew; try again with larger slices
+	}
+}
+
+// printGoroutineStacksWithLabels formats goroutine records in a format similar
+// to runtime.Stack, but also includes labels as well.
+func printGoroutineStacksWithLabels(
+	w io.Writer, records []profilerecord.StackRecord, labels []unsafe.Pointer, infos []profilerecord.GoroutineInfo,
+) error {
+	for i, r := range records {
+		goroutineID := infos[i].ID
+		state := "unknown"
+		if i < len(infos) && infos[i].State != "" {
+			state = infos[i].State
+		}
+
+		// Calculate blocked time (same logic as goroutineheader in traceback.go)
+		blockedStr := ""
+		if i < len(infos) && infos[i].WaitSince != 0 {
+			// Check if this is a waiting or syscall state where blocked time applies.
+			if strings.Contains(state, "waiting") || strings.Contains(state, "syscall") {
+				waitfor := (runtime_nanotime() - infos[i].WaitSince) / 60e9 // convert to minutes
+				if waitfor >= 1 {
+					blockedStr = fmt.Sprintf(", %d minutes", waitfor)
+				}
+			}
+		}
+
+		// Get label information using the same format as debug=1.
+		var labelStr string
+		if i < len(labels) && labels[i] != nil {
+			labelMap := (*labelMap)(labels[i])
+			if labelMap != nil && len(labelMap.list) > 0 {
+				labelStr = labelMap.String()
+			}
+		}
+
+		fmt.Fprintf(w, "goroutine %d [%s%s]%s:\n", goroutineID, state, blockedStr, labelStr)
+
+		// Print stack trace with runtime filtering (same logic as debug=2).
+		show := false
+		frames := runtime.CallersFrames(r.Stack)
+		for {
+			frame, more := frames.Next()
+			name := frame.Function
+			// Hide runtime.goexit, runtime.main as well as any runtime prior to the
+			// first non-runtime function.
+			if name != "runtime.goexit" && name != "runtime.main" && (show || !(strings.HasPrefix(name, "runtime.") || strings.HasPrefix(name, "internal/runtime/"))) {
+				show = true
+				if name == "" {
+					name = "unknown"
+				}
+				fmt.Fprintf(w, "%s(...)\n", name)
+				fmt.Fprintf(w, "\t%s:%d +0x%x\n", frame.File, frame.Line, frame.PC-frame.Entry)
+			}
+			if !more {
+				break
+			}
+		}
+
+		// Print "created by" information if available (skip main goroutine)
+		if i < len(infos) && goroutineID != 1 && infos[i].CreationPC != 0 {
+			if f := runtime.FuncForPC(infos[i].CreationPC - 1); f != nil {
+				name := f.Name()
+				file, line := f.FileLine(infos[i].CreationPC - 1)
+				if infos[i].CreatorID != 0 {
+					fmt.Fprintf(w, "created by %s in goroutine %d\n", name, infos[i].CreatorID)
+				} else {
+					fmt.Fprintf(w, "created by %s\n", name)
+				}
+				fmt.Fprintf(w, "\t%s:%d +0x%x\n", file, line, infos[i].CreationPC)
+			}
+		}
+
+		if i < len(records)-1 {
+			fmt.Fprintln(w)
+		}
+	}
+
+	return nil
+}
+
 func writeRuntimeProfile(w io.Writer, debug int, name string, fetch func([]profilerecord.StackRecord, []unsafe.Pointer) (int, bool)) error {
 	// Find out how many records there are (fetch(nil)),
 	// allocate that many records, and get the data.
@@ -977,9 +1081,15 @@ func writeProfileInternal(w io.Writer, debug int, name string, runtimeProfile fu
 //go:linkname pprof_goroutineProfileWithLabels runtime.pprof_goroutineProfileWithLabels
 func pprof_goroutineProfileWithLabels(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool)
 
+//go:linkname pprof_goroutineStacksWithLabels runtime.pprof_goroutineStacksWithLabels
+func pprof_goroutineStacksWithLabels(stacks []profilerecord.StackRecord, labels []unsafe.Pointer, infos []profilerecord.GoroutineInfo) (n int, ok bool)
+
 //go:linkname pprof_cyclesPerSecond runtime/pprof.runtime_cyclesPerSecond
 func pprof_cyclesPerSecond() int64
 
+//go:linkname runtime_nanotime runtime.nanotime
+func runtime_nanotime() int64
+
 //go:linkname pprof_memProfileInternal runtime.pprof_memProfileInternal
 func pprof_memProfileInternal(p []profilerecord.MemProfileRecord, inuseZero bool) (n int, ok bool)