diff --git a/src/internal/profilerecord/profilerecord.go b/src/internal/profilerecord/profilerecord.go index a5efdced8f77c9..5b42980088f8c0 100644 --- a/src/internal/profilerecord/profilerecord.go +++ b/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 +} diff --git a/src/runtime/mprof.go b/src/runtime/mprof.go index 4b8a60718f6f5d..cb6f25d092c900 100644 --- a/src/runtime/mprof.go +++ b/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 { @@ -1328,11 +1328,51 @@ var goroutineProfile = struct { active bool offset atomic.Int64 records []profilerecord.StackRecord - labels []unsafe.Pointer + // labels, if non-nil, should have the same length as records. + labels []unsafe.Pointer + // infos, if non-nil, should have the same length as records. + 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 +1406,18 @@ 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) { +// goroutineProfileWithLabelsConcurrent collects the stacks of all user +// goroutines into the passed slice, provided it has sufficeient length to do +// so, returning the number collected and ok=true. If the passed slice does +// not have sufficient length, it returns the required length and ok=false +// instead. +// +// Additional information about each goroutine can optionally be collected into +// the labels and/or infos slices if they are non-nil. Their length must match +// len(p) if non-nil. +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 +1462,17 @@ func goroutineProfileWithLabelsConcurrent(p []profilerecord.StackRecord, labels if labels != nil { labels[0] = ourg.labels } + + // If extended goroutine info collection is enabled, gather the additional + // fields as well. + if len(infos) > 0 { + infos[0].ID = ourg.goid + infos[0].CreatorID = ourg.parentGoid + infos[0].CreationPC = ourg.gopc + infos[0].State = goroutineStatusString(ourg) + infos[0].WaitSince = ourg.waitsince + } + ourg.goroutineProfiled.Store(goroutineProfileSatisfied) goroutineProfile.offset.Store(1) @@ -1422,6 +1484,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 +1517,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 @@ -1575,9 +1640,20 @@ func doRecordGoroutineProfile(gp1 *g, pcbuf []uintptr) { // to avoid schedule delays. systemstack(func() { saveg(^uintptr(0), ^uintptr(0), gp1, &goroutineProfile.records[offset], pcbuf) }) + // If label collection is enabled, collect the labels. if goroutineProfile.labels != nil { goroutineProfile.labels[offset] = gp1.labels } + + // If extended goroutine info collection is enabled and there is sufficient + // capacity to do so, gather the additional goroutine fields as well. + if goroutineProfile.infos != nil && offset < len(goroutineProfile.infos) { + goroutineProfile.infos[offset].ID = gp1.goid + goroutineProfile.infos[offset].CreatorID = gp1.parentGoid + goroutineProfile.infos[offset].CreationPC = gp1.gopc + goroutineProfile.infos[offset].State = goroutineStatusString(gp1) + goroutineProfile.infos[offset].WaitSince = gp1.waitsince + } } func goroutineProfileWithLabelsSync(p []profilerecord.StackRecord, labels []unsafe.Pointer) (n int, ok bool) { @@ -1733,3 +1809,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) +} diff --git a/src/runtime/pprof/pprof.go b/src/runtime/pprof/pprof.go index b7680a13fdcb25..1d0aa7c3f55407 100644 --- a/src/runtime/pprof/pprof.go +++ b/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) diff --git a/src/runtime/pprof/pprof_test.go b/src/runtime/pprof/pprof_test.go index c226ef66a217c1..e25c3f35706970 100644 --- a/src/runtime/pprof/pprof_test.go +++ b/src/runtime/pprof/pprof_test.go @@ -1934,6 +1934,342 @@ func BenchmarkGoroutine(b *testing.B) { } } +func TestGoroutineProfileDebug25257MatchesDebug2(t *testing.T) { + // Create synthetic goroutines using the helper + cleanup := createSyntheticGoroutines(35, 10, 4) + defer cleanup() + + // Get reference output. + profile := Lookup("goroutine") + var buf bytes.Buffer + err := profile.WriteTo(&buf, 2) + if err != nil { + t.Fatal(err) + } + expected := parseGoroutines(t, buf.String(), true) + + // Get fast output. + buf.Reset() + err = profile.WriteTo(&buf, 26257) + if err != nil { + t.Fatal(err) + } + got := parseGoroutines(t, buf.String(), true) + + if len(got) != len(expected) { + t.Errorf("Expected %d goroutines, got %d", len(expected), len(got)) + } + + for id, info := range expected { + found, ok := got[id] + if !ok { + t.Log(info.raw) + t.Fatalf("goroutine %s not found in actual output", id) + continue + } + if info.state != found.state { + t.Log(info.raw) + t.Log(found.raw) + t.Fatalf("goroutine %s state mismatch: expected %q, got %q", id, info.state, found.state) + } + + for line := 0; line < min(len(info.stack), len(found.stack)); line++ { + if info.stack[line] != found.stack[line] { + t.Log(info.raw) + t.Log(found.raw) + t.Fatalf("goroutine %s stack line %d does not match: expected %q, got %q", id, line, found.stack[line], info.stack[line]) + } + } + if len(info.stack) != len(found.stack) { + t.Log(info.raw) + t.Log(found.raw) + if len(info.stack) < len(found.stack) { + for line := len(info.stack); line < len(found.stack); line++ { + t.Logf("Goroutine %s missing stack line %d: %q", id, line, found.stack[line]) + } + t.Fatalf("Goroutine %s stack too short: expected %d lines, got %d lines", id, len(info.stack), len(found.stack)) + } else { + for line := len(found.stack); line < len(info.stack); line++ { + t.Logf("Goroutine %s extra stack line %d: %q", id, line, info.stack[line]) + } + t.Fatalf("Goroutine %s stack too long: expected %d lines, got %d lines", id, len(info.stack), len(found.stack)) + } + } + } +} + +// BenchmarkGoroutineProfileLatencyImpact measures the latency impact on *other* +// running goroutines during goroutine profile collection, when variable numbers +// of other goroutines are profiled. This focus on the observed latency of in +// other goroutines is what differentiates this benchmark from other benchmarks +// of goroutine profiling, such as BenchmarkGoroutine, that measure the +// the performance of profiling itself rather than its impact on the performance +// of concurrently executing goroutines. +func BenchmarkGoroutineProfileLatencyImpact(b *testing.B) { + for _, numGoroutines := range []int{100, 1000, 10000, 25000} { + for _, withDepth := range []int{3, 10, 50} { + b.Run(fmt.Sprintf("goroutines=%dx%d", numGoroutines, withDepth), func(b *testing.B) { + // Setup synthetic blocked goroutines using helper + cleanup := createSyntheticGoroutines(numGoroutines, withDepth, 24) + defer cleanup() + for _, debug := range []int{1, 2, 26257, -1} { + name := fmt.Sprintf("debug=%d", debug) + if debug < 0 { + name = "debug=none" + } + b.Run(name, func(b *testing.B) { + // Launch latency probe goroutines. + const numProbes = 3 + probeStop := make(chan struct{}) + var probeWg, probesReady sync.WaitGroup + probes := make([]time.Duration, numProbes) + for prober := 0; prober < numProbes; prober++ { + probeWg.Add(1) + probesReady.Add(1) + go func(idx int) { + defer probeWg.Done() + probesReady.Done() + for { + select { + case <-probeStop: + return + default: + last := time.Now() + for i := 0; i < 20; i++ { + latency := time.Since(last) + last = time.Now() + if probes[idx] < latency { + probes[idx] = latency + } + } + } + } + }(prober) + } + probesReady.Wait() + + for i := 0; i < b.N; i++ { + if debug >= 0 { + var buf bytes.Buffer + err := Lookup("goroutine").WriteTo(&buf, debug) + if err != nil { + b.Fatalf("Profile failed: %v", err) + } + b.SetBytes(int64(buf.Len())) + + } else { + // Just observe the probes without a profile interrupting them. + time.Sleep(15 * time.Millisecond) + } + } + close(probeStop) + probeWg.Wait() + + var probeMax time.Duration + for _, probe := range probes { + if probe > probeMax { + probeMax = probe + } + } + b.ReportMetric(float64(probeMax), "max_latency_ns") + }) + } + }) + } + } +} + +// createSyntheticGoroutines creates a requested number of goroutines to provide +// testdata against which various stack dummping facilities such as +// runtime.Stack(all=true) or pprof.Lookup("goroutine").WriteTo(debug=1/2) can +// be tested or benchmarked. It returns once the requested goroutines have been +// started, after which they block on a ch until the returned cleanup func is +// called to stop them and wait for them to exit. The stacks of the goroutines +// will vary with up to 9 different sequences of calls and some variation in the +// exact depth depending on the sequence. If labels > 0, some (but not all) +// launched goroutines will have a pprof label applied, which is intentionally +// set differently from the call sequence choice so the same stack may appear +// with different labels in different goroutines. +func createSyntheticGoroutines(numGoroutines, minDepth, labels int) func() { + var syntheticStackFn0, syntheticStackFn1, syntheticStackFn2 func(<-chan struct{}, int) + var syntheticStackFn3, syntheticStackFn4, syntheticStackFn5 func(<-chan struct{}, int) + var syntheticStackFn6, syntheticStackFn7, syntheticStackFn8 func(<-chan struct{}, int) + + syntheticStackFn0 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn1(ch, depth-1) + } + <-ch + } + syntheticStackFn1 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn2(ch, depth-1) + } + <-ch + } + syntheticStackFn2 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn3(ch, depth-1) + } + <-ch + } + syntheticStackFn3 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn4(ch, depth-1) + } + <-ch + } + syntheticStackFn4 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn5(ch, depth-1) + } + <-ch + } + syntheticStackFn5 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn6(ch, depth-1) + } + <-ch + } + syntheticStackFn6 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn7(ch, depth-1) + } + <-ch + } + syntheticStackFn7 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn8(ch, depth-1) + } + <-ch + } + syntheticStackFn8 = func(ch <-chan struct{}, depth int) { + if depth > 0 { + syntheticStackFn0(ch, depth-1) + } + <-ch + } + var wg, setup sync.WaitGroup + setup.Add(numGoroutines) + + blockCh := make(chan struct{}) + + for i := 0; i < numGoroutines; i++ { + wg.Add(1) + go func(id int) { + defer wg.Done() + setup.Done() + + // Add labels if requested to some of the stacks. + if labels > 0 && (id%labels) > 0 { + SetGoroutineLabels(WithLabels(context.Background(), Labels("group", strconv.Itoa(id%labels)))) + } + // Add a little variation to the depth. + depth := minDepth + (id % 7) + switch id % 9 { + case 0: + syntheticStackFn0(blockCh, depth) + case 1: + syntheticStackFn1(blockCh, depth) + case 2: + syntheticStackFn2(blockCh, depth) + case 3: + syntheticStackFn3(blockCh, depth) + case 4: + syntheticStackFn4(blockCh, depth) + case 5: + syntheticStackFn5(blockCh, depth) + case 6: + syntheticStackFn6(blockCh, depth) + case 7: + syntheticStackFn7(blockCh, depth) + case 8: + syntheticStackFn8(blockCh, depth) + } + }(i) + } + + // Wait for all goroutines to reach blocking point + setup.Wait() + + // Return cleanup function + return func() { + close(blockCh) + wg.Wait() + } +} + +// goroutineInfo represents parsed information about a goroutine +type goroutineInfo struct { + id string + state string + since string + labels string + stack []string + created string + raw string +} + +// parseGoroutines parses goroutine profile output and returns a map of goroutine ID to info +func parseGoroutines(t *testing.T, output string, elideArgs bool) map[string]goroutineInfo { + result := make(map[string]goroutineInfo) + r := regexp.MustCompile(`^(.+)(\(.*\))$`) + for _, block := range strings.Split(output, "\n\n") { + lines := strings.Split(strings.TrimSpace(block), "\n") + + // Parse goroutine ID and state, optional block time, and optonal labels. + header := strings.TrimSuffix(lines[0], ":") + + // First, extract any labels from the new format + var labels string + if idx := strings.Index(header, "{"); idx >= 0 { + header, labels = header[:idx], header[idx:] + } + + parts := strings.SplitN(header, " ", 3) + if len(parts) != 3 { + t.Fatalf("Unexpected goroutine line format: %s", lines[0]) + } + statParts := strings.SplitN(strings.TrimSuffix(strings.TrimPrefix(parts[2], "["), "]"), ", ", 2) + + g := goroutineInfo{ + id: parts[1], + state: statParts[0], + raw: block, + labels: labels, // Use the extracted labels from new format + } + if len(statParts) > 1 { + g.since = statParts[1] + } + + // Remove function arguments from the stack trace + for i := 1; i < len(lines); i++ { + if idx := strings.LastIndex(lines[i], " +0x"); idx >= 0 { + lines[i] = lines[i][:idx] + } + if elideArgs { + lines[i] = r.ReplaceAllString(lines[i], "$1") + } + if strings.Contains(lines[i], "runtime/pprof.writeGoroutine") || + strings.Contains(lines[i], "runtime/pprof.writeGoroutineStacks") { + // Skip pprof internal calls and the following file line. + i++ + continue + } + if strings.Contains(lines[i], "runtime/pprof.(*Profile).WriteTo") { + // Skip pprof WriteTo and its file line, *and the following frame*, as + // it is the caller which will differ across calls in the test. + i += 3 + continue + } + g.stack = append(g.stack, lines[i]) + } + result[g.id] = g + } + + return result +} + var emptyCallStackTestRun int64 // Issue 18836.