diff --git a/README.md b/README.md new file mode 100644 index 0000000..b94f41b --- /dev/null +++ b/README.md @@ -0,0 +1,115 @@ +# schedstat + +Analyze Go execution traces and answer: **"What's causing goroutines to wait?"** + +`schedstat` converts a Go execution trace into a DuckDB database, runs analysis +queries, and presents the results as formatted output. It detects scheduling +latency spikes and runnable goroutine spikes, then provides per-window root +cause analysis showing burst breakdowns, heavy unblockers, and queue activity. + +## Usage + +```bash +go install github.com/dt/schedstat@latest + +# Basic analysis: summary + spike detection + per-spike details +schedstat trace.out + +# Show more spikes +schedstat -n 10 trace.out + +# Tuning thresholds +schedstat --spike-threshold=2ms trace.out # latency spike threshold (default 1ms) +schedstat --runnable-threshold=200 trace.out # runnable count threshold (default 5*GOMAXPROCS) + +# Additional analyses +schedstat --bursts trace.out # goroutine launch bursts + who launched them +schedstat --worst=20 trace.out # N worst individual delays with stacks +schedstat --timeseries trace.out # p99 per time window +schedstat --by-creator trace.out # delays grouped by goroutine creator +schedstat --gc trace.out # GC-related state transitions + +# Power user +schedstat --sql trace.out # drop into DuckDB shell after analysis +schedstat --keep-db trace.out # keep .duckdb file for later exploration +``` + +## Output + +The default output includes: + +1. **Overall latency stats** - event count, min, p50, p90, p99, max +2. **Latency Spikes** - windows where p99 exceeded the threshold, ranked by severity +3. **Runnable Spikes** - windows where the runnable goroutine count exceeded the + threshold, ranked by peak count +4. **Spike Details** - per-window root cause analysis for each spike: + - Worst individual delay in the window (latency spikes) + - Burst breakdown: how many goroutines became runnable, by category + (unblocked, new, preempted, syscall) + - Heavy unblockers: which goroutines unblocked the most others + - Longest run during the wait (latency spikes) + - Queue activity (latency spikes) + +### Example + +``` +--- Latency Spikes (p99 > 1ms per 100ms) --- +1 window(s) above threshold + + [1] t=4200ms p99=6.85ms max=9.44ms 12933 events + +--- Runnable Spikes (>80 runnable per 100ms) --- +100 window(s) above threshold (showing top 5) + + [2] t=4200ms peak 542 runnable + [3] t=9800ms peak 237 runnable + ... + +--- Spike Details --- + +[1] t=4200ms [latency] p99=6.85ms + → G852 waited 9.44ms on P6 + → Burst: 125 goroutines became runnable within ±1ms + Breakdown: 139 unblocked + Unblocked by (94): selectgo + Heavy unblocker G841 (4): (*writeBatch).CommitNoSyncWait → ... + → Longest run during wait: G901 ran 886.8µs + → Queue activity: 174 goroutines ran 176 times during the wait + +[2] t=4200ms [runnable] peak 542 runnable + Breakdown: 1214 unblocked, 229 preempted, 1 new + Unblocked by (832): (*Cond).Signal + Heavy unblocker G1222 (389): (*Store).HandleRaftRequest → ... +``` + +## Flags + +| Flag | Default | Description | +|------|---------|-------------| +| `-w`, `--window` | `100ms` | Time window for analysis | +| `--spike-threshold` | `1ms` | p99 threshold to flag as latency spike | +| `--runnable-threshold` | `0` | Runnable goroutine count threshold (0 = 5*GOMAXPROCS) | +| `-n`, `--top` | `5` | Number of spike listings and detail entries | +| `--timeseries` | `false` | Show p99 latency per time window | +| `--by-creator` | `false` | Group delays by goroutine creator | +| `--gc` | `false` | Show GC-related state transitions | +| `--bursts` | `false` | Show burst events and who launched delayed goroutines | +| `--worst` | `0` | Show N worst individual delays with stacks | +| `--top-waiters` | `false` | Show goroutines with most total wait time | +| `--keep-db` | `false` | Keep DuckDB file after analysis | +| `--sql` | `false` | Drop into DuckDB shell after analysis | +| `-v`, `--verbose` | `false` | Verbose output | + +## Collecting a trace + +```bash +curl -o trace.out 'http://localhost:8080/debug/pprof/trace?seconds=10' +``` + +Or programmatically: + +```go +f, _ := os.Create("trace.out") +trace.Start(f) +defer trace.Stop() +``` diff --git a/docs/PLAN.md b/docs/PLAN.md index cdfaa29..d3a45be 100644 --- a/docs/PLAN.md +++ b/docs/PLAN.md @@ -21,19 +21,21 @@ trace.out → sqlprof → DuckDB → schedstat queries → formatted output ### CLI Interface ```bash -# Basic analysis (summary + anomalies + top goroutines) +# Basic analysis (summary + spike detection + spike details) schedstat trace.out -# Root cause analysis (recommended) -schedstat --why=5 trace.out # Explain 5 worst delays: what caused them? -schedstat --bursts trace.out # Detect goroutine launch bursts + who launched them - # Additional analyses +schedstat --bursts trace.out # Detect goroutine launch bursts + who launched them schedstat --worst=20 trace.out # N worst individual delays with stacks schedstat --timeseries trace.out # p99 per time window schedstat --by-creator trace.out # delays grouped by goroutine creator schedstat --gc trace.out # GC-related state transitions +# Tuning +schedstat -n 10 trace.out # show top 10 spikes per type (default 5) +schedstat --spike-threshold=2ms trace.out # only flag windows with p99 > 2ms +schedstat --runnable-threshold=200 trace.out # only flag windows with >200 runnable + # Power user schedstat --sql trace.out # drop into DuckDB shell after analysis schedstat --keep-db trace.out # keep .duckdb file for later exploration @@ -52,8 +54,10 @@ Runtime/stdlib frames are filtered out to focus on application code. 1. **Trace duration** - orientation 2. **Overall latency stats** - min, p50, p90, p99, max -3. **Anomalies** - time windows where p99 exceeded threshold -4. **Top goroutines** - which goroutines spent the most time waiting +3. **Latency Spikes** - time windows where p99 exceeded threshold +4. **Runnable Spikes** - time windows where runnable goroutine count exceeded threshold +5. **Spike Details** - per-window root cause analysis (burst breakdown, heavy unblockers, + longest run, queue activity) ### Key Design Decisions @@ -189,14 +193,15 @@ Based on real-world usage (e.g., Tobi's investigation): - [x] Delays by creator (`--by-creator`) - [x] GC-related transitions (`--gc`) - [x] Worst individual delays (`--worst=N`) with full stack paths -- [x] **Root cause analysis** (`--why=N`) - For each delay, show what was running on the P - and whether it was a single blocker or runqueue saturation +- [x] **Spike details** - Per-window root cause analysis: burst breakdown, heavy unblockers, + longest run during wait, queue activity (replaces old `--why` flag) +- [x] **Runnable spike detection** - Time windows with high runnable goroutine count, + with burst breakdown at the peak entry-rate bucket - [x] **Burst detection** (`--bursts`) - When many goroutines became runnable at once - [x] **Who launched delayed goroutines** - What code path created goroutines that experienced delays ### To Add -- [ ] **Runnable count over time** - How many goroutines were runnable at each point? - This is key for diagnosing "too many goroutines" situations. +- [ ] **Per-bucket runnable chart** - Detailed timeseries of runnable goroutine count per 1ms bucket within a spike window. - [ ] **Processor utilization** - Were all Ps busy? Were some idle while work waited? - [ ] **Correlation with metrics** - Overlay scheduling latency with /gc/heap/allocs, etc. - [ ] **STW detection** - Identify stop-the-world pauses and their duration diff --git a/main.go b/main.go index 665bed5..54d3be8 100644 --- a/main.go +++ b/main.go @@ -19,19 +19,19 @@ import ( ) var opts struct { - window time.Duration - spikeThreshold time.Duration - timeseries bool - byCreator bool - gc bool - bursts bool - worst int - why int - top int - topWaiters bool - keepDB bool - sql bool - verbose bool + window time.Duration + spikeThreshold time.Duration + goroutineThreshold int + timeseries bool + byCreator bool + gc bool + bursts bool + worst int + top int + topWaiters bool + keepDB bool + sql bool + verbose bool } func main() { @@ -41,7 +41,8 @@ func main() { Long: `schedstat analyzes Go execution traces and answers: "What's causing goroutines to wait?" Examples: - schedstat trace.out # Summary + anomalies + root cause analysis + schedstat trace.out # Summary + spike detection + spike details + schedstat -n 10 trace.out # Show top 10 spikes per type (default 5) schedstat --bursts trace.out # Detect goroutine launch bursts schedstat --sql trace.out # Drop into DuckDB shell for custom queries`, Args: cobra.MinimumNArgs(1), @@ -66,13 +67,13 @@ Examples: f := rootCmd.Flags() f.DurationVarP(&opts.window, "window", "w", 100*time.Millisecond, "time window for analysis") f.DurationVar(&opts.spikeThreshold, "spike-threshold", 1*time.Millisecond, "p99 threshold to highlight as anomaly") + f.IntVar(&opts.goroutineThreshold, "runnable-threshold", 0, "runnable goroutine count to highlight as anomaly (0 = 5*GOMAXPROCS)") f.BoolVar(&opts.timeseries, "timeseries", false, "show p99 latency per time window") f.BoolVar(&opts.byCreator, "by-creator", false, "group delays by goroutine creator") f.BoolVar(&opts.gc, "gc", false, "show GC-related state transitions") f.BoolVar(&opts.bursts, "bursts", false, "show burst events and who launched delayed goroutines") f.IntVar(&opts.worst, "worst", 0, "show N worst individual delays with stacks") - f.IntVar(&opts.why, "why", 5, "explain N worst delays: what caused the wait?") - f.IntVarP(&opts.top, "top", "n", 5, "number of entries in summaries") + f.IntVarP(&opts.top, "top", "n", 5, "number of spike listings and detail entries") f.BoolVar(&opts.topWaiters, "top-waiters", false, "show goroutines with most total wait time") f.BoolVar(&opts.keepDB, "keep-db", false, "keep DuckDB file after analysis") f.BoolVar(&opts.sql, "sql", false, "drop into DuckDB shell after analysis") @@ -175,6 +176,16 @@ func analyze(db *sql.DB, traceFile string, w io.Writer) error { durationMs := float64(maxTime-minTime) / 1e6 fmt.Fprintf(w, "\nTrace duration: %.1fms\n", durationMs) + // Get processor count for goroutine threshold default + var procCount int + if err := db.QueryRow(`SELECT COUNT(*) FROM procs`).Scan(&procCount); err != nil { + return fmt.Errorf("getting processor count: %w", err) + } + goroutineThreshold := opts.goroutineThreshold + if goroutineThreshold == 0 { + goroutineThreshold = 5 * procCount + } + // Always show overall stats if err := printOverallStats(db, w); err != nil { return err @@ -187,11 +198,39 @@ func analyze(db *sql.DB, traceFile string, w io.Writer) error { } } - // Anomaly detection (always) - if err := printAnomalies(db, w, minTime, opts.window, opts.spikeThreshold); err != nil { + // Spike detection. + latencySpikes, totalLatency, err := queryLatencySpikes(db, minTime, opts.window, opts.spikeThreshold, opts.top) + if err != nil { + return err + } + runnableSpikes, totalRunnable, err := queryRunnableSpikes(db, minTime, opts.window, goroutineThreshold, opts.top) + if err != nil { return err } + // Assign display indices before printing so print functions are pure output. + idx := 1 + for i := range latencySpikes { + latencySpikes[i].index = idx + idx++ + } + for i := range runnableSpikes { + runnableSpikes[i].index = idx + idx++ + } + + printLatencySpikesSection(w, latencySpikes, totalLatency, opts.window, opts.spikeThreshold) + printRunnableSpikesSection(w, runnableSpikes, totalRunnable, opts.window, goroutineThreshold) + + allSpikes := make([]spikeInfo, 0, len(latencySpikes)+len(runnableSpikes)) + allSpikes = append(allSpikes, latencySpikes...) + allSpikes = append(allSpikes, runnableSpikes...) + if len(allSpikes) > 0 { + if err := printSpikeDetails(db, w, allSpikes, minTime, opts.window); err != nil { + return err + } + } + // By-creator analysis if opts.byCreator { if err := printByCreator(db, w); err != nil { @@ -220,13 +259,6 @@ func analyze(db *sql.DB, traceFile string, w io.Writer) error { } } - // Root cause analysis - if opts.why > 0 { - if err := printWhyDelays(db, w, opts.why); err != nil { - return err - } - } - // Top goroutines by wait time (optional, can be slow) if opts.topWaiters { if err := printTopGoroutines(db, w); err != nil { @@ -310,78 +342,153 @@ func printTimeseries(db *sql.DB, w io.Writer, minTime int64, window time.Duratio return rows.Err() } -func printAnomalies(db *sql.DB, w io.Writer, minTime int64, window, threshold time.Duration) error { +type spikeType int + +const ( + latencySpike spikeType = iota + runnableSpike +) + +type spikeInfo struct { + index int // sequential display number, assigned in analyze() + windowNum int + startMs float64 + eventCount int + p99 float64 + maxLatency float64 + maxRunnable int + spikeType spikeType +} + +func queryLatencySpikes(db *sql.DB, minTime int64, window, threshold time.Duration, top int) ([]spikeInfo, int, error) { windowNs := window.Nanoseconds() thresholdNs := float64(threshold.Nanoseconds()) - var spikeCount int - err := db.QueryRow(` - SELECT COUNT(*) - FROM ( - SELECT PERCENTILE_CONT(0.99) WITHIN GROUP (ORDER BY duration_ns) as p99 + rows, err := db.Query(` + WITH spike_windows AS ( + SELECT + (end_time_ns - $1) // $2 as window_num, + ((end_time_ns - $1) // $2) * $2 / 1e6 as start_ms, + COUNT(*) as event_count, + PERCENTILE_CONT(0.99) WITHIN GROUP (ORDER BY duration_ns) as p99, + MAX(duration_ns) as max_latency FROM g_transitions WHERE from_state = 'runnable' AND to_state = 'running' - GROUP BY (end_time_ns - $1) // $2 + GROUP BY 1, 2 HAVING p99 > $3 ) - `, minTime, windowNs, thresholdNs).Scan(&spikeCount) + SELECT *, COUNT(*) OVER() as total + FROM spike_windows + ORDER BY p99 DESC + LIMIT $4 + `, minTime, windowNs, thresholdNs, top) if err != nil { - return fmt.Errorf("counting spikes: %w", err) + return nil, 0, fmt.Errorf("latency spikes query: %w", err) } + defer rows.Close() - fmt.Fprintf(w, "\n--- Anomalies (p99 > %s per %s) ---\n", threshold, window) - - if spikeCount == 0 { - fmt.Fprintln(w, "No anomalies detected.") - return nil + var spikes []spikeInfo + var total int + for rows.Next() { + var s spikeInfo + s.spikeType = latencySpike + if err := rows.Scan(&s.windowNum, &s.startMs, &s.eventCount, &s.p99, &s.maxLatency, &total); err != nil { + return nil, 0, err + } + spikes = append(spikes, s) } + return spikes, total, rows.Err() +} - fmt.Fprintf(w, "%d window(s) with elevated latency\n\n", spikeCount) +func queryRunnableSpikes(db *sql.DB, minTime int64, window time.Duration, runnableThreshold, top int) ([]spikeInfo, int, error) { + windowMs := window.Milliseconds() rows, err := db.Query(` - WITH windowed AS ( + WITH buckets AS ( SELECT - (end_time_ns - $1) // $2 as window_num, - duration_ns, - g + (end_time_ns - $1) // 1000000 as bucket_ms, + COUNT(*) FILTER (WHERE to_state = 'runnable') as enter, + COUNT(*) FILTER (WHERE from_state = 'runnable') as leave FROM g_transitions - WHERE from_state = 'runnable' AND to_state = 'running' + WHERE from_state = 'runnable' OR to_state = 'runnable' + GROUP BY bucket_ms ), - window_stats AS ( + -- Cumulative runnable count. This assumes zero runnable goroutines at + -- trace start, which is approximate but sufficient for spike detection. + running AS ( SELECT - window_num, - window_num * $2 / 1e6 as start_ms, - COUNT(*) as event_count, - COUNT(DISTINCT g) as goroutine_count, - PERCENTILE_CONT(0.99) WITHIN GROUP (ORDER BY duration_ns) as p99, - MAX(duration_ns) as max_latency - FROM windowed - GROUP BY 1, 2 - HAVING p99 > $3 + bucket_ms, + SUM(enter - leave) OVER (ORDER BY bucket_ms) as runnable_count + FROM buckets + ), + window_max AS ( + SELECT + bucket_ms // $2 as window_num, + MAX(runnable_count) as max_runnable + FROM running + GROUP BY window_num + HAVING max_runnable > $3 ) - SELECT window_num, start_ms, event_count, goroutine_count, p99, max_latency - FROM window_stats - ORDER BY p99 DESC + SELECT window_num, max_runnable, COUNT(*) OVER() as total + FROM window_max + ORDER BY max_runnable DESC LIMIT $4 - `, minTime, windowNs, thresholdNs, opts.top) + `, minTime, windowMs, runnableThreshold, top) if err != nil { - return fmt.Errorf("anomaly query: %w", err) + return nil, 0, fmt.Errorf("runnable spikes query: %w", err) } defer rows.Close() + var spikes []spikeInfo + var total int for rows.Next() { - var windowNum int - var startMs float64 - var eventCount, goroutineCount int - var p99, maxLatency float64 - if err := rows.Scan(&windowNum, &startMs, &eventCount, &goroutineCount, &p99, &maxLatency); err != nil { - return err + var s spikeInfo + s.spikeType = runnableSpike + if err := rows.Scan(&s.windowNum, &s.maxRunnable, &total); err != nil { + return nil, 0, err } - fmt.Fprintf(w, " t=%-6.0fms p99=%-10s max=%-10s %d events, %d goroutines\n", - startMs, fmtDuration(p99), fmtDuration(maxLatency), eventCount, goroutineCount) + s.startMs = float64(s.windowNum) * float64(windowMs) + spikes = append(spikes, s) } + return spikes, total, rows.Err() +} - return rows.Err() +func printLatencySpikesSection(w io.Writer, spikes []spikeInfo, total int, window, threshold time.Duration) { + if total == 0 { + return + } + + fmt.Fprintf(w, "\n--- Latency Spikes (p99 > %s per %s) ---\n", threshold, window) + if total > len(spikes) { + fmt.Fprintf(w, "%d window(s) above threshold (showing top %d)\n", total, len(spikes)) + } else { + fmt.Fprintf(w, "%d window(s) above threshold\n", total) + } + fmt.Fprintln(w) + + for _, s := range spikes { + fmt.Fprintf(w, " [%d] t=%.0fms p99=%s max=%s %d events\n", + s.index, s.startMs, fmtDuration(s.p99), fmtDuration(s.maxLatency), s.eventCount) + } +} + +func printRunnableSpikesSection(w io.Writer, spikes []spikeInfo, total int, window time.Duration, runnableThreshold int) { + if total == 0 { + return + } + + fmt.Fprintf(w, "\n--- Runnable Spikes (>%d runnable per %s) ---\n", runnableThreshold, window) + if total > len(spikes) { + fmt.Fprintf(w, "%d window(s) above threshold (showing top %d)\n", total, len(spikes)) + } else { + fmt.Fprintf(w, "%d window(s) above threshold\n", total) + } + fmt.Fprintln(w) + + for _, s := range spikes { + fmt.Fprintf(w, " [%d] t=%.0fms peak %d runnable\n", + s.index, s.startMs, s.maxRunnable) + } } func printByCreator(db *sql.DB, w io.Writer) error { @@ -620,130 +727,177 @@ func printWorstDelays(db *sql.DB, w io.Writer, n int) error { return rows.Err() } -func printWhyDelays(db *sql.DB, w io.Writer, n int) error { - fmt.Fprintf(w, "\n--- Why Did the %d Worst Delays Happen? ---\n", n) +func printSpikeDetails(db *sql.DB, w io.Writer, spikes []spikeInfo, minTime int64, window time.Duration) error { + fmt.Fprintf(w, "\n--- Spike Details ---\n") - // Get worst delays with their P and time window - rows, err := db.Query(` + windowNs := window.Nanoseconds() + + for _, s := range spikes { + fmt.Fprintln(w) + if s.spikeType == latencySpike { + fmt.Fprintf(w, "[%d] t=%.0fms [latency] p99=%s\n", s.index, s.startMs, fmtDuration(s.p99)) + if err := printLatencySpikeDetail(db, w, s, minTime, windowNs); err != nil { + return err + } + } else { + fmt.Fprintf(w, "[%d] t=%.0fms [runnable] peak %d runnable\n", s.index, s.startMs, s.maxRunnable) + if err := printRunnableSpikeDetail(db, w, s, minTime, window); err != nil { + return err + } + } + } + + return nil +} + +func printLatencySpikeDetail(db *sql.DB, w io.Writer, s spikeInfo, minTime, windowNs int64) error { + windowStart := minTime + int64(s.windowNum)*windowNs + windowEnd := windowStart + windowNs + + // Find the worst individual delay within this window. + // Latency spikes filter by wait_start (end_time_ns - duration_ns) because + // that's when the goroutine entered the runnable state — the event that + // defines which window a scheduling delay belongs to. + var g int64 + var durationNs float64 + var endTime, waitStart int64 + var srcP sql.NullInt64 + err := db.QueryRow(` SELECT g, duration_ns, end_time_ns, src_p, end_time_ns - duration_ns AS wait_start FROM g_transitions WHERE from_state = 'runnable' AND to_state = 'running' + AND end_time_ns - duration_ns >= $1 + AND end_time_ns - duration_ns < $2 ORDER BY duration_ns DESC - LIMIT $1 - `, n) + LIMIT 1 + `, windowStart, windowEnd).Scan(&g, &durationNs, &endTime, &srcP, &waitStart) if err != nil { - return fmt.Errorf("why delays query: %w", err) + if err == sql.ErrNoRows { + return nil + } + return fmt.Errorf("worst delay query: %w", err) } - defer rows.Close() - type delayInfo struct { - g int64 - durationNs float64 - endTime int64 - waitStart int64 - srcP sql.NullInt64 - } - var delays []delayInfo - for rows.Next() { - var d delayInfo - if err := rows.Scan(&d.g, &d.durationNs, &d.endTime, &d.srcP, &d.waitStart); err != nil { - return err - } - delays = append(delays, d) + fmt.Fprintf(w, " → G%d waited %s", g, fmtDuration(durationNs)) + if srcP.Valid { + fmt.Fprintf(w, " on P%d", srcP.Int64) } - if err := rows.Err(); err != nil { - return err + fmt.Fprintln(w) + + // Was there a burst of goroutines becoming runnable? + var burstCount int + err = db.QueryRow(` + SELECT COUNT(DISTINCT g) + FROM g_transitions + WHERE (to_state = 'runnable' OR (from_state = 'notexist' AND to_state = 'running')) + AND end_time_ns - duration_ns BETWEEN $1 - 1000000 AND $1 + 1000000 + `, waitStart).Scan(&burstCount) + if err != nil { + return fmt.Errorf("burst query: %w", err) } - // For each delay, analyze WHY this goroutine had to wait - for i, d := range delays { - fmt.Fprintf(w, "\n%d. G%d waited %s", i+1, d.g, fmtDuration(d.durationNs)) - if d.srcP.Valid { - fmt.Fprintf(w, " on P%d", d.srcP.Int64) + // Was there a long-running goroutine that blocked the queue? + var longestRunNs sql.NullFloat64 + var longestRunG sql.NullInt64 + var longestRunStack sql.NullString + if srcP.Valid { + err = db.QueryRow(` + SELECT duration_ns, g, stack_funcs(stack_id)::VARCHAR + FROM g_transitions + WHERE from_state = 'running' + AND src_p = $1 + AND end_time_ns > $2 + AND end_time_ns - duration_ns < $3 + ORDER BY duration_ns DESC + LIMIT 1 + `, srcP.Int64, waitStart, endTime).Scan(&longestRunNs, &longestRunG, &longestRunStack) + if err != nil && err != sql.ErrNoRows { + return fmt.Errorf("longest run query: %w", err) } - fmt.Fprintln(w) + } - // Question 1: Was there a burst of goroutines becoming runnable? - // Count how many goroutines became runnable within 1ms of when this G became runnable - var burstCount int - err := db.QueryRow(` - SELECT COUNT(DISTINCT g) + // How many goroutines ran during the wait? + var runnersCount, totalRuns int + if srcP.Valid { + err = db.QueryRow(` + SELECT COUNT(DISTINCT g), COUNT(*) FROM g_transitions - WHERE (to_state = 'runnable' OR (from_state = 'notexist' AND to_state = 'running')) - AND end_time_ns - duration_ns BETWEEN $1 - 1000000 AND $1 + 1000000 - `, d.waitStart).Scan(&burstCount) + WHERE from_state = 'running' + AND src_p = $1 + AND end_time_ns > $2 + AND end_time_ns - duration_ns < $3 + `, srcP.Int64, waitStart, endTime).Scan(&runnersCount, &totalRuns) if err != nil { - return fmt.Errorf("burst query: %w", err) + return fmt.Errorf("runners count query: %w", err) } + } - // Question 2: Was there a long-running goroutine that blocked the queue? - // Find the longest single run during the wait window on this P - var longestRunNs sql.NullFloat64 - var longestRunG sql.NullInt64 - var longestRunStack sql.NullString - if d.srcP.Valid { - err = db.QueryRow(` - SELECT duration_ns, g, stack_funcs(stack_id)::VARCHAR - FROM g_transitions - WHERE from_state = 'running' - AND src_p = $1 - AND end_time_ns > $2 - AND end_time_ns - duration_ns < $3 - ORDER BY duration_ns DESC - LIMIT 1 - `, d.srcP.Int64, d.waitStart, d.endTime).Scan(&longestRunNs, &longestRunG, &longestRunStack) - if err != nil && err != sql.ErrNoRows { - return fmt.Errorf("longest run query: %w", err) - } + // Report findings + if burstCount > 10 { + fmt.Fprintf(w, " → Burst: %d goroutines became runnable within ±1ms\n", burstCount) + if err := printBurstBreakdown(db, w, waitStart); err != nil { + fmt.Fprintf(w, " (burst breakdown error: %v)\n", err) } + } - // Question 3: How many goroutines ran during the wait? - var runnersCount, totalRuns int - if d.srcP.Valid { - err = db.QueryRow(` - SELECT COUNT(DISTINCT g), COUNT(*) - FROM g_transitions - WHERE from_state = 'running' - AND src_p = $1 - AND end_time_ns > $2 - AND end_time_ns - duration_ns < $3 - `, d.srcP.Int64, d.waitStart, d.endTime).Scan(&runnersCount, &totalRuns) - if err != nil { - return fmt.Errorf("runners count query: %w", err) - } + if longestRunNs.Valid && longestRunNs.Float64 > 500000 { // > 500µs + stack := parseStackArray(longestRunStack.String) + fmt.Fprintf(w, " → Longest run during wait: G%d ran %s\n", + longestRunG.Int64, fmtDuration(longestRunNs.Float64)) + if len(stack) > 0 { + fmt.Fprintf(w, " %s\n", formatStack(stack, 80)) } + } - // Report findings - if burstCount > 10 { - fmt.Fprintf(w, " → Burst: %d goroutines became runnable within ±1ms\n", burstCount) - // Show detailed burst breakdown - if err := printBurstBreakdown(db, w, d.waitStart); err != nil { - // Non-fatal: just skip the breakdown on error - if opts.verbose { - fmt.Fprintf(w, " (burst breakdown unavailable: %v)\n", err) - } - } - } + if runnersCount > 0 { + fmt.Fprintf(w, " → Queue activity: %d goroutines ran %d times during the wait\n", + runnersCount, totalRuns) + } - if longestRunNs.Valid && longestRunNs.Float64 > 500000 { // > 500µs - stack := parseStackArray(longestRunStack.String) - fmt.Fprintf(w, " → Longest run during wait: G%d ran %s\n", - longestRunG.Int64, fmtDuration(longestRunNs.Float64)) - if len(stack) > 0 { - fmt.Fprintf(w, " %s\n", formatStack(stack, 80)) - } - } + if burstCount <= 10 && (!longestRunNs.Valid || longestRunNs.Float64 <= 500000) && runnersCount == 0 { + fmt.Fprintln(w, " → No clear single cause identified") + } - if runnersCount > 0 { - fmt.Fprintf(w, " → Queue activity: %d goroutines ran %d times during the wait\n", - runnersCount, totalRuns) - } + return nil +} - // If nothing notable, say so - if burstCount <= 10 && (!longestRunNs.Valid || longestRunNs.Float64 <= 500000) && runnersCount == 0 { - fmt.Fprintln(w, " → No clear single cause identified") +func printRunnableSpikeDetail(db *sql.DB, w io.Writer, s spikeInfo, minTime int64, window time.Duration) error { + windowMs := window.Milliseconds() + windowStartMs := int64(s.windowNum) * windowMs + windowEndMs := windowStartMs + windowMs + + // Find the 1ms bucket within the window where most goroutines became runnable. + // Runnable spikes use end_time_ns for bucketing (the transition completion + // time) rather than wait_start, since we're counting state transitions into + // "runnable" — a different semantic than latency spike detection. + var peakBucketMs int64 + err := db.QueryRow(` + SELECT bucket_ms + FROM ( + SELECT + (end_time_ns - $1) // 1000000 as bucket_ms, + COUNT(*) as enter_count + FROM g_transitions + WHERE to_state = 'runnable' + AND (end_time_ns - $1) // 1000000 >= $2 + AND (end_time_ns - $1) // 1000000 < $3 + GROUP BY bucket_ms + ) + ORDER BY enter_count DESC + LIMIT 1 + `, minTime, windowStartMs, windowEndMs).Scan(&peakBucketMs) + if err != nil { + if err == sql.ErrNoRows { + return nil } + return fmt.Errorf("peak bucket query: %w", err) + } + + peakNs := minTime + peakBucketMs*1000000 + + if err := printBurstBreakdown(db, w, peakNs); err != nil { + fmt.Fprintf(w, " (burst breakdown error: %v)\n", err) } return nil @@ -1006,7 +1160,7 @@ func printHeavyUnblockers(db *sql.DB, w io.Writer, runnableStartNs int64) error COUNT(*) as cnt FROM burst_unblocks GROUP BY src_g - ORDER BY cnt DESC + ORDER BY cnt DESC, src_g LIMIT $2 ) SELECT diff --git a/main_test.go b/main_test.go index 58eb65a..5471497 100644 --- a/main_test.go +++ b/main_test.go @@ -13,6 +13,45 @@ import ( var rewrite = flag.Bool("rewrite", false, "regenerate golden output files in testdata/") +// testOpts returns a default opts struct suitable for deterministic tests. +// Callers override individual fields as needed. +func testOpts() struct { + window time.Duration + spikeThreshold time.Duration + goroutineThreshold int + timeseries bool + byCreator bool + gc bool + bursts bool + worst int + top int + topWaiters bool + keepDB bool + sql bool + verbose bool +} { + return struct { + window time.Duration + spikeThreshold time.Duration + goroutineThreshold int + timeseries bool + byCreator bool + gc bool + bursts bool + worst int + top int + topWaiters bool + keepDB bool + sql bool + verbose bool + }{ + window: 100 * time.Millisecond, + spikeThreshold: 1 * time.Millisecond, + goroutineThreshold: 40, // fixed value for deterministic output + top: 5, + } +} + // TestGoldenOutput runs schedstat on each .bin trace file in testdata/ and // compares the output against the corresponding .txt golden file. When invoked // with -rewrite, the golden files are regenerated instead. @@ -34,26 +73,7 @@ func TestGoldenOutput(t *testing.T) { } // Use fixed flags for deterministic output. - opts = struct { - window time.Duration - spikeThreshold time.Duration - timeseries bool - byCreator bool - gc bool - bursts bool - worst int - why int - top int - topWaiters bool - keepDB bool - sql bool - verbose bool - }{ - window: 100 * time.Millisecond, - spikeThreshold: 1 * time.Millisecond, - why: 5, - top: 5, - } + opts = testOpts() for _, traceFile := range traces { name := strings.TrimSuffix(filepath.Base(traceFile), ".bin") @@ -87,6 +107,42 @@ func TestGoldenOutput(t *testing.T) { } } +// TestGoroutineThreshold verifies that the goroutine threshold triggers +// appropriately at different levels. +func TestGoroutineThreshold(t *testing.T) { + traceFile := "testdata/experiment-upsert1000-gateway.bin" + if _, err := os.Stat(traceFile); os.IsNotExist(err) { + t.Skip("test trace not available") + } + + tests := []struct { + name string + goroutineThreshold int + wantGoroutineSpikes bool + }{ + {"low_threshold_triggers", 80, true}, + {"high_threshold_no_trigger", 3000, false}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + opts = testOpts() + opts.goroutineThreshold = tc.goroutineThreshold + + var buf bytes.Buffer + if err := runAnalysis(traceFile, &buf); err != nil { + t.Fatalf("runAnalysis: %v", err) + } + output := buf.String() + + hasGoroutineSpikes := strings.Contains(output, "Runnable Spikes") + if hasGoroutineSpikes != tc.wantGoroutineSpikes { + t.Errorf("goroutine spikes: got %v, want %v", hasGoroutineSpikes, tc.wantGoroutineSpikes) + } + }) + } +} + // lineDiff returns a simple line-by-line comparison showing the first few // differences, to keep test output manageable. func lineDiff(want, got string) string { diff --git a/testdata/experiment-upsert1000-gateway.bin b/testdata/experiment-upsert1000-gateway.bin new file mode 100644 index 0000000..30ca7fa Binary files /dev/null and b/testdata/experiment-upsert1000-gateway.bin differ diff --git a/testdata/experiment-upsert1000-gateway.txt b/testdata/experiment-upsert1000-gateway.txt new file mode 100644 index 0000000..a2475a6 --- /dev/null +++ b/testdata/experiment-upsert1000-gateway.txt @@ -0,0 +1,111 @@ +schedstat: experiment-upsert1000-gateway.bin +============================================================ + +Trace duration: 10001.1ms + +--- Scheduling Latency (runnable → running) --- +Events: 1554412 + min: 1ns p50: 21.4µs p90: 169.7µs + avg: 63.5µs p99: 521.8µs max: 9.44ms + +--- Latency Spikes (p99 > 1ms per 100ms) --- +1 window(s) above threshold + + [1] t=4200ms p99=6.85ms max=9.44ms 12933 events + +--- Runnable Spikes (>40 runnable per 100ms) --- +100 window(s) above threshold (showing top 5) + + [2] t=4200ms peak 542 runnable + [3] t=9800ms peak 237 runnable + [4] t=6700ms peak 221 runnable + [5] t=9700ms peak 219 runnable + [6] t=1800ms peak 190 runnable + +--- Spike Details --- + +[1] t=4200ms [latency] p99=6.85ms + → G852 waited 9.44ms on P6 + → Burst: 125 goroutines became runnable within ±1ms + Breakdown: 139 unblocked + Unblocked by (94): selectgo + Unblocked by (10): systemstack_switch + Unblocked by (8): (*Cond).Signal + Blocked at (94): (*streamPool[...]).newPooledStream.func2 → (*pooledStream[...]).runOnce [selectgo] + Blocked at (10): gopark [gopark] + Blocked at (9): ReadFull → ReadAtLeast → (*Reader).Read → (*conn).Read → (*netFD).Read [(*FD).Read] + Heavy unblocker G841 (4): (*writeBatch).CommitNoSyncWait → (*DB).applyInternal → (*commitPipeline).prepare + Heavy unblocker G917 (4): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G2228028 (4): (*LogWriter).flushPending → (*pendingSyncsWithSyncQueue).pop → (*syncQueue).pop + → Longest run during wait: G901 ran 886.8µs + (*DB).applyInternal → (*commitPipeline).prepare + → Queue activity: 174 goroutines ran 176 times during the wait + +[2] t=4200ms [runnable] peak 542 runnable + Breakdown: 1214 unblocked, 229 preempted, 1 new + Unblocked by (832): (*Cond).Signal + Unblocked by (195): (*WaitGroup).Add + Unblocked by (157): (*Mutex).Unlock + Blocked at (832): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (152): (*DB).applyInternal → (*commitPipeline).publish [(*WaitGroup).Wait] + Blocked at (40): (*DB).applyInternal → (*commitPipeline).prepare [(*Mutex).Lock] + Heavy unblocker G1222 (389): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G916 (160): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G919 (121): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (1): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + +[3] t=9800ms [runnable] peak 237 runnable + Breakdown: 1013 unblocked, 4 new, 2 preempted + Unblocked by (694): (*Cond).Signal + Unblocked by (170): (*Mutex).Unlock + Unblocked by (121): (*WaitGroup).Add + Blocked at (692): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (86): (*DB).applyInternal → (*commitPipeline).publish [(*WaitGroup).Wait] + Blocked at (60): (*DB).applyInternal → (*commitPipeline).prepare [(*Mutex).Lock] + Heavy unblocker G916 (169): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G1222 (161): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G919 (160): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (4): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + +[4] t=6700ms [runnable] peak 221 runnable + Breakdown: 1160 unblocked, 356 new, 96 preempted + Unblocked by (380): selectnbsend + Unblocked by (315): chansend1 + Unblocked by (241): (*Cond).Signal + Blocked at (315): (*streamPool[...]).Send → (*pooledStream[...]).Send [selectgo] + Blocked at (315): ReadAtLeast → (*transportReader).Read → (*recvBufferReader).readClient [selectgo] + Blocked at (240): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Heavy unblocker G1012 (315): (*http2Client).handleData → (*Stream).write → (*recvBuffer).put + Heavy unblocker G1222 (79): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G917 (49): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (352): (*txnLockGatekeeper).SendLocked → (*DistSender).sendPartialBatchAsync + Created by (3): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + Created by (1): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + +[5] t=9700ms [runnable] peak 219 runnable + Breakdown: 1410 unblocked, 6 new, 5 preempted + Unblocked by (829): (*Cond).Signal + Unblocked by (297): (*WaitGroup).Add + Unblocked by (260): (*Mutex).Unlock + Blocked at (828): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (184): (*DB).applyInternal → (*commitPipeline).publish [(*WaitGroup).Wait] + Blocked at (104): (*Batch).Commit → (*DB).applyInternal → (*commitPipeline).publish [(*WaitGroup).Wait] + Heavy unblocker G1222 (313): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G918 (147): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G916 (131): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (4): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + Created by (2): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + +[6] t=1800ms [runnable] peak 190 runnable + Breakdown: 933 unblocked, 31 new, 2 preempted + Unblocked by (288): (*WaitGroup).Add + Unblocked by (257): (*Cond).Signal + Unblocked by (208): selectgo + Blocked at (257): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (222): (*DB).applyInternal → (*commitPipeline).publish [(*WaitGroup).Wait] + Blocked at (208): (*streamPool[...]).newPooledStream.func2 → (*pooledStream[...]).runOnce [selectgo] + Heavy unblocker G1222 (116): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G916 (50): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G917 (34): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (28): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + Created by (3): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async diff --git a/testdata/experiment-upsert1000-leaseholder.bin b/testdata/experiment-upsert1000-leaseholder.bin new file mode 100644 index 0000000..b1cebbd Binary files /dev/null and b/testdata/experiment-upsert1000-leaseholder.bin differ diff --git a/testdata/experiment-upsert1000-leaseholder.txt b/testdata/experiment-upsert1000-leaseholder.txt new file mode 100644 index 0000000..ff94a8e --- /dev/null +++ b/testdata/experiment-upsert1000-leaseholder.txt @@ -0,0 +1,185 @@ +schedstat: experiment-upsert1000-leaseholder.bin +============================================================ + +Trace duration: 10000.8ms + +--- Scheduling Latency (runnable → running) --- +Events: 1557821 + min: 1ns p50: 41.5µs p90: 1.14ms + avg: 350.3µs p99: 3.21ms max: 21.76ms + +--- Latency Spikes (p99 > 1ms per 100ms) --- +101 window(s) above threshold (showing top 5) + + [1] t=9900ms p99=15.94ms max=21.76ms 14755 events + [2] t=7700ms p99=4.73ms max=6.18ms 16930 events + [3] t=200ms p99=4.65ms max=5.71ms 14891 events + [4] t=10000ms p99=4.64ms max=4.79ms 207 events + [5] t=7000ms p99=4.64ms max=6.39ms 15733 events + +--- Runnable Spikes (>40 runnable per 100ms) --- +101 window(s) above threshold (showing top 5) + + [6] t=9300ms peak 804 runnable + [7] t=7700ms peak 763 runnable + [8] t=4700ms peak 761 runnable + [9] t=8200ms peak 749 runnable + [10] t=9900ms peak 720 runnable + +--- Spike Details --- + +[1] t=9900ms [latency] p99=15.94ms + → G2508080 waited 21.76ms on P5 + → Burst: 305 goroutines became runnable within ±1ms + Breakdown: 245 new, 179 unblocked, 17 preempted + Created by (235): New.func1 → (*RequestBatcher).sendBatch + Created by (1): (*storeReplicaVisitor).Visit → (*replicaScanner).waitAndProcess → (*baseQueue).Async + Created by (1): (*storeReplicaVisitor).Visit → (*replicaScanner).waitAndProcess → (*baseQueue).Async + Unblocked by (45): (*Cond).Signal + Unblocked by (43): selectnbsend + Unblocked by (24): chansend1 + Blocked at (43): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (18): Do → (*RaftTransport).processQueue [selectgo] + Blocked at (18): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Heavy unblocker G3947 (21): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G857 (12): New.func1 → (*RequestBatcher).run + Heavy unblocker G3822 (10): (*csAttempt).sendMsg → (*http2Client).Write → (*controlBuffer).executeAndPut + → Longest run during wait: G1046 ran 14.09ms + (*Registry).Each.func1 → extractValue → registryRecorder.record.func1 + → Queue activity: 54 goroutines ran 131 times during the wait + +[2] t=7700ms [latency] p99=4.73ms + → G2485448 waited 6.18ms on P10 + → Burst: 759 goroutines became runnable within ±1ms + Breakdown: 726 unblocked, 515 new, 19 preempted + Unblocked by (356): (*Cond).Signal + Unblocked by (174): chansend1 + Unblocked by (69): selectnbsend + Blocked at (356): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (143): (*Store).SendWithWriteBytes → (*Replica).executeWriteBatch [selectgo] + Blocked at (35): (*RequestBatcher).sendDone [selectgo] + Heavy unblocker G4027 (115): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G3947 (96): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G857 (35): New.func1 → (*RequestBatcher).run + Created by (515): New.func1 → (*RequestBatcher).sendBatch + → Queue activity: 122 goroutines ran 153 times during the wait + +[3] t=200ms [latency] p99=4.65ms + → G2408021 waited 5.71ms on P11 + → Burst: 743 goroutines became runnable within ±1ms + Breakdown: 523 unblocked, 395 new, 2 preempted + Unblocked by (234): (*Cond).Signal + Unblocked by (215): chansend1 + Unblocked by (39): (*Mutex).Unlock + Blocked at (234): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (211): (*Store).SendWithWriteBytes → (*Replica).executeWriteBatch [selectgo] + Blocked at (15): Do → (*RaftTransport).processQueue [selectgo] + Heavy unblocker G1028 (20): (*Store).raftTickLoop → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G960 (12): (*replicatedCmd).AckOutcomeAndFinish → (*ProposalData).signalProposalResult + Heavy unblocker G904 (11): (*replicatedCmd).AckOutcomeAndFinish → (*ProposalData).signalProposalResult + Created by (395): New.func1 → (*RequestBatcher).sendBatch + → Queue activity: 96 goroutines ran 99 times during the wait + +[4] t=10000ms [latency] p99=4.64ms + → G277751 waited 318.3µs on P7 + → Burst: 78 goroutines became runnable within ±1ms + Breakdown: 150 preempted, 91 unblocked, 3 new + Unblocked by (51): (*RWMutex).Unlock + Unblocked by (27): selectnbsend + Unblocked by (5): (*Mutex).Unlock + Blocked at (46): (*tokenCounter).tokens → (*tokenCounterMu).RLock [(*RWMutex).RLock] + Blocked at (14): NewServerTransport.func2 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Blocked at (5): (*Stopper).RunAsyncTaskEx.func1 → (*infoStore).launchCallbackWorker.func1 [selectgo] + Heavy unblocker G996 (49): (*tokenCounter).adjust.(*tokenCounter).adjustLockedAndUnlock.func1 → (*tokenCounterMu).Unlock + Heavy unblocker G720 (5): (*StoreGossip).GossipStore → (*Gossip).addInfoLocked → (*infoStore).runCallbacks + Heavy unblocker G176 (4): (*infoStore).launchCallbackWorker.func1 → (*StorePool).storeDescriptorUpdate + Created by (1): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + Created by (1): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + Created by (1): (*baseQueue).processOneAsyncAndReleaseSem → (*Stopper).RunAsyncTaskEx + → Queue activity: 1 goroutines ran 25 times during the wait + +[5] t=7000ms [latency] p99=4.64ms + → G2478120 waited 6.39ms on P0 + → Burst: 636 goroutines became runnable within ±1ms + Breakdown: 767 unblocked, 444 new, 16 preempted + Unblocked by (360): (*Cond).Signal + Unblocked by (181): chansend1 + Unblocked by (71): selectnbsend + Blocked at (360): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (130): (*Store).SendWithWriteBytes → (*Replica).executeWriteBatch [selectgo] + Blocked at (64): (*RequestBatcher).sendDone [selectgo] + Heavy unblocker G3947 (93): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G857 (64): New.func1 → (*RequestBatcher).run + Heavy unblocker G4027 (64): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (442): New.func1 → (*RequestBatcher).sendBatch + Created by (2): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + → Queue activity: 100 goroutines ran 113 times during the wait + +[6] t=9300ms [runnable] peak 804 runnable + Breakdown: 643 unblocked, 500 new, 20 preempted + Unblocked by (301): (*Cond).Signal + Unblocked by (162): chansend1 + Unblocked by (65): selectnbsend + Blocked at (301): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (142): (*Store).SendWithWriteBytes → (*Replica).executeWriteBatch [selectgo] + Blocked at (32): Do → (*RaftTransport).processQueue [selectgo] + Heavy unblocker G3947 (126): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G4027 (31): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G857 (30): New.func1 → (*RequestBatcher).run + Created by (499): New.func1 → (*RequestBatcher).sendBatch + Created by (1): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + +[7] t=7700ms [runnable] peak 763 runnable + Breakdown: 1025 unblocked, 33 preempted, 3 new + Unblocked by (776): (*Cond).Signal + Unblocked by (72): selectnbsend + Unblocked by (45): selectgo + Blocked at (776): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (45): New.func1 → (*RequestBatcher).run [selectgo] + Blocked at (36): (*IntentResolver).resolveIntents [selectgo] + Heavy unblocker G3947 (427): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G4027 (332): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G1028 (22): (*Store).raftTickLoop → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Created by (1): New.func1 → (*RequestBatcher).sendBatch + Created by (1): (*Task).applyOneBatch → (*replicaAppBatch).ApplyToStateMachine → (*baseQueue).Async + Created by (1): (*IntentResolver).cleanupFinishedTxnIntents + +[8] t=4700ms [runnable] peak 761 runnable + Breakdown: 634 unblocked, 483 new, 5 preempted + Unblocked by (300): (*Cond).Signal + Unblocked by (186): chansend1 + Unblocked by (42): selectgo + Blocked at (300): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (147): (*Store).SendWithWriteBytes → (*Replica).executeWriteBatch [selectgo] + Blocked at (42): (*RequestBatcher).sendDone [selectgo] + Heavy unblocker G4027 (85): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G3947 (71): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G857 (42): New.func1 → (*RequestBatcher).run + Created by (472): New.func1 → (*RequestBatcher).sendBatch + Created by (1): (*storeReplicaVisitor).Visit → (*replicaScanner).waitAndProcess → (*baseQueue).Async + Created by (1): (*storeReplicaVisitor).Visit → (*replicaScanner).waitAndProcess → (*baseQueue).Async + +[9] t=8200ms [runnable] peak 749 runnable + Breakdown: 931 unblocked, 396 new, 2 preempted + Unblocked by (364): (*RWMutex).Unlock + Unblocked by (292): (*Cond).Signal + Unblocked by (143): chansend1 + Blocked at (364): (*tokenCounter).tokens → (*tokenCounterMu).RLock [(*RWMutex).RLock] + Blocked at (291): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (124): (*Store).SendWithWriteBytes → (*Replica).executeWriteBatch [selectgo] + Heavy unblocker G906 (368): (*tokenCounter).adjust.(*tokenCounter).adjustLockedAndUnlock.func1 → (*tokenCounterMu).Unlock + Heavy unblocker G3947 (57): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G4027 (27): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (396): New.func1 → (*RequestBatcher).sendBatch + +[10] t=9900ms [runnable] peak 720 runnable + Breakdown: 401 preempted, 280 unblocked + Unblocked by (109): (*RWMutex).Unlock + Unblocked by (71): (*Cond).Signal + Unblocked by (43): chansend1 + Blocked at (107): (*Reader).Read → (*Handle).GetWithReadHandle → (*shard).getWithReadEntry [(*RWMutex).RLock] + Blocked at (71): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (43): (*Store).SendWithWriteBytes → (*Replica).executeWriteBatch [selectgo] + Heavy unblocker G278027 (125): (*Reader).Read → ReadHandle.SetReadValue → (*readEntry).setReadValue → (*shard).set + Heavy unblocker G1032 (11): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G3947 (10): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal diff --git a/testdata/microspikes_ticks_heartbeats.txt b/testdata/microspikes_ticks_heartbeats.txt index f32fc67..b55b721 100644 --- a/testdata/microspikes_ticks_heartbeats.txt +++ b/testdata/microspikes_ticks_heartbeats.txt @@ -8,18 +8,48 @@ Events: 163815 min: 1ns p50: 6.1µs p90: 85.4µs avg: 37.1µs p99: 443.5µs max: 2.43ms ---- Anomalies (p99 > 1ms per 100ms) --- -6 window(s) with elevated latency +--- Latency Spikes (p99 > 1ms per 100ms) --- +6 window(s) above threshold (showing top 5) - t=2200 ms p99=1.83ms max=2.41ms 5962 events, 485 goroutines - t=1200 ms p99=1.76ms max=2.43ms 5075 events, 458 goroutines - t=1700 ms p99=1.74ms max=2.23ms 4183 events, 464 goroutines - t=700 ms p99=1.63ms max=2.30ms 5519 events, 500 goroutines - t=2700 ms p99=1.14ms max=1.77ms 5562 events, 515 goroutines + [1] t=2200ms p99=1.83ms max=2.41ms 5962 events + [2] t=1200ms p99=1.76ms max=2.43ms 5075 events + [3] t=1700ms p99=1.74ms max=2.23ms 4183 events + [4] t=700ms p99=1.63ms max=2.30ms 5519 events + [5] t=2700ms p99=1.14ms max=1.77ms 5562 events ---- Why Did the 5 Worst Delays Happen? --- +--- Runnable Spikes (>40 runnable per 100ms) --- +18 window(s) above threshold (showing top 5) -1. G2074 waited 2.43ms on P15 + [6] t=1800ms peak 129 runnable + [7] t=2600ms peak 122 runnable + [8] t=1600ms peak 120 runnable + [9] t=2200ms peak 112 runnable + [10] t=1500ms peak 95 runnable + +--- Spike Details --- + +[1] t=2200ms [latency] p99=1.83ms + → G1927 waited 2.41ms on P9 + → Burst: 93 goroutines became runnable within ±1ms + Breakdown: 125 unblocked, 14 preempted, 3 new + Unblocked by (45): selectnbsend + Unblocked by (33): (*Mutex).Unlock + Unblocked by (11): (*Cond).Broadcast + Blocked at (19): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Blocked at (19): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (18): (*Stopper).RunAsyncTaskEx.func2 → (*RaftTransport).processQueue [selectgo] + Heavy unblocker G4203943013 (11): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G2159 (9): (*Store).sendQueuedHeartbeatsToNode → (*RaftTransport).SendAsync + Heavy unblocker G1994 (5): (*Store).processReady → (*Replica).sendRaftMessageRequest → (*RaftTransport).SendAsync + Created by (1): (*DistSender).sendPartialBatchAsync → (*Stopper).RunAsyncTaskEx + Created by (1): (*pendingLeaseRequest).requestLeaseAsync → (*Stopper).RunAsyncTaskEx + Created by (1): (*DistSender).divideAndSendParallelCommit → (*Stopper).RunAsyncTaskEx + → Longest run during wait: G2041 ran 646.3µs + (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker + → Queue activity: 21 goroutines ran 27 times during the wait + +[2] t=1200ms [latency] p99=1.76ms + → G2074 waited 2.43ms on P15 → Burst: 176 goroutines became runnable within ±1ms Breakdown: 329 unblocked, 13 preempted, 4 new Unblocked by (173): (*Cond).Broadcast @@ -37,76 +67,126 @@ Events: 163815 (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker → Queue activity: 9 goroutines ran 10 times during the wait -2. G2067 waited 2.41ms on P10 - → Burst: 176 goroutines became runnable within ±1ms - Breakdown: 329 unblocked, 13 preempted, 4 new - Unblocked by (173): (*Cond).Broadcast - Unblocked by (61): (*Mutex).Unlock - Unblocked by (37): (*Cond).Signal - Blocked at (207): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] - Blocked at (28): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Mutex).Lock] - Blocked at (21): (*Store).processReady → (*Replica).maybeCoalesceHeartbeat [(*Mutex).Lock] - Heavy unblocker G2158 (129): (*Store).raftTickLoop → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal - Heavy unblocker G4203943013 (45): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal - Heavy unblocker G4203890404 (10): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal - Created by (3): (*http2Server).operateHeaders → (*Server).serveStreams.func1 - Created by (1): (*txnCommitter).makeTxnCommitExplicitAsync → (*Stopper).RunAsyncTaskEx - → Longest run during wait: G2150 ran 1.04ms - (*Store).processReady → (*Replica).maybeCoalesceHeartbeat - → Queue activity: 19 goroutines ran 20 times during the wait +[3] t=1700ms [latency] p99=1.74ms + → G1925 waited 2.23ms on P6 + → Burst: 162 goroutines became runnable within ±1ms + Breakdown: 352 unblocked, 7 preempted + Unblocked by (262): (*Cond).Broadcast + Unblocked by (37): (*Mutex).Unlock + Unblocked by (19): selectnbsend + Blocked at (277): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (16): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Mutex).Lock] + Blocked at (12): (*Store).processReady → (*Replica).maybeCoalesceHeartbeat [(*Mutex).Lock] + Heavy unblocker G2158 (128): (*Store).raftTickLoop → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203943013 (120): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203944670 (12): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + → Longest run during wait: G2100 ran 860.4µs + (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker + → Queue activity: 10 goroutines ran 10 times during the wait -3. G1934 waited 2.41ms on P10 - → Burst: 176 goroutines became runnable within ±1ms - Breakdown: 329 unblocked, 13 preempted, 4 new - Unblocked by (173): (*Cond).Broadcast - Unblocked by (61): (*Mutex).Unlock - Unblocked by (37): (*Cond).Signal - Blocked at (207): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] - Blocked at (28): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Mutex).Lock] - Blocked at (21): (*Store).processReady → (*Replica).maybeCoalesceHeartbeat [(*Mutex).Lock] - Heavy unblocker G2158 (129): (*Store).raftTickLoop → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal - Heavy unblocker G4203943013 (45): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal - Heavy unblocker G4203890404 (10): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal - Created by (3): (*http2Server).operateHeaders → (*Server).serveStreams.func1 - Created by (1): (*txnCommitter).makeTxnCommitExplicitAsync → (*Stopper).RunAsyncTaskEx - → Longest run during wait: G2150 ran 1.04ms - (*Store).processReady → (*Replica).maybeCoalesceHeartbeat - → Queue activity: 18 goroutines ran 19 times during the wait +[4] t=700ms [latency] p99=1.63ms + → G2069 waited 2.30ms on P15 + → Burst: 173 goroutines became runnable within ±1ms + Breakdown: 365 unblocked, 6 preempted, 2 new + Unblocked by (243): (*Cond).Broadcast + Unblocked by (51): (*Mutex).Unlock + Unblocked by (27): (*Cond).Signal + Blocked at (262): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (23): (*Store).processReady → (*Replica).maybeCoalesceHeartbeat [(*Mutex).Lock] + Blocked at (17): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Mutex).Lock] + Heavy unblocker G2158 (128): (*Store).raftTickLoop → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203943013 (102): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203944670 (12): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Created by (2): (*http2Server).operateHeaders → (*Server).serveStreams.func1 + → Queue activity: 24 goroutines ran 26 times during the wait -4. G1927 waited 2.41ms on P9 - → Burst: 93 goroutines became runnable within ±1ms - Breakdown: 125 unblocked, 14 preempted, 3 new - Unblocked by (45): selectnbsend - Unblocked by (33): (*Mutex).Unlock - Unblocked by (11): (*Cond).Broadcast - Blocked at (19): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] - Blocked at (19): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] - Blocked at (18): (*Stopper).RunAsyncTaskEx.func2 → (*RaftTransport).processQueue [selectgo] - Heavy unblocker G4203943013 (11): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal - Heavy unblocker G2159 (9): (*Store).sendQueuedHeartbeatsToNode → (*RaftTransport).SendAsync - Heavy unblocker G1994 (5): (*Store).processReady → (*Replica).sendRaftMessageRequest → (*RaftTransport).SendAsync - Created by (1): (*DistSender).sendPartialBatchAsync → (*Stopper).RunAsyncTaskEx - Created by (1): (*pendingLeaseRequest).requestLeaseAsync → (*Stopper).RunAsyncTaskEx - Created by (1): (*DistSender).divideAndSendParallelCommit → (*Stopper).RunAsyncTaskEx - → Longest run during wait: G2041 ran 646.3µs +[5] t=2700ms [latency] p99=1.14ms + → G2073 waited 1.77ms on P10 + → Burst: 168 goroutines became runnable within ±1ms + Breakdown: 367 unblocked, 8 preempted + Unblocked by (193): (*Cond).Broadcast + Unblocked by (69): (*Mutex).Unlock + Unblocked by (58): (*Cond).Signal + Blocked at (247): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (28): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Mutex).Lock] + Blocked at (18): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Mutex).Lock] + Heavy unblocker G2158 (125): (*Store).raftTickLoop → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203943013 (78): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203954368 (9): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + → Longest run during wait: G2119 ran 670.5µs (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker - → Queue activity: 21 goroutines ran 27 times during the wait + → Queue activity: 10 goroutines ran 10 times during the wait -5. G1930 waited 2.41ms on P9 - → Burst: 93 goroutines became runnable within ±1ms - Breakdown: 125 unblocked, 14 preempted, 3 new - Unblocked by (45): selectnbsend - Unblocked by (33): (*Mutex).Unlock - Unblocked by (11): (*Cond).Broadcast - Blocked at (19): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] - Blocked at (19): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] - Blocked at (18): (*Stopper).RunAsyncTaskEx.func2 → (*RaftTransport).processQueue [selectgo] - Heavy unblocker G4203943013 (11): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal - Heavy unblocker G2159 (9): (*Store).sendQueuedHeartbeatsToNode → (*RaftTransport).SendAsync - Heavy unblocker G1994 (5): (*Store).processReady → (*Replica).sendRaftMessageRequest → (*RaftTransport).SendAsync +[6] t=1800ms [runnable] peak 129 runnable + Breakdown: 589 unblocked, 93 preempted, 50 new + Unblocked by (306): (*Cond).Signal + Unblocked by (189): selectnbsend + Unblocked by (29): (*WaitGroup).Add + Blocked at (306): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (85): (*Stopper).RunAsyncTaskEx.func2 → (*RaftTransport).processQueue [selectgo] + Blocked at (77): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Heavy unblocker G2161 (57): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G2160 (52): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G2178 (49): (*Store).enqueueRaftUpdateCheck → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (29): (*baseQueue).Async → (*Stopper).RunAsyncTaskEx + Created by (10): (*http2Server).operateHeaders → (*Server).serveStreams.func1 + Created by (1): (*replicaScanner).waitAndProcess → (*baseQueue).Async → (*Stopper).RunAsyncTaskEx + +[7] t=2600ms [runnable] peak 122 runnable + Breakdown: 335 unblocked, 21 preempted, 12 new + Unblocked by (166): (*Cond).Signal + Unblocked by (81): (*Cond).Broadcast + Unblocked by (49): selectnbsend + Blocked at (247): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (18): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Blocked at (17): (*Stopper).RunAsyncTaskEx.func2 → (*RaftTransport).processQueue [selectgo] + Heavy unblocker G4203956581 (113): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G9828 (34): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203954980 (13): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (2): (*http2Server).operateHeaders → (*Server).serveStreams.func1 + Created by (1): (*replicaScanner).waitAndProcess → (*baseQueue).Async → (*Stopper).RunAsyncTaskEx + Created by (1): (*replicaScanner).waitAndProcess → (*baseQueue).Async → (*Stopper).RunAsyncTaskEx + +[8] t=1600ms [runnable] peak 120 runnable + Breakdown: 229 unblocked, 20 preempted, 3 new + Unblocked by (123): (*Cond).Signal + Unblocked by (49): selectnbsend + Unblocked by (24): (*Cond).Broadcast + Blocked at (143): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (18): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Blocked at (16): (*Stopper).RunAsyncTaskEx.func2 → (*RaftTransport).processQueue [selectgo] + Heavy unblocker G2633 (15): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G4203954368 (15): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G4203890404 (14): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (1): (*IntentResolver).runAsyncTask → (*Stopper).RunAsyncTaskEx + Created by (1): (*IntentResolver).cleanupFinishedTxnIntents → (*Stopper).RunAsyncTaskEx + Created by (1): (*http2Server).operateHeaders → (*Server).serveStreams.func1 + +[9] t=2200ms [runnable] peak 112 runnable + Breakdown: 244 unblocked, 22 preempted, 4 new + Unblocked by (141): (*Cond).Signal + Unblocked by (42): selectnbsend + Unblocked by (28): (*Mutex).Unlock + Blocked at (137): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (23): (*Store).processReady → (*Replica).maybeCoalesceHeartbeat [(*Mutex).Lock] + Blocked at (18): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Heavy unblocker G4203890404 (24): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G4203954368 (15): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G990213 (12): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal Created by (1): (*DistSender).sendPartialBatchAsync → (*Stopper).RunAsyncTaskEx - Created by (1): (*pendingLeaseRequest).requestLeaseAsync → (*Stopper).RunAsyncTaskEx - Created by (1): (*DistSender).divideAndSendParallelCommit → (*Stopper).RunAsyncTaskEx - → Longest run during wait: G2041 ran 646.3µs - (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker - → Queue activity: 20 goroutines ran 26 times during the wait + Created by (1): (*baseQueue).Async → (*Stopper).RunAsyncTaskEx + Created by (1): (*RequestBatcher).sendBatch → (*Stopper).RunAsyncTaskEx + +[10] t=1500ms [runnable] peak 95 runnable + Breakdown: 366 unblocked, 25 preempted, 2 new + Unblocked by (152): (*Cond).Signal + Unblocked by (103): (*Cond).Broadcast + Unblocked by (60): selectnbsend + Blocked at (254): (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker [(*Cond).Wait] + Blocked at (21): newHTTP2Client.func6 → (*loopyWriter).run → (*controlBuffer).get [selectgo] + Blocked at (19): (*Buffer).ReadFrom → (*MuxConn).Read → (*conn).Read → (*netFD).Read [(*FD).Read] + Heavy unblocker G4203955801 (122): (*Store).uncoalesceBeats → (*raftScheduler).enqueueBatch → (*raftSchedulerShard).signal + Heavy unblocker G4203890404 (22): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Heavy unblocker G4203954368 (13): (*Store).HandleRaftRequest → (*raftScheduler).enqueue1 → (*raftSchedulerShard).signal + Created by (1): (*IntentResolver).runAsyncTask → (*Stopper).RunAsyncTaskEx + Created by (1): (*http2Server).operateHeaders → (*Server).serveStreams.func1