From 38648134c9f5f5ffa9f7c524934e627d67d94f92 Mon Sep 17 00:00:00 2001 From: Tobias Grieger Date: Fri, 8 May 2026 12:31:27 +0200 Subject: [PATCH] schedstat: per-cycle GC mark assist breakdown MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Replace the cross-cycle mark assist summary (and the verbose-only per-cycle table) with a single per-cycle GC detail section shown unconditionally after the sweep summary. For each GC cycle we now show: Cycle N @ t=Xms, duration: Y Mark assist: N events, M goroutines, total: T g N assists, total T, max T @ t=Xms ... Cycles with no mark assists collapse to a single "(no mark assists)" line. The previous aggregate "Mark assist: ..." line is dropped — the per-cycle view contains the same information at higher fidelity, plus the cycle that the burst belongs to. The verbose-only per-cycle table is removed since the new section subsumes it. GC analysis section order is now: cycle summary, STW, latency comparison, sweep, per-cycle detail. JSON: GCMarkAssist and the old GCPerCycleBreakdown types are removed; the new GCPerCycleDetail / GCCycleDetail / CycleAssistG types take their place. JSON goldens regenerated. Co-Authored-By: roachdev-claude --- main.go | 181 +++++++++--------- report.go | 95 ++++----- testdata/experiment-upsert1000-gateway.json | 102 +++++----- testdata/experiment-upsert1000-gateway.txt | 15 +- .../experiment-upsert1000-leaseholder.json | 152 ++++++++++----- .../experiment-upsert1000-leaseholder.txt | 23 ++- testdata/single-node-lowcpu-gcassist.json | 152 ++++++++++----- testdata/single-node-lowcpu-gcassist.txt | 23 ++- 8 files changed, 435 insertions(+), 308 deletions(-) diff --git a/main.go b/main.go index 9c136c5..448c0d5 100644 --- a/main.go +++ b/main.go @@ -651,14 +651,6 @@ func collectGCAnalysis(db *sql.DB) (*GCReport, error) { g.STW = stw } - ma, err := collectMarkAssist(db) - if err != nil { - return nil, err - } - if ma != nil { - g.MarkAssist = ma - } - cmp, err := collectGCLatencyComparison(db) if err != nil { return nil, err @@ -667,14 +659,6 @@ func collectGCAnalysis(db *sql.DB) (*GCReport, error) { g.LatencyComparison = cmp } - if opts.verbose { - pc, err := collectPerCycleBreakdown(db) - if err != nil { - return nil, err - } - g.PerCycle = pc - } - sweep, err := collectSweepSummary(db) if err != nil { return nil, err @@ -683,6 +667,14 @@ func collectGCAnalysis(db *sql.DB) (*GCReport, error) { g.Sweep = sweep } + pc, err := collectPerCycleGCDetail(db) + if err != nil { + return nil, err + } + if pc != nil { + g.PerCycle = pc + } + return g, nil } @@ -755,66 +747,6 @@ func collectSTWSummary(db *sql.DB) (*GCSTWSummary, error) { }, nil } -func collectMarkAssist(db *sql.DB) (*GCMarkAssist, error) { - var totalEvents int - var totalGoroutines int - var totalNs, maxSingleNs sql.NullFloat64 - err := db.QueryRow(` - SELECT COUNT(*), COUNT(DISTINCT scope_id), SUM(duration_ns), MAX(duration_ns) - FROM gc_ranges - WHERE name = 'GC mark assist' - `).Scan(&totalEvents, &totalGoroutines, &totalNs, &maxSingleNs) - if err != nil { - return nil, fmt.Errorf("mark assist summary: %w", err) - } - if totalEvents == 0 { - return nil, nil - } - - out := &GCMarkAssist{ - TotalEvents: totalEvents, - TotalGoroutines: totalGoroutines, - TotalNs: nullF64ToInt64Ptr(totalNs), - MaxSingleNs: nullF64ToInt64Ptr(maxSingleNs), - } - - rows, err := db.Query(` - WITH t0 AS ( - SELECT MIN(end_time_ns - duration_ns) as v FROM g_transitions - WHERE from_state = 'runnable' AND to_state = 'running' - ) - SELECT - r.scope_id, - COALESCE(g.name, '(unknown)') as gname, - COUNT(*) as assists, - SUM(r.duration_ns) as total_assist_ns, - MAX(r.duration_ns) as max_assist_ns, - (arg_max(r.start_time_ns, r.duration_ns) - (SELECT v FROM t0)) / 1e6 as worst_at_ms - FROM gc_ranges r - LEFT JOIN goroutines g ON r.scope_id = g.g - WHERE r.name = 'GC mark assist' - GROUP BY r.scope_id, gname - ORDER BY total_assist_ns DESC - LIMIT $1 - `, opts.top) - if err != nil { - return nil, fmt.Errorf("mark assist top goroutines: %w", err) - } - defer rows.Close() - - for rows.Next() { - var e MarkAssistGEntry - var totNs, mxNs float64 - if err := rows.Scan(&e.G, &e.Name, &e.Assists, &totNs, &mxNs, &e.WorstAtMs); err != nil { - return nil, err - } - e.TotalNs = int64(totNs) - e.MaxNs = int64(mxNs) - out.TopGoroutines = append(out.TopGoroutines, e) - } - return out, rows.Err() -} - func collectGCLatencyComparison(db *sql.DB) (*GCLatencyComparison, error) { var cycleCount int if err := db.QueryRow(`SELECT COUNT(*) FROM gc_cycles`).Scan(&cycleCount); err != nil { @@ -900,10 +832,26 @@ func collectGCLatencyComparison(db *sql.DB) (*GCLatencyComparison, error) { return out, nil } -func collectPerCycleBreakdown(db *sql.DB) (*GCPerCycleBreakdown, error) { - rows, err := db.Query(` +// collectPerCycleGCDetail returns one entry per GC cycle with that cycle's +// mark-assist totals and the top-N affected goroutines. Returns nil if the +// trace contains no GC cycles. +func collectPerCycleGCDetail(db *sql.DB) (*GCPerCycleDetail, error) { + var cycleCount int + if err := db.QueryRow(`SELECT COUNT(*) FROM gc_cycles`).Scan(&cycleCount); err != nil { + return nil, fmt.Errorf("gc cycle count: %w", err) + } + if cycleCount == 0 { + return nil, nil + } + + cycleRows, err := db.Query(` + WITH t0 AS ( + SELECT MIN(end_time_ns - duration_ns) as v FROM g_transitions + WHERE from_state = 'runnable' AND to_state = 'running' + ) SELECT gc.cycle, + (gc.start_time_ns - (SELECT v FROM t0)) / 1e6 as start_ms, gc.duration_ns, COUNT(r.name) as assists, COUNT(DISTINCT r.scope_id) as goroutines, @@ -913,26 +861,81 @@ func collectPerCycleBreakdown(db *sql.DB) (*GCPerCycleBreakdown, error) { ON r.name = 'GC mark assist' AND r.start_time_ns < gc.end_time_ns AND r.end_time_ns > gc.start_time_ns - GROUP BY gc.cycle, gc.duration_ns, gc.start_time_ns + GROUP BY gc.cycle, gc.start_time_ns, gc.duration_ns ORDER BY gc.start_time_ns `) if err != nil { - return nil, fmt.Errorf("per-cycle breakdown: %w", err) + return nil, fmt.Errorf("per-cycle detail: %w", err) } - defer rows.Close() + defer cycleRows.Close() - out := &GCPerCycleBreakdown{} - for rows.Next() { - var e GCCycleEntry + out := &GCPerCycleDetail{} + cycleIdx := map[int]int{} // cycle number → index in out.Cycles + for cycleRows.Next() { + var c GCCycleDetail var dur, assist float64 - if err := rows.Scan(&e.Cycle, &dur, &e.Assists, &e.Goroutines, &assist); err != nil { + if err := cycleRows.Scan(&c.Cycle, &c.StartMs, &dur, &c.AssistEvents, &c.AssistGoroutines, &assist); err != nil { return nil, err } - e.DurationNs = int64(dur) - e.AssistTimeNs = int64(assist) - out.Cycles = append(out.Cycles, e) + c.DurationNs = int64(dur) + c.AssistTotalNs = int64(assist) + cycleIdx[c.Cycle] = len(out.Cycles) + out.Cycles = append(out.Cycles, c) } - return out, rows.Err() + if err := cycleRows.Err(); err != nil { + return nil, err + } + + gRows, err := db.Query(` + WITH t0 AS ( + SELECT MIN(end_time_ns - duration_ns) as v FROM g_transitions + WHERE from_state = 'runnable' AND to_state = 'running' + ), + per_g AS ( + SELECT + gc.cycle, + r.scope_id, + COALESCE(g.name, '(unknown)') as gname, + COUNT(*) as assists, + SUM(r.duration_ns) as total_assist_ns, + MAX(r.duration_ns) as max_assist_ns, + (arg_max(r.start_time_ns, r.duration_ns) - (SELECT v FROM t0)) / 1e6 as worst_at_ms + FROM gc_cycles gc + JOIN gc_ranges r + ON r.name = 'GC mark assist' + AND r.start_time_ns < gc.end_time_ns + AND r.end_time_ns > gc.start_time_ns + LEFT JOIN goroutines g ON r.scope_id = g.g + GROUP BY gc.cycle, r.scope_id, gname + ), + ranked AS ( + SELECT *, ROW_NUMBER() OVER (PARTITION BY cycle ORDER BY total_assist_ns DESC) as rn + FROM per_g + ) + SELECT cycle, scope_id, gname, assists, total_assist_ns, max_assist_ns, worst_at_ms + FROM ranked + WHERE rn <= $1 + ORDER BY cycle, total_assist_ns DESC + `, opts.top) + if err != nil { + return nil, fmt.Errorf("per-cycle goroutines: %w", err) + } + defer gRows.Close() + + for gRows.Next() { + var cycle int + var e CycleAssistG + var totNs, mxNs float64 + if err := gRows.Scan(&cycle, &e.G, &e.Name, &e.Assists, &totNs, &mxNs, &e.WorstAtMs); err != nil { + return nil, err + } + e.TotalNs = int64(totNs) + e.MaxNs = int64(mxNs) + if i, ok := cycleIdx[cycle]; ok { + out.Cycles[i].TopGoroutines = append(out.Cycles[i].TopGoroutines, e) + } + } + return out, gRows.Err() } func collectSweepSummary(db *sql.DB) (*GCSweepSummary, error) { diff --git a/report.go b/report.go index 1aafe25..b0abdf3 100644 --- a/report.go +++ b/report.go @@ -417,10 +417,9 @@ func (r *ByCreatorReport) String() string { type GCReport struct { CycleSummary *GCCycleSummary `json:"cycle_summary,omitempty"` STW *GCSTWSummary `json:"stw,omitempty"` - MarkAssist *GCMarkAssist `json:"mark_assist,omitempty"` LatencyComparison *GCLatencyComparison `json:"latency_comparison,omitempty"` - PerCycle *GCPerCycleBreakdown `json:"per_cycle,omitempty"` Sweep *GCSweepSummary `json:"sweep,omitempty"` + PerCycle *GCPerCycleDetail `json:"per_cycle,omitempty"` } func (g *GCReport) String() string { @@ -432,18 +431,15 @@ func (g *GCReport) String() string { if g.STW != nil { b.WriteString(g.STW.String()) } - if g.MarkAssist != nil { - b.WriteString(g.MarkAssist.String()) - } if g.LatencyComparison != nil { b.WriteString(g.LatencyComparison.String()) } - if g.PerCycle != nil { - b.WriteString(g.PerCycle.String()) - } if g.Sweep != nil { b.WriteString(g.Sweep.String()) } + if g.PerCycle != nil { + b.WriteString(g.PerCycle.String()) + } return b.String() } @@ -491,39 +487,6 @@ func (g *GCSTWSummary) String() string { return b.String() } -type GCMarkAssist struct { - TotalEvents int `json:"total_events"` - TotalGoroutines int `json:"total_goroutines"` - TotalNs *int64 `json:"total_ns,omitempty"` - MaxSingleNs *int64 `json:"max_single_ns,omitempty"` - TopGoroutines []MarkAssistGEntry `json:"top_goroutines,omitempty"` -} - -type MarkAssistGEntry struct { - G int64 `json:"g"` - Name string `json:"name"` - Assists int `json:"assists"` - TotalNs int64 `json:"total_ns"` - MaxNs int64 `json:"max_ns"` - WorstAtMs float64 `json:"worst_at_ms"` -} - -func (g *GCMarkAssist) String() string { - if g.TotalEvents == 0 { - return "" - } - var b strings.Builder - fmt.Fprintf(&b, " Mark assist: %d events across %d goroutines, total: %s, max single: %s\n", - g.TotalEvents, g.TotalGoroutines, fmtNsPtr(g.TotalNs), fmtNsPtr(g.MaxSingleNs)) - b.WriteString(" Top affected goroutines:\n") - for _, e := range g.TopGoroutines { - fmt.Fprintf(&b, " g%-8d %-40s %d assists, total %s, max %s @ t=%.0fms\n", - e.G, shortenFunc(e.Name), e.Assists, - fmtDuration(float64(e.TotalNs)), fmtDuration(float64(e.MaxNs)), e.WorstAtMs) - } - return b.String() -} - type GCLatencyComparison struct { DuringGC LatencyBucket `json:"during_gc"` NonGC LatencyBucket `json:"non_gc"` @@ -559,25 +522,49 @@ func (g *GCLatencyComparison) String() string { return b.String() } -type GCPerCycleBreakdown struct { - Cycles []GCCycleEntry `json:"cycles"` +// GCPerCycleDetail is the per-cycle GC mark-assist breakdown. For each GC +// cycle we show its start time, duration, mark-assist totals, and the top +// affected goroutines (by total assist time within the cycle). +type GCPerCycleDetail struct { + Cycles []GCCycleDetail `json:"cycles"` } -type GCCycleEntry struct { - Cycle int `json:"cycle"` - DurationNs int64 `json:"duration_ns"` - Assists int `json:"assists"` - Goroutines int `json:"goroutines"` - AssistTimeNs int64 `json:"assist_time_ns"` +type GCCycleDetail struct { + Cycle int `json:"cycle"` + StartMs float64 `json:"start_ms"` + DurationNs int64 `json:"duration_ns"` + AssistEvents int `json:"assist_events"` + AssistGoroutines int `json:"assist_goroutines"` + AssistTotalNs int64 `json:"assist_total_ns"` + TopGoroutines []CycleAssistG `json:"top_goroutines,omitempty"` } -func (g *GCPerCycleBreakdown) String() string { +type CycleAssistG struct { + G int64 `json:"g"` + Name string `json:"name"` + Assists int `json:"assists"` + TotalNs int64 `json:"total_ns"` + MaxNs int64 `json:"max_ns"` + WorstAtMs float64 `json:"worst_at_ms"` +} + +func (g *GCPerCycleDetail) String() string { var b strings.Builder - b.WriteString(" Per-cycle breakdown:\n") - fmt.Fprintf(&b, " %-6s %-12s %-8s %-12s %-12s\n", "Cycle", "Duration", "Assists", "Goroutines", "Assist Time") for _, c := range g.Cycles { - fmt.Fprintf(&b, " %-6d %-12s %-8d %-12d %-12s\n", - c.Cycle, fmtDuration(float64(c.DurationNs)), c.Assists, c.Goroutines, fmtDuration(float64(c.AssistTimeNs))) + if c.AssistEvents == 0 { + fmt.Fprintf(&b, "\n Cycle %d @ t=%.0fms, duration: %s (no mark assists)\n", + c.Cycle, c.StartMs, fmtDuration(float64(c.DurationNs))) + continue + } + fmt.Fprintf(&b, "\n Cycle %d @ t=%.0fms, duration: %s\n", + c.Cycle, c.StartMs, fmtDuration(float64(c.DurationNs))) + fmt.Fprintf(&b, " Mark assist: %d events, %d goroutines, total: %s\n", + c.AssistEvents, c.AssistGoroutines, fmtDuration(float64(c.AssistTotalNs))) + for _, r := range c.TopGoroutines { + fmt.Fprintf(&b, " g%-8d %-40s %d assists, total %s, max %s @ t=%.0fms\n", + r.G, shortenFunc(r.Name), r.Assists, + fmtDuration(float64(r.TotalNs)), fmtDuration(float64(r.MaxNs)), r.WorstAtMs) + } } return b.String() } diff --git a/testdata/experiment-upsert1000-gateway.json b/testdata/experiment-upsert1000-gateway.json index 110392b..28730fb 100644 --- a/testdata/experiment-upsert1000-gateway.json +++ b/testdata/experiment-upsert1000-gateway.json @@ -1096,54 +1096,6 @@ } ] }, - "mark_assist": { - "total_events": 963, - "total_goroutines": 836, - "total_ns": 93391242, - "max_single_ns": 1255872, - "top_goroutines": [ - { - "g": 1222, - "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).raftMessageBatch.func1", - "assists": 95, - "total_ns": 11638848, - "max_ns": 1255872, - "worst_at_ms": 4266.09536 - }, - { - "g": 1012, - "name": "google.golang.org/grpc/internal/transport.(*http2Client).reader", - "assists": 7, - "total_ns": 1048768, - "max_ns": 313664, - "worst_at_ms": 4255.092992 - }, - { - "g": 1285, - "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).startProcessNewQueue.func3", - "assists": 7, - "total_ns": 715198, - "max_ns": 139840, - "worst_at_ms": 4251.602048 - }, - { - "g": 916, - "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", - "assists": 4, - "total_ns": 594176, - "max_ns": 296704, - "worst_at_ms": 4249.792192 - }, - { - "g": 919, - "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", - "assists": 4, - "total_ns": 566528, - "max_ns": 210688, - "worst_at_ms": 4249.729728 - } - ] - }, "latency_comparison": { "during_gc": { "count": 4969, @@ -1164,6 +1116,60 @@ "sweep": { "count": 376, "total_ns": 304941 + }, + "per_cycle": { + "cycles": [ + { + "cycle": 1, + "start_ms": 4249.358144, + "duration_ns": 30313984, + "assist_events": 963, + "assist_goroutines": 836, + "assist_total_ns": 93391242, + "top_goroutines": [ + { + "g": 1222, + "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).raftMessageBatch.func1", + "assists": 95, + "total_ns": 11638848, + "max_ns": 1255872, + "worst_at_ms": 4266.09536 + }, + { + "g": 1012, + "name": "google.golang.org/grpc/internal/transport.(*http2Client).reader", + "assists": 7, + "total_ns": 1048768, + "max_ns": 313664, + "worst_at_ms": 4255.092992 + }, + { + "g": 1285, + "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).startProcessNewQueue.func3", + "assists": 7, + "total_ns": 715198, + "max_ns": 139840, + "worst_at_ms": 4251.602048 + }, + { + "g": 916, + "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", + "assists": 4, + "total_ns": 594176, + "max_ns": 296704, + "worst_at_ms": 4249.792192 + }, + { + "g": 919, + "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", + "assists": 4, + "total_ns": 566528, + "max_ns": 210688, + "worst_at_ms": 4249.729728 + } + ] + } + ] } } } diff --git a/testdata/experiment-upsert1000-gateway.txt b/testdata/experiment-upsert1000-gateway.txt index a1acaf1..ff375b9 100644 --- a/testdata/experiment-upsert1000-gateway.txt +++ b/testdata/experiment-upsert1000-gateway.txt @@ -116,16 +116,17 @@ GC cycles: 1, total: 30.31ms, avg: 30.31ms, min: 30.31ms, max: 30.31ms GC sweep termination: 1 pauses, total 140.4µs, max 140.4µs GC mark termination: 1 pauses, total 125.7µs, max 125.7µs start trace: 1 pauses, total 4.2µs, max 4.2µs - Mark assist: 963 events across 836 goroutines, total: 93.39ms, max single: 1.26ms - Top affected goroutines: - g1222 kv/kvserver.(*RaftTransport).raftMessageBatch.func1 95 assists, total 11.64ms, max 1.26ms @ t=4266ms - g1012 internal/transport.(*http2Client).reader 7 assists, total 1.05ms, max 313.7µs @ t=4255ms - g1285 kv/kvserver.(*RaftTransport).startProcessNewQueue.func3 7 assists, total 715.2µs, max 139.8µs @ t=4252ms - g916 util/stop.(*Stopper).RunAsyncTaskEx.func1 4 assists, total 594.2µs, max 296.7µs @ t=4250ms - g919 util/stop.(*Stopper).RunAsyncTaskEx.func1 4 assists, total 566.5µs, max 210.7µs @ t=4250ms Scheduling latency during GC vs normal: count p50 p99 max During GC: 4969 74.6µs 7.51ms 9.44ms Non-GC: 1549443 21.3µs 502.6µs 2.40ms Ratio: 3.5x 15.0x 3.9x Sweep: 376 events, total: 304.9µs + + Cycle 1 @ t=4249ms, duration: 30.31ms + Mark assist: 963 events, 836 goroutines, total: 93.39ms + g1222 kv/kvserver.(*RaftTransport).raftMessageBatch.func1 95 assists, total 11.64ms, max 1.26ms @ t=4266ms + g1012 internal/transport.(*http2Client).reader 7 assists, total 1.05ms, max 313.7µs @ t=4255ms + g1285 kv/kvserver.(*RaftTransport).startProcessNewQueue.func3 7 assists, total 715.2µs, max 139.8µs @ t=4252ms + g916 util/stop.(*Stopper).RunAsyncTaskEx.func1 4 assists, total 594.2µs, max 296.7µs @ t=4250ms + g919 util/stop.(*Stopper).RunAsyncTaskEx.func1 4 assists, total 566.5µs, max 210.7µs @ t=4250ms diff --git a/testdata/experiment-upsert1000-leaseholder.json b/testdata/experiment-upsert1000-leaseholder.json index a549591..79906a3 100644 --- a/testdata/experiment-upsert1000-leaseholder.json +++ b/testdata/experiment-upsert1000-leaseholder.json @@ -1893,54 +1893,6 @@ } ] }, - "mark_assist": { - "total_events": 1039, - "total_goroutines": 698, - "total_ns": 97127500, - "max_single_ns": 1746624, - "top_goroutines": [ - { - "g": 1046, - "name": "github.com/cockroachdb/cockroach/pkg/ts.(*poller).start.func1", - "assists": 97, - "total_ns": 9179136, - "max_ns": 1746624, - "worst_at_ms": 9934.948672 - }, - { - "g": 2504794, - "name": "github.com/cockroachdb/pebble.(*DB).flush", - "assists": 20, - "total_ns": 5544769, - "max_ns": 1674240, - "worst_at_ms": 9943.552 - }, - { - "g": 1055, - "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", - "assists": 46, - "total_ns": 3530304, - "max_ns": 181376, - "worst_at_ms": 9923.295296 - }, - { - "g": 718, - "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", - "assists": 40, - "total_ns": 3501696, - "max_ns": 354880, - "worst_at_ms": 9937.5904 - }, - { - "g": 720, - "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", - "assists": 38, - "total_ns": 2805697, - "max_ns": 149760, - "worst_at_ms": 9927.487424 - } - ] - }, "latency_comparison": { "during_gc": { "count": 9730, @@ -1961,6 +1913,110 @@ "sweep": { "count": 3809, "total_ns": 2903876 + }, + "per_cycle": { + "cycles": [ + { + "cycle": 1, + "start_ms": 2633.9792, + "duration_ns": 31405440, + "assist_events": 26, + "assist_goroutines": 20, + "assist_total_ns": 2786497, + "top_goroutines": [ + { + "g": 4027, + "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).raftMessageBatch.func1", + "assists": 5, + "total_ns": 490560, + "max_ns": 127872, + "worst_at_ms": 2644.622208 + }, + { + "g": 3947, + "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*RaftTransport).raftMessageBatch.func1", + "assists": 3, + "total_ns": 439040, + "max_ns": 157888, + "worst_at_ms": 2644.753984 + }, + { + "g": 951, + "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2", + "assists": 1, + "total_ns": 178496, + "max_ns": 178496, + "worst_at_ms": 2634.46304 + }, + { + "g": 883, + "name": "github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*raftScheduler).Start.func2", + "assists": 1, + "total_ns": 165185, + "max_ns": 165185, + "worst_at_ms": 2644.631296 + }, + { + "g": 4378, + "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", + "assists": 1, + "total_ns": 156992, + "max_ns": 156992, + "worst_at_ms": 2644.624448 + } + ] + }, + { + "cycle": 2, + "start_ms": 9922.0496, + "duration_ns": 57142400, + "assist_events": 1013, + "assist_goroutines": 693, + "assist_total_ns": 94341003, + "top_goroutines": [ + { + "g": 1046, + "name": "github.com/cockroachdb/cockroach/pkg/ts.(*poller).start.func1", + "assists": 97, + "total_ns": 9179136, + "max_ns": 1746624, + "worst_at_ms": 9934.948672 + }, + { + "g": 2504794, + "name": "github.com/cockroachdb/pebble.(*DB).flush", + "assists": 20, + "total_ns": 5544769, + "max_ns": 1674240, + "worst_at_ms": 9943.552 + }, + { + "g": 1055, + "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", + "assists": 46, + "total_ns": 3530304, + "max_ns": 181376, + "worst_at_ms": 9923.295296 + }, + { + "g": 718, + "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", + "assists": 40, + "total_ns": 3501696, + "max_ns": 354880, + "worst_at_ms": 9937.5904 + }, + { + "g": 720, + "name": "github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func1", + "assists": 38, + "total_ns": 2805697, + "max_ns": 149760, + "worst_at_ms": 9927.487424 + } + ] + } + ] } } } diff --git a/testdata/experiment-upsert1000-leaseholder.txt b/testdata/experiment-upsert1000-leaseholder.txt index 775aafb..7d2fedd 100644 --- a/testdata/experiment-upsert1000-leaseholder.txt +++ b/testdata/experiment-upsert1000-leaseholder.txt @@ -190,16 +190,25 @@ GC cycles: 2, total: 88.55ms, avg: 44.27ms, min: 31.41ms, max: 57.14ms GC sweep termination: 2 pauses, total 659.3µs, max 429.4µs GC mark termination: 2 pauses, total 213.7µs, max 125.4µs start trace: 1 pauses, total 49.0µs, max 49.0µs - Mark assist: 1039 events across 698 goroutines, total: 97.13ms, max single: 1.75ms - Top affected goroutines: - g1046 pkg/ts.(*poller).start.func1 97 assists, total 9.18ms, max 1.75ms @ t=9935ms - g2504794 cockroachdb/pebble.(*DB).flush 20 assists, total 5.54ms, max 1.67ms @ t=9944ms - g1055 util/stop.(*Stopper).RunAsyncTaskEx.func1 46 assists, total 3.53ms, max 181.4µs @ t=9923ms - g718 util/stop.(*Stopper).RunAsyncTaskEx.func1 40 assists, total 3.50ms, max 354.9µs @ t=9938ms - g720 util/stop.(*Stopper).RunAsyncTaskEx.func1 38 assists, total 2.81ms, max 149.8µs @ t=9927ms Scheduling latency during GC vs normal: count p50 p99 max During GC: 9730 79.7µs 16.28ms 21.76ms Non-GC: 1548091 41.3µs 3.16ms 7.58ms Ratio: 1.9x 5.2x 2.9x Sweep: 3809 events, total: 2.90ms + + Cycle 1 @ t=2634ms, duration: 31.41ms + Mark assist: 26 events, 20 goroutines, total: 2.79ms + g4027 kv/kvserver.(*RaftTransport).raftMessageBatch.func1 5 assists, total 490.6µs, max 127.9µs @ t=2645ms + g3947 kv/kvserver.(*RaftTransport).raftMessageBatch.func1 3 assists, total 439.0µs, max 157.9µs @ t=2645ms + g951 kv/kvserver.(*raftScheduler).Start.func2 1 assists, total 178.5µs, max 178.5µs @ t=2634ms + g883 kv/kvserver.(*raftScheduler).Start.func2 1 assists, total 165.2µs, max 165.2µs @ t=2645ms + g4378 util/stop.(*Stopper).RunAsyncTaskEx.func1 1 assists, total 157.0µs, max 157.0µs @ t=2645ms + + Cycle 2 @ t=9922ms, duration: 57.14ms + Mark assist: 1013 events, 693 goroutines, total: 94.34ms + g1046 pkg/ts.(*poller).start.func1 97 assists, total 9.18ms, max 1.75ms @ t=9935ms + g2504794 cockroachdb/pebble.(*DB).flush 20 assists, total 5.54ms, max 1.67ms @ t=9944ms + g1055 util/stop.(*Stopper).RunAsyncTaskEx.func1 46 assists, total 3.53ms, max 181.4µs @ t=9923ms + g718 util/stop.(*Stopper).RunAsyncTaskEx.func1 40 assists, total 3.50ms, max 354.9µs @ t=9938ms + g720 util/stop.(*Stopper).RunAsyncTaskEx.func1 38 assists, total 2.81ms, max 149.8µs @ t=9927ms diff --git a/testdata/single-node-lowcpu-gcassist.json b/testdata/single-node-lowcpu-gcassist.json index fb4ab13..7e6abe1 100644 --- a/testdata/single-node-lowcpu-gcassist.json +++ b/testdata/single-node-lowcpu-gcassist.json @@ -43,54 +43,6 @@ } ] }, - "mark_assist": { - "total_events": 72, - "total_goroutines": 30, - "total_ns": 33431232, - "max_single_ns": 3481024, - "top_goroutines": [ - { - "g": 1068065, - "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", - "assists": 4, - "total_ns": 4716160, - "max_ns": 3251776, - "worst_at_ms": 73.187904 - }, - { - "g": 1067930, - "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", - "assists": 3, - "total_ns": 4379840, - "max_ns": 3481024, - "worst_at_ms": 71.874944 - }, - { - "g": 1068084, - "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", - "assists": 5, - "total_ns": 3777216, - "max_ns": 3243776, - "worst_at_ms": 72.88928 - }, - { - "g": 1058917, - "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", - "assists": 6, - "total_ns": 3502784, - "max_ns": 1643520, - "worst_at_ms": 70.568128 - }, - { - "g": 1068213, - "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", - "assists": 6, - "total_ns": 3499329, - "max_ns": 1678912, - "worst_at_ms": 75.028032 - } - ] - }, "latency_comparison": { "during_gc": { "count": 869, @@ -111,6 +63,110 @@ "sweep": { "count": 333, "total_ns": 359226 + }, + "per_cycle": { + "cycles": [ + { + "cycle": 1, + "start_ms": 69.299264, + "duration_ns": 14160768, + "assist_events": 61, + "assist_goroutines": 29, + "assist_total_ns": 28239999, + "top_goroutines": [ + { + "g": 1068065, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 4, + "total_ns": 4716160, + "max_ns": 3251776, + "worst_at_ms": 73.187904 + }, + { + "g": 1067930, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 2, + "total_ns": 4332032, + "max_ns": 3481024, + "worst_at_ms": 71.874944 + }, + { + "g": 1068084, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 5, + "total_ns": 3777216, + "max_ns": 3243776, + "worst_at_ms": 72.88928 + }, + { + "g": 1068213, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 5, + "total_ns": 3405760, + "max_ns": 1678912, + "worst_at_ms": 75.028032 + }, + { + "g": 1065731, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 4, + "total_ns": 3119040, + "max_ns": 2371648, + "worst_at_ms": 75.974848 + } + ] + }, + { + "cycle": 2, + "start_ms": 687.8688, + "duration_ns": 11623296, + "assist_events": 11, + "assist_goroutines": 10, + "assist_total_ns": 5191233, + "top_goroutines": [ + { + "g": 1068180, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 1, + "total_ns": 1966720, + "max_ns": 1966720, + "worst_at_ms": 689.48864 + }, + { + "g": 1058917, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 2, + "total_ns": 1474624, + "max_ns": 1222272, + "worst_at_ms": 689.857472 + }, + { + "g": 1068032, + "name": "github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveImpl.func4", + "assists": 1, + "total_ns": 966336, + "max_ns": 966336, + "worst_at_ms": 688.759424 + }, + { + "g": 1058474, + "name": "github.com/cockroachdb/cockroach/pkg/util/netutil.(*TCPServer).ServeWith.func1", + "assists": 1, + "total_ns": 181376, + "max_ns": 181376, + "worst_at_ms": 688.751744 + }, + { + "g": 1068107, + "name": "github.com/cockroachdb/cockroach/pkg/util/netutil.(*TCPServer).ServeWith.func1", + "assists": 1, + "total_ns": 162368, + "max_ns": 162368, + "worst_at_ms": 688.766656 + } + ] + } + ] } } } diff --git a/testdata/single-node-lowcpu-gcassist.txt b/testdata/single-node-lowcpu-gcassist.txt index f7f183c..73aee87 100644 --- a/testdata/single-node-lowcpu-gcassist.txt +++ b/testdata/single-node-lowcpu-gcassist.txt @@ -14,16 +14,25 @@ GC cycles: 2, total: 25.78ms, avg: 12.89ms, min: 11.62ms, max: 14.16ms GC mark termination: 2 pauses, total 483.1µs, max 311.6µs GC sweep termination: 2 pauses, total 228.7µs, max 137.0µs start trace: 1 pauses, total 4.5µs, max 4.5µs - Mark assist: 72 events across 30 goroutines, total: 33.43ms, max single: 3.48ms - Top affected goroutines: - g1068065 sql/pgwire.(*Server).serveImpl.func4 4 assists, total 4.72ms, max 3.25ms @ t=73ms - g1067930 sql/pgwire.(*Server).serveImpl.func4 3 assists, total 4.38ms, max 3.48ms @ t=72ms - g1068084 sql/pgwire.(*Server).serveImpl.func4 5 assists, total 3.78ms, max 3.24ms @ t=73ms - g1058917 sql/pgwire.(*Server).serveImpl.func4 6 assists, total 3.50ms, max 1.64ms @ t=71ms - g1068213 sql/pgwire.(*Server).serveImpl.func4 6 assists, total 3.50ms, max 1.68ms @ t=75ms Scheduling latency during GC vs normal: count p50 p99 max During GC: 869 4.5µs 456.6µs 1.06ms Non-GC: 22646 5.5µs 82.5µs 402.5µs Ratio: 0.8x 5.5x 2.6x Sweep: 333 events, total: 359.2µs + + Cycle 1 @ t=69ms, duration: 14.16ms + Mark assist: 61 events, 29 goroutines, total: 28.24ms + g1068065 sql/pgwire.(*Server).serveImpl.func4 4 assists, total 4.72ms, max 3.25ms @ t=73ms + g1067930 sql/pgwire.(*Server).serveImpl.func4 2 assists, total 4.33ms, max 3.48ms @ t=72ms + g1068084 sql/pgwire.(*Server).serveImpl.func4 5 assists, total 3.78ms, max 3.24ms @ t=73ms + g1068213 sql/pgwire.(*Server).serveImpl.func4 5 assists, total 3.41ms, max 1.68ms @ t=75ms + g1065731 sql/pgwire.(*Server).serveImpl.func4 4 assists, total 3.12ms, max 2.37ms @ t=76ms + + Cycle 2 @ t=688ms, duration: 11.62ms + Mark assist: 11 events, 10 goroutines, total: 5.19ms + g1068180 sql/pgwire.(*Server).serveImpl.func4 1 assists, total 1.97ms, max 1.97ms @ t=689ms + g1058917 sql/pgwire.(*Server).serveImpl.func4 2 assists, total 1.47ms, max 1.22ms @ t=690ms + g1068032 sql/pgwire.(*Server).serveImpl.func4 1 assists, total 966.3µs, max 966.3µs @ t=689ms + g1058474 util/netutil.(*TCPServer).ServeWith.func1 1 assists, total 181.4µs, max 181.4µs @ t=689ms + g1068107 util/netutil.(*TCPServer).ServeWith.func1 1 assists, total 162.4µs, max 162.4µs @ t=689ms