diff --git a/main.go b/main.go index 54d3be8..7a1866c 100644 --- a/main.go +++ b/main.go @@ -4,6 +4,7 @@ package main import ( "database/sql" "fmt" + "io" "os" "os/exec" "path/filepath" @@ -11,8 +12,6 @@ import ( "syscall" "time" - "io" - "github.com/dt/schedstat/internal/tracedb" _ "github.com/marcboeker/go-duckdb" "github.com/spf13/cobra" @@ -360,7 +359,9 @@ type spikeInfo struct { spikeType spikeType } -func queryLatencySpikes(db *sql.DB, minTime int64, window, threshold time.Duration, top int) ([]spikeInfo, int, error) { +func queryLatencySpikes( + db *sql.DB, minTime int64, window, threshold time.Duration, top int, +) ([]spikeInfo, int, error) { windowNs := window.Nanoseconds() thresholdNs := float64(threshold.Nanoseconds()) @@ -400,7 +401,9 @@ func queryLatencySpikes(db *sql.DB, minTime int64, window, threshold time.Durati return spikes, total, rows.Err() } -func queryRunnableSpikes(db *sql.DB, minTime int64, window time.Duration, runnableThreshold, top int) ([]spikeInfo, int, error) { +func queryRunnableSpikes( + db *sql.DB, minTime int64, window time.Duration, runnableThreshold, top int, +) ([]spikeInfo, int, error) { windowMs := window.Milliseconds() rows, err := db.Query(` @@ -453,7 +456,9 @@ func queryRunnableSpikes(db *sql.DB, minTime int64, window time.Duration, runnab return spikes, total, rows.Err() } -func printLatencySpikesSection(w io.Writer, spikes []spikeInfo, total int, window, threshold time.Duration) { +func printLatencySpikesSection( + w io.Writer, spikes []spikeInfo, total int, window, threshold time.Duration, +) { if total == 0 { return } @@ -472,7 +477,9 @@ func printLatencySpikesSection(w io.Writer, spikes []spikeInfo, total int, windo } } -func printRunnableSpikesSection(w io.Writer, spikes []spikeInfo, total int, window time.Duration, runnableThreshold int) { +func printRunnableSpikesSection( + w io.Writer, spikes []spikeInfo, total int, window time.Duration, runnableThreshold int, +) { if total == 0 { return } @@ -720,14 +727,16 @@ func printWorstDelays(db *sql.DB, w io.Writer, n int) error { return err } stack := parseStackArray(stackStr) - fmt.Fprintf(w, "\n%d. G%d waited %s\n", rank, g, fmtDuration(durationNs)) + fmt.Fprintf(w, "\n%d. g%d waited %s\n", rank, g, fmtDuration(durationNs)) fmt.Fprintf(w, " %s\n", formatStack(stack, 100)) rank++ } return rows.Err() } -func printSpikeDetails(db *sql.DB, w io.Writer, spikes []spikeInfo, minTime int64, window time.Duration) error { +func printSpikeDetails( + db *sql.DB, w io.Writer, spikes []spikeInfo, minTime int64, window time.Duration, +) error { fmt.Fprintf(w, "\n--- Spike Details ---\n") windowNs := window.Nanoseconds() @@ -779,7 +788,7 @@ func printLatencySpikeDetail(db *sql.DB, w io.Writer, s spikeInfo, minTime, wind return fmt.Errorf("worst delay query: %w", err) } - fmt.Fprintf(w, " → G%d waited %s", g, fmtDuration(durationNs)) + fmt.Fprintf(w, " → g%d waited %s", g, fmtDuration(durationNs)) if srcP.Valid { fmt.Fprintf(w, " on P%d", srcP.Int64) } @@ -843,7 +852,7 @@ func printLatencySpikeDetail(db *sql.DB, w io.Writer, s spikeInfo, minTime, wind if longestRunNs.Valid && longestRunNs.Float64 > 500000 { // > 500µs stack := parseStackArray(longestRunStack.String) - fmt.Fprintf(w, " → Longest run during wait: G%d ran %s\n", + 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)) @@ -862,7 +871,9 @@ func printLatencySpikeDetail(db *sql.DB, w io.Writer, s spikeInfo, minTime, wind return nil } -func printRunnableSpikeDetail(db *sql.DB, w io.Writer, s spikeInfo, minTime int64, window time.Duration) error { +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 @@ -1185,9 +1196,9 @@ func printHeavyUnblockers(db *sql.DB, w io.Writer, runnableStartNs int64) error } if stackStr.Valid { stack := parseStackArray(stackStr.String) - fmt.Fprintf(w, " Heavy unblocker G%d (%d): %s\n", srcG, cnt, formatStack(stack, 100)) + fmt.Fprintf(w, " Heavy unblocker g%d (%d): %s\n", srcG, cnt, formatStack(stack, 100)) } else { - fmt.Fprintf(w, " Heavy unblocker G%d (%d): (unknown stack)\n", srcG, cnt) + fmt.Fprintf(w, " Heavy unblocker g%d (%d): (unknown stack)\n", srcG, cnt) } } return rows.Err() @@ -1261,7 +1272,7 @@ func printTopGoroutines(db *sql.DB, w io.Writer) error { return err } stack := parseStackArray(stackStr) - fmt.Fprintf(w, " G%-6d %s\n", g, formatStack(stack, 80)) + fmt.Fprintf(w, " g%-6d %s\n", g, formatStack(stack, 80)) fmt.Fprintf(w, " %d schedulings, total: %s, max: %s\n", schedCount, fmtDuration(totalWait), fmtDuration(maxWait)) } diff --git a/testdata/experiment-upsert1000-gateway.txt b/testdata/experiment-upsert1000-gateway.txt index a2475a6..bfa9947 100644 --- a/testdata/experiment-upsert1000-gateway.txt +++ b/testdata/experiment-upsert1000-gateway.txt @@ -25,7 +25,7 @@ Events: 1554412 --- Spike Details --- [1] t=4200ms [latency] p99=6.85ms - → G852 waited 9.44ms on P6 + → g852 waited 9.44ms on P6 → Burst: 125 goroutines became runnable within ±1ms Breakdown: 139 unblocked Unblocked by (94): selectgo @@ -34,10 +34,10 @@ Events: 1554412 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 + 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 @@ -49,9 +49,9 @@ Events: 1554412 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 + 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 @@ -62,9 +62,9 @@ Events: 1554412 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 + 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 @@ -75,9 +75,9 @@ Events: 1554412 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 + 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 @@ -90,9 +90,9 @@ Events: 1554412 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 + 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 @@ -104,8 +104,8 @@ Events: 1554412 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 + 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.txt b/testdata/experiment-upsert1000-leaseholder.txt index ff94a8e..45a9317 100644 --- a/testdata/experiment-upsert1000-leaseholder.txt +++ b/testdata/experiment-upsert1000-leaseholder.txt @@ -29,7 +29,7 @@ Events: 1557821 --- Spike Details --- [1] t=9900ms [latency] p99=15.94ms - → G2508080 waited 21.76ms on P5 + → 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 @@ -41,15 +41,15 @@ Events: 1557821 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 + 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 + → 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 @@ -58,14 +58,14 @@ Events: 1557821 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 + 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 + → 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 @@ -74,14 +74,14 @@ Events: 1557821 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 + 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 + → 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 @@ -90,16 +90,16 @@ Events: 1557821 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 + 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 + → 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 @@ -108,9 +108,9 @@ Events: 1557821 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 + 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 @@ -123,9 +123,9 @@ Events: 1557821 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 + 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 @@ -137,9 +137,9 @@ Events: 1557821 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 + 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 @@ -152,9 +152,9 @@ Events: 1557821 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 + 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 @@ -167,9 +167,9 @@ Events: 1557821 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 + 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 @@ -180,6 +180,6 @@ Events: 1557821 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 + 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 b55b721..dbd919b 100644 --- a/testdata/microspikes_ticks_heartbeats.txt +++ b/testdata/microspikes_ticks_heartbeats.txt @@ -29,7 +29,7 @@ Events: 163815 --- Spike Details --- [1] t=2200ms [latency] p99=1.83ms - → G1927 waited 2.41ms on P9 + → g1927 waited 2.41ms on P9 → Burst: 93 goroutines became runnable within ±1ms Breakdown: 125 unblocked, 14 preempted, 3 new Unblocked by (45): selectnbsend @@ -38,18 +38,18 @@ Events: 163815 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 + 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 + → 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 + → 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 @@ -58,17 +58,17 @@ Events: 163815 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 + 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: G1936 ran 620.1µs + → Longest run during wait: g1936 ran 620.1µs (*raftScheduler).Start.func2 → (*raftSchedulerShard).worker → Queue activity: 9 goroutines ran 10 times during the wait [3] t=1700ms [latency] p99=1.74ms - → G1925 waited 2.23ms on P6 + → g1925 waited 2.23ms on P6 → Burst: 162 goroutines became runnable within ±1ms Breakdown: 352 unblocked, 7 preempted Unblocked by (262): (*Cond).Broadcast @@ -77,15 +77,15 @@ Events: 163815 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 + 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 [4] t=700ms [latency] p99=1.63ms - → G2069 waited 2.30ms on P15 + → 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 @@ -94,14 +94,14 @@ Events: 163815 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 + 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 [5] t=2700ms [latency] p99=1.14ms - → G2073 waited 1.77ms on P10 + → g2073 waited 1.77ms on P10 → Burst: 168 goroutines became runnable within ±1ms Breakdown: 367 unblocked, 8 preempted Unblocked by (193): (*Cond).Broadcast @@ -110,10 +110,10 @@ Events: 163815 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 + 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: 10 goroutines ran 10 times during the wait @@ -125,9 +125,9 @@ Events: 163815 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 + 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 @@ -140,9 +140,9 @@ Events: 163815 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 + 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 @@ -155,9 +155,9 @@ Events: 163815 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 + 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 @@ -170,9 +170,9 @@ Events: 163815 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 + 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): (*baseQueue).Async → (*Stopper).RunAsyncTaskEx Created by (1): (*RequestBatcher).sendBatch → (*Stopper).RunAsyncTaskEx @@ -185,8 +185,8 @@ Events: 163815 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 + 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