diff --git a/internal/tracedb/schema.sql b/internal/tracedb/schema.sql index 4f528f1..31d13b1 100644 --- a/internal/tracedb/schema.sql +++ b/internal/tracedb/schema.sql @@ -167,3 +167,22 @@ select from goroutines group by 1 order by running_ns desc, name; + +create table gc_ranges ( + name text, + scope_kind text, + scope_id bigint, + start_time_ns bigint, + end_time_ns bigint, + duration_ns bigint, + stack_id ubigint, + g bigint, + p bigint +); + +create view gc_cycles as +select + row_number() over (order by start_time_ns) as cycle, + start_time_ns, end_time_ns, duration_ns +from gc_ranges +where name = 'GC concurrent mark phase'; diff --git a/internal/tracedb/tracedb.go b/internal/tracedb/tracedb.go index 9793706..d5cf4f8 100644 --- a/internal/tracedb/tracedb.go +++ b/internal/tracedb/tracedb.go @@ -98,6 +98,7 @@ func (db *DB) loadTrace(ctx context.Context, r io.Reader) (err error) { gIdx := map[trace.GoID]*gState{} pIdx := map[trace.ProcID]*pState{} + rIdx := map[rangeKey]*rangeState{} for first := true; ; first = false { var ev trace.Event if ev, err = tr.ReadEvent(); err == io.EOF { @@ -231,6 +232,46 @@ func (db *DB) loadTrace(ctx context.Context, r io.Reader) (err error) { } g.time = ev.Time() } + case trace.EventRangeBegin, trace.EventRangeActive: + r := ev.Range() + key := rangeKey{ + name: r.Name, + scopeKind: r.Scope.Kind, + scopeID: scopeIDFromRange(r), + } + rIdx[key] = &rangeState{ + start: ev.Time(), + stackID: srcStackID, + g: ev.Goroutine(), + p: ev.Proc(), + } + case trace.EventRangeEnd: + r := ev.Range() + key := rangeKey{ + name: r.Name, + scopeKind: r.Scope.Kind, + scopeID: scopeIDFromRange(r), + } + rs, ok := rIdx[key] + if !ok { + break + } + delete(rIdx, key) + dt := uint64(ev.Time() - rs.start) + scopeKind, scopeID := scopeFromRange(r) + if err = l.Append("gc_ranges", + r.Name, + scopeKind, + scopeID, + uint64(rs.start), + uint64(ev.Time()), + dt, + nullableUint64(rs.stackID), + nullableResource(rs.g), + nullableResource(rs.p), + ); err != nil { + return + } } } return @@ -267,6 +308,41 @@ type pState struct { time trace.Time } +type rangeKey struct { + name string + scopeKind trace.ResourceKind + scopeID int64 +} + +type rangeState struct { + start trace.Time + stackID uint64 + g trace.GoID + p trace.ProcID +} + +func scopeFromRange(r trace.Range) (kind string, id any) { + switch r.Scope.Kind { + case trace.ResourceGoroutine: + return "goroutine", int64(r.Scope.Goroutine()) + case trace.ResourceProc: + return "proc", int64(r.Scope.Proc()) + default: + return "none", nil + } +} + +func scopeIDFromRange(r trace.Range) int64 { + switch r.Scope.Kind { + case trace.ResourceGoroutine: + return int64(r.Scope.Goroutine()) + case trace.ResourceProc: + return int64(r.Scope.Proc()) + default: + return 0 + } +} + func (db *DB) loader(ctx context.Context) (*loader, error) { l := &loader{ funcIdx: map[functionKey]*functionRow{}, diff --git a/main.go b/main.go index 7a1866c..e2cacff 100644 --- a/main.go +++ b/main.go @@ -69,7 +69,7 @@ Examples: 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.gc, "gc", true, "show GC analysis from range events") 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.IntVarP(&opts.top, "top", "n", 5, "number of spike listings and detail entries") @@ -537,49 +537,325 @@ func printByCreator(db *sql.DB, w io.Writer) error { } func printGCAnalysis(db *sql.DB, w io.Writer) error { - fmt.Fprintln(w, "\n--- GC-Related Activity ---") + // Check if there's any GC data at all. + var totalRanges int + if err := db.QueryRow(`SELECT COUNT(*) FROM gc_ranges`).Scan(&totalRanges); err != nil { + return fmt.Errorf("gc range count: %w", err) + } + if totalRanges == 0 { + return nil + } + + fmt.Fprintln(w, "\n--- GC Analysis ---") + + // 3a. GC Cycle Summary + if err := printGCCycleSummary(db, w); err != nil { + return err + } + + // 3b. STW Summary + if err := printSTWSummary(db, w); err != nil { + return err + } + + // 3c. Mark Assist + if err := printMarkAssist(db, w); err != nil { + return err + } + + // 3d. Scheduling Latency: During GC vs Normal + if err := printGCLatencyComparison(db, w); err != nil { + return err + } + + // 3e. Per-Cycle Breakdown (verbose only) + if opts.verbose { + if err := printPerCycleBreakdown(db, w); err != nil { + return err + } + } + + // 3f. Sweep Summary + if err := printSweepSummary(db, w); err != nil { + return err + } + + return nil +} + +func printGCCycleSummary(db *sql.DB, w io.Writer) error { + var count int + var totalNs, avgNs, minNs, maxNs sql.NullFloat64 + err := db.QueryRow(` + SELECT COUNT(*), SUM(duration_ns), AVG(duration_ns), MIN(duration_ns), MAX(duration_ns) + FROM gc_ranges + WHERE name = 'GC concurrent mark phase' + `).Scan(&count, &totalNs, &avgNs, &minNs, &maxNs) + if err != nil { + return fmt.Errorf("gc cycle summary: %w", err) + } + if count == 0 { + fmt.Fprintln(w, "GC cycles: 0") + return nil + } + fmt.Fprintf(w, "GC cycles: %d, total: %s, avg: %s, min: %s, max: %s\n", + count, fmtNullDuration(totalNs), fmtNullDuration(avgNs), fmtNullDuration(minNs), fmtNullDuration(maxNs)) + return nil +} +func printSTWSummary(db *sql.DB, w io.Writer) error { rows, err := db.Query(` SELECT - from_state, - to_state, - reason, - COUNT(*) as transitions, + regexp_extract(name, '\((.*)\)', 1) as reason, + COUNT(*) as cnt, SUM(duration_ns) as total_ns, MAX(duration_ns) as max_ns - FROM g_transitions - WHERE reason LIKE '%GC%' - OR reason LIKE '%gc%' - OR from_state LIKE '%gc%' - OR to_state LIKE '%gc%' - GROUP BY 1, 2, 3 + FROM gc_ranges + WHERE name LIKE 'stop-the-world%' + GROUP BY 1 ORDER BY total_ns DESC + `) + if err != nil { + return fmt.Errorf("stw query: %w", err) + } + defer rows.Close() + + type stwEntry struct { + reason string + count int + totalNs float64 + maxNs float64 + } + var entries []stwEntry + var totalCount int + var totalNs, overallMax float64 + + for rows.Next() { + var e stwEntry + if err := rows.Scan(&e.reason, &e.count, &e.totalNs, &e.maxNs); err != nil { + return err + } + entries = append(entries, e) + totalCount += e.count + totalNs += e.totalNs + if e.maxNs > overallMax { + overallMax = e.maxNs + } + } + if err := rows.Err(); err != nil { + return err + } + + if totalCount == 0 { + return nil + } + + fmt.Fprintf(w, " STW pauses: %d, total: %s, max: %s\n", + totalCount, fmtDuration(totalNs), fmtDuration(overallMax)) + for _, e := range entries { + fmt.Fprintf(w, " %s: %d pauses, total %s, max %s\n", + e.reason, e.count, fmtDuration(e.totalNs), fmtDuration(e.maxNs)) + } + return nil +} + +func printMarkAssist(db *sql.DB, w io.Writer) 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 fmt.Errorf("mark assist summary: %w", err) + } + if totalEvents == 0 { + return nil + } + + fmt.Fprintf(w, " Mark assist: %d events across %d goroutines, total: %s, max single: %s\n", + totalEvents, totalGoroutines, fmtNullDuration(totalNs), fmtNullDuration(maxSingleNs)) + + // Top affected goroutines + 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*2) + `, opts.top) if err != nil { - return fmt.Errorf("gc query: %w", err) + return fmt.Errorf("mark assist top goroutines: %w", err) } defer rows.Close() - hasRows := false + fmt.Fprintln(w, " Top affected goroutines:") for rows.Next() { - hasRows = true - var fromState, toState, reason string - var transitions int - var totalNs, maxNs float64 - if err := rows.Scan(&fromState, &toState, &reason, &transitions, &totalNs, &maxNs); err != nil { + var scopeID int64 + var gname string + var assists int + var totalAssistNs, maxAssistNs, worstAtMs float64 + if err := rows.Scan(&scopeID, &gname, &assists, &totalAssistNs, &maxAssistNs, &worstAtMs); err != nil { return err } - fmt.Fprintf(w, " %s → %s (%s)\n", fromState, toState, reason) - fmt.Fprintf(w, " %d transitions, total: %s, max: %s\n", - transitions, fmtDuration(totalNs), fmtDuration(maxNs)) + fmt.Fprintf(w, " G%-8d %-40s %d assists, total %s, max %s @ t=%.0fms\n", + scopeID, shortenFunc(gname), assists, fmtDuration(totalAssistNs), fmtDuration(maxAssistNs), worstAtMs) } - if !hasRows { - fmt.Fprintln(w, " No GC-related transitions found.") + return rows.Err() +} + +func printGCLatencyComparison(db *sql.DB, w io.Writer) error { + // Check if we have any GC cycles to compare against + var cycleCount int + if err := db.QueryRow(`SELECT COUNT(*) FROM gc_cycles`).Scan(&cycleCount); err != nil { + return fmt.Errorf("gc cycle count: %w", err) + } + if cycleCount == 0 { + return nil + } + + type latencyStats struct { + count int + p50 sql.NullFloat64 + p99 sql.NullFloat64 + max sql.NullFloat64 + } + + var duringGC, nonGC latencyStats + err := db.QueryRow(` + SELECT + COUNT(*), + PERCENTILE_CONT(0.50) WITHIN GROUP (ORDER BY duration_ns), + PERCENTILE_CONT(0.99) WITHIN GROUP (ORDER BY duration_ns), + MAX(duration_ns) + FROM g_transitions gt + WHERE from_state = 'runnable' AND to_state = 'running' + AND EXISTS ( + SELECT 1 FROM gc_cycles gc + WHERE gt.end_time_ns - gt.duration_ns < gc.end_time_ns + AND gt.end_time_ns > gc.start_time_ns + ) + `).Scan(&duringGC.count, &duringGC.p50, &duringGC.p99, &duringGC.max) + if err != nil { + return fmt.Errorf("gc latency during: %w", err) + } + + err = db.QueryRow(` + SELECT + COUNT(*), + PERCENTILE_CONT(0.50) WITHIN GROUP (ORDER BY duration_ns), + PERCENTILE_CONT(0.99) WITHIN GROUP (ORDER BY duration_ns), + MAX(duration_ns) + FROM g_transitions gt + WHERE from_state = 'runnable' AND to_state = 'running' + AND NOT EXISTS ( + SELECT 1 FROM gc_cycles gc + WHERE gt.end_time_ns - gt.duration_ns < gc.end_time_ns + AND gt.end_time_ns > gc.start_time_ns + ) + `).Scan(&nonGC.count, &nonGC.p50, &nonGC.p99, &nonGC.max) + if err != nil { + return fmt.Errorf("gc latency non-gc: %w", err) + } + + if duringGC.count == 0 { + return nil + } + + fmt.Fprintln(w, " Scheduling latency during GC vs normal:") + fmt.Fprintf(w, " %-14s %-10s %-10s %-10s %-10s\n", "", "count", "p50", "p99", "max") + fmt.Fprintf(w, " %-14s %-10d %-10s %-10s %-10s\n", + "During GC:", duringGC.count, fmtNullDuration(duringGC.p50), fmtNullDuration(duringGC.p99), fmtNullDuration(duringGC.max)) + fmt.Fprintf(w, " %-14s %-10d %-10s %-10s %-10s\n", + "Non-GC:", nonGC.count, fmtNullDuration(nonGC.p50), fmtNullDuration(nonGC.p99), fmtNullDuration(nonGC.max)) + + if nonGC.p50.Valid && nonGC.p50.Float64 > 0 && duringGC.p50.Valid { + p50Ratio := duringGC.p50.Float64 / nonGC.p50.Float64 + p99Ratio := 0.0 + if nonGC.p99.Valid && nonGC.p99.Float64 > 0 && duringGC.p99.Valid { + p99Ratio = duringGC.p99.Float64 / nonGC.p99.Float64 + } + maxRatio := 0.0 + if nonGC.max.Valid && nonGC.max.Float64 > 0 && duringGC.max.Valid { + maxRatio = duringGC.max.Float64 / nonGC.max.Float64 + } + fmt.Fprintf(w, " %-14s %-10s %-10s %-10s %-10s\n", + "Ratio:", "", fmt.Sprintf("%.1fx", p50Ratio), fmt.Sprintf("%.1fx", p99Ratio), fmt.Sprintf("%.1fx", maxRatio)) + } + + return nil +} + +func printPerCycleBreakdown(db *sql.DB, w io.Writer) error { + rows, err := db.Query(` + SELECT + gc.cycle, + gc.duration_ns, + COUNT(r.name) as assists, + COUNT(DISTINCT r.scope_id) as goroutines, + COALESCE(SUM(r.duration_ns), 0) as assist_time_ns + FROM gc_cycles gc + LEFT 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 + GROUP BY gc.cycle, gc.duration_ns, gc.start_time_ns + ORDER BY gc.start_time_ns + `) + if err != nil { + return fmt.Errorf("per-cycle breakdown: %w", err) + } + defer rows.Close() + + fmt.Fprintln(w, " Per-cycle breakdown:") + fmt.Fprintf(w, " %-6s %-12s %-8s %-12s %-12s\n", "Cycle", "Duration", "Assists", "Goroutines", "Assist Time") + for rows.Next() { + var cycle int + var durationNs float64 + var assists, goroutines int + var assistTimeNs float64 + if err := rows.Scan(&cycle, &durationNs, &assists, &goroutines, &assistTimeNs); err != nil { + return err + } + fmt.Fprintf(w, " %-6d %-12s %-8d %-12d %-12s\n", + cycle, fmtDuration(durationNs), assists, goroutines, fmtDuration(assistTimeNs)) } return rows.Err() } +func printSweepSummary(db *sql.DB, w io.Writer) error { + var count int + var totalNs sql.NullFloat64 + err := db.QueryRow(` + SELECT COUNT(*), SUM(duration_ns) + FROM gc_ranges + WHERE name = 'GC incremental sweep' + `).Scan(&count, &totalNs) + if err != nil { + return fmt.Errorf("sweep summary: %w", err) + } + if count == 0 { + return nil + } + fmt.Fprintf(w, " Sweep: %d events, total: %s\n", + count, fmtNullDuration(totalNs)) + return nil +} + func printBurstAnalysis(db *sql.DB, w io.Writer, window time.Duration) error { // Use 1ms micro-windows to detect bursts microWindowNs := int64(1e6) // 1ms diff --git a/main_test.go b/main_test.go index 5471497..3db09d3 100644 --- a/main_test.go +++ b/main_test.go @@ -48,6 +48,7 @@ func testOpts() struct { window: 100 * time.Millisecond, spikeThreshold: 1 * time.Millisecond, goroutineThreshold: 40, // fixed value for deterministic output + gc: true, top: 5, } } @@ -116,8 +117,8 @@ func TestGoroutineThreshold(t *testing.T) { } tests := []struct { - name string - goroutineThreshold int + name string + goroutineThreshold int wantGoroutineSpikes bool }{ {"low_threshold_triggers", 80, true}, diff --git a/testdata/experiment-upsert1000-gateway.txt b/testdata/experiment-upsert1000-gateway.txt index bfa9947..40e53a4 100644 --- a/testdata/experiment-upsert1000-gateway.txt +++ b/testdata/experiment-upsert1000-gateway.txt @@ -109,3 +109,23 @@ Events: 1554412 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 + +--- GC Analysis --- +GC cycles: 1, total: 30.31ms, avg: 30.31ms, min: 30.31ms, max: 30.31ms + STW pauses: 3, total: 270.3µs, max: 140.4µs + 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 diff --git a/testdata/experiment-upsert1000-leaseholder.txt b/testdata/experiment-upsert1000-leaseholder.txt index 45a9317..bcd3cdd 100644 --- a/testdata/experiment-upsert1000-leaseholder.txt +++ b/testdata/experiment-upsert1000-leaseholder.txt @@ -183,3 +183,23 @@ Events: 1557821 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 + +--- GC Analysis --- +GC cycles: 2, total: 88.55ms, avg: 44.27ms, min: 31.41ms, max: 57.14ms + STW pauses: 5, total: 922.0µs, max: 429.4µs + 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 diff --git a/testdata/microspikes_ticks_heartbeats.txt b/testdata/microspikes_ticks_heartbeats.txt index dbd919b..883eaa0 100644 --- a/testdata/microspikes_ticks_heartbeats.txt +++ b/testdata/microspikes_ticks_heartbeats.txt @@ -190,3 +190,8 @@ Events: 163815 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 + +--- GC Analysis --- +GC cycles: 0 + STW pauses: 1, total: 4.5µs, max: 4.5µs + start trace: 1 pauses, total 4.5µs, max 4.5µs diff --git a/testdata/single-node-lowcpu-gcassist.bin b/testdata/single-node-lowcpu-gcassist.bin new file mode 100644 index 0000000..b5cd19a Binary files /dev/null and b/testdata/single-node-lowcpu-gcassist.bin differ diff --git a/testdata/single-node-lowcpu-gcassist.txt b/testdata/single-node-lowcpu-gcassist.txt new file mode 100644 index 0000000..e3ed975 --- /dev/null +++ b/testdata/single-node-lowcpu-gcassist.txt @@ -0,0 +1,29 @@ +schedstat: single-node-lowcpu-gcassist.bin +============================================================ + +Trace duration: 1050.7ms + +--- Scheduling Latency (runnable → running) --- +Events: 23515 + min: 1ns p50: 5.5µs p90: 50.0µs + avg: 15.1µs p99: 87.3µs max: 1.06ms + +--- GC Analysis --- +GC cycles: 2, total: 25.78ms, avg: 12.89ms, min: 11.62ms, max: 14.16ms + STW pauses: 5, total: 716.3µs, max: 311.6µs + 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