|
| 1 | +// Copyright 2025 The LevelDB-Go and Pebble Authors. All rights reserved. Use |
| 2 | +// of this source code is governed by a BSD-style license that can be found in |
| 3 | +// the LICENSE file. |
| 4 | + |
| 5 | +// Package inflight provides a lightweight, sharded tracker for reporting |
| 6 | +// long-running operations. |
| 7 | +package inflight |
| 8 | + |
| 9 | +import ( |
| 10 | + "cmp" |
| 11 | + "fmt" |
| 12 | + "iter" |
| 13 | + "maps" |
| 14 | + "runtime" |
| 15 | + "slices" |
| 16 | + "strings" |
| 17 | + "sync" |
| 18 | + "sync/atomic" |
| 19 | + "time" |
| 20 | + |
| 21 | + "github.com/cockroachdb/crlib/crsync" |
| 22 | + "github.com/cockroachdb/crlib/crtime" |
| 23 | + "github.com/puzpuzpuz/xsync/v3" |
| 24 | +) |
| 25 | + |
| 26 | +// Tracker is a lightweight, sharded tracker for detecting long-running |
| 27 | +// operations. Call Start() at the beginning of an operation and Stop() when it |
| 28 | +// completes; if an operation exceeds a configured age threshold, a formatted |
| 29 | +// report that includes the caller stack of Start() can be produced via Report, |
| 30 | +// or periodically via NewPollingTracker. |
| 31 | +// |
| 32 | +// The tracker is concurrency-safe and designed to have very low overhead in the |
| 33 | +// common path (Start/Stop). Observability work (capturing up to a small fixed |
| 34 | +// number of program counters and formatting stack frames) is deferred to when a |
| 35 | +// report is requested. |
| 36 | +// |
| 37 | +// Example: |
| 38 | +// |
| 39 | +// pollInterval := time.Minute |
| 40 | +// maxAge := 10 * time.Minute |
| 41 | +// t := NewPollingTracker(pollInterval, maxAge, func(r string) { |
| 42 | +// log.Infof(ctx, "slow operations:\n%s", r) |
| 43 | +// }) |
| 44 | +// defer t.Close() |
| 45 | +// |
| 46 | +// h := t.Start() |
| 47 | +// // ... do work ... |
| 48 | +// t.Stop(h) |
| 49 | +// |
| 50 | +// If any operations have been running for more than 10 minutes, the report |
| 51 | +// function is called every 1 minute with a human‑readable dump that deduplicates |
| 52 | +// by Start() stack trace and shows the oldest occurrence per trace. |
| 53 | +type Tracker struct { |
| 54 | + // The tracker has a fixed number of shards to reduce contention on |
| 55 | + // Start/Stop. The first byte of Handle identifies the shard that was used |
| 56 | + // during Start(). |
| 57 | + |
| 58 | + // Both maps and handleCounters have one entry per shard. We separate them |
| 59 | + // because the map pointers don't change. |
| 60 | + maps []*xsync.MapOf[Handle, entry] |
| 61 | + handleCounters []handleCounter |
| 62 | + |
| 63 | + mu struct { |
| 64 | + sync.Mutex |
| 65 | + // timer is non-nil if this tracker was created with NewPollingTracker() and |
| 66 | + // hasn't been closed yet. |
| 67 | + timer *time.Timer |
| 68 | + } |
| 69 | +} |
| 70 | + |
| 71 | +// Handle uniquely identifies a started operation. Treat it as an opaque token. |
| 72 | +// A zero Handle is not valid. |
| 73 | +type Handle uint64 |
| 74 | + |
| 75 | +// ReportFn is called (typically periodically) with a formatted report that |
| 76 | +// describes entries older than some threshold. An empty string report is never |
| 77 | +// delivered by the polling tracker. |
| 78 | +// |
| 79 | +// See Tracker.Report() for details on the report format. |
| 80 | +type ReportFn func(report string) |
| 81 | + |
| 82 | +// NewTracker creates a new tracker that can be used to generate reports on |
| 83 | +// long-running operations. It does not start any background goroutines; callers |
| 84 | +// can invoke Report() on demand. |
| 85 | +func NewTracker() *Tracker { |
| 86 | + return newTracker(crsync.NumShards()) |
| 87 | +} |
| 88 | + |
| 89 | +// NewPollingTracker creates a new tracker that will periodically generate |
| 90 | +// reports on long-running operations. |
| 91 | +// |
| 92 | +// Specifically, every pollInterval, reportFn will be called if there are |
| 93 | +// operations that have been running for more than maxAge. |
| 94 | +// |
| 95 | +// The tracker must be closed with Close() when no longer needed. |
| 96 | +func NewPollingTracker( |
| 97 | + pollInterval time.Duration, maxAge time.Duration, reportFn ReportFn, |
| 98 | +) *Tracker { |
| 99 | + t := newTracker(crsync.NumShards()) |
| 100 | + |
| 101 | + t.mu.Lock() |
| 102 | + defer t.mu.Unlock() |
| 103 | + t.mu.timer = time.AfterFunc(pollInterval, func() { |
| 104 | + t.mu.Lock() |
| 105 | + defer t.mu.Unlock() |
| 106 | + if t.mu.timer == nil { |
| 107 | + // Close was called. |
| 108 | + return |
| 109 | + } |
| 110 | + if report := t.Report(maxAge); report != "" { |
| 111 | + reportFn(report) |
| 112 | + } |
| 113 | + t.mu.timer.Reset(pollInterval) |
| 114 | + }) |
| 115 | + return t |
| 116 | +} |
| 117 | + |
| 118 | +// Close stops background polling (if enabled). |
| 119 | +// |
| 120 | +// Note that Start, Stop, and Report can still be used during/after Close. |
| 121 | +func (t *Tracker) Close() { |
| 122 | + t.mu.Lock() |
| 123 | + defer t.mu.Unlock() |
| 124 | + if t.mu.timer != nil { |
| 125 | + t.mu.timer.Stop() |
| 126 | + // If the timer function is waiting for the mutex, it will notice that timer |
| 127 | + // is nil and exit. |
| 128 | + t.mu.timer = nil |
| 129 | + } |
| 130 | +} |
| 131 | + |
| 132 | +// Start records the start of an operation and returns a handle that should be |
| 133 | +// used with Stop. |
| 134 | +func (t *Tracker) Start() Handle { |
| 135 | + // We record a monotonic start time and capture program counters from the |
| 136 | + // caller’s stack. We generate a handle that includes the shard index in its |
| 137 | + // high byte, making Stop an O(1) operation on the right shard without a |
| 138 | + // lookup. |
| 139 | + var e entry |
| 140 | + e.startTime = crtime.NowMono() |
| 141 | + runtime.Callers(2, e.stack[:]) |
| 142 | + shardIdx := crsync.CPUBiasedInt() % len(t.maps) |
| 143 | + h := Handle(t.handleCounters[shardIdx].Add(1)) |
| 144 | + t.maps[shardIdx].Store(h, e) |
| 145 | + return h |
| 146 | +} |
| 147 | + |
| 148 | +// Stop records the end of an operation. Does nothing if the operation was |
| 149 | +// already stopped. |
| 150 | +func (t *Tracker) Stop(h Handle) { |
| 151 | + // The high byte of h is the shard index; see newTracker. |
| 152 | + t.maps[h>>56].Delete(h) |
| 153 | +} |
| 154 | + |
| 155 | +// Report returns a multi-line, human-readable summary of all entries that were |
| 156 | +// started before the given threshold (i.e., with age > threshold at the call |
| 157 | +// time). The result is suitable for logging or debugging. If no entries exceed |
| 158 | +// the threshold, Report returns "". |
| 159 | +// |
| 160 | +// The output is grouped by Start() stack trace: for each unique stack we show |
| 161 | +// the number of occurrences and the oldest start time among them. Groups are |
| 162 | +// ordered by age (oldest first), and for each group we print the resolved stack |
| 163 | +// frames. |
| 164 | +func (t *Tracker) Report(threshold time.Duration) string { |
| 165 | + type infoForStackTrace struct { |
| 166 | + oldestStartTime crtime.Mono |
| 167 | + occurrences int |
| 168 | + } |
| 169 | + now := crtime.NowMono() |
| 170 | + cutoff := now - crtime.Mono(threshold) |
| 171 | + // We deduplicate stack traces in the report. For each stack, we mention the |
| 172 | + // number of long-running operations and the oldest operation time. |
| 173 | + var m map[stack]infoForStackTrace |
| 174 | + for e := range t.olderThan(cutoff) { |
| 175 | + if m == nil { |
| 176 | + m = make(map[stack]infoForStackTrace) |
| 177 | + } |
| 178 | + info, ok := m[e.stack] |
| 179 | + if ok { |
| 180 | + info.occurrences++ |
| 181 | + info.oldestStartTime = min(info.oldestStartTime, e.startTime) |
| 182 | + } else { |
| 183 | + info.occurrences = 1 |
| 184 | + info.oldestStartTime = e.startTime |
| 185 | + } |
| 186 | + m[e.stack] = info |
| 187 | + } |
| 188 | + if len(m) == 0 { |
| 189 | + return "" |
| 190 | + } |
| 191 | + // Sort by oldest start time. |
| 192 | + stacks := slices.Collect(maps.Keys(m)) |
| 193 | + slices.SortFunc(stacks, func(a, b stack) int { |
| 194 | + return cmp.Compare(m[a].oldestStartTime, m[b].oldestStartTime) |
| 195 | + }) |
| 196 | + var b strings.Builder |
| 197 | + for _, stack := range stacks { |
| 198 | + info := m[stack] |
| 199 | + if info.occurrences == 1 { |
| 200 | + fmt.Fprintf(&b, "started %s ago:\n", now.Sub(info.oldestStartTime)) |
| 201 | + } else { |
| 202 | + fmt.Fprintf(&b, "%d occurrences, oldest started %s ago:\n", info.occurrences, now.Sub(info.oldestStartTime)) |
| 203 | + } |
| 204 | + pcs := stack[:] |
| 205 | + for i := range pcs { |
| 206 | + if pcs[i] == 0 { |
| 207 | + pcs = pcs[:i] |
| 208 | + break |
| 209 | + } |
| 210 | + } |
| 211 | + frames := runtime.CallersFrames(pcs) |
| 212 | + for { |
| 213 | + frame, more := frames.Next() |
| 214 | + fmt.Fprintf(&b, " %s\n %s:%d\n", frame.Function, frame.File, frame.Line) |
| 215 | + if !more { |
| 216 | + break |
| 217 | + } |
| 218 | + } |
| 219 | + b.WriteString("\n") |
| 220 | + } |
| 221 | + return b.String() |
| 222 | +} |
| 223 | + |
| 224 | +func (t *Tracker) olderThan(cutoff crtime.Mono) iter.Seq[entry] { |
| 225 | + return func(yield func(entry) bool) { |
| 226 | + for i := range t.maps { |
| 227 | + for _, e := range t.maps[i].Range { |
| 228 | + if e.startTime < cutoff && !yield(e) { |
| 229 | + return |
| 230 | + } |
| 231 | + } |
| 232 | + } |
| 233 | + } |
| 234 | +} |
| 235 | + |
| 236 | +// We use the high byte of Handle as a shard index. This limits us to 256 shards |
| 237 | +// (which is plenty). |
| 238 | +const maxShards = 256 |
| 239 | +const mapPresize = 16 |
| 240 | + |
| 241 | +// handleCounter is an atomic counter with padding to avoid false sharing. |
| 242 | +type handleCounter struct { |
| 243 | + atomic.Uint64 |
| 244 | + _ [7]uint64 |
| 245 | +} |
| 246 | + |
| 247 | +type entry struct { |
| 248 | + startTime crtime.Mono |
| 249 | + stack stack |
| 250 | +} |
| 251 | + |
| 252 | +// stack contains program counters from Start()'s stack frame. Only the first 7 |
| 253 | +// frames are recorded to keep Start() overhead low. Unused slots are zero. |
| 254 | +// |
| 255 | +// We chose 7 so that entry{} fits in a typical cache line. It should be |
| 256 | +// sufficient to identify the call path in most cases. |
| 257 | +type stack [7]uintptr |
| 258 | + |
| 259 | +func newTracker(numShards int) *Tracker { |
| 260 | + numShards = min(numShards, maxShards) |
| 261 | + |
| 262 | + maps := make([]*xsync.MapOf[Handle, entry], numShards) |
| 263 | + handleCounters := make([]handleCounter, numShards) |
| 264 | + for i := range numShards { |
| 265 | + // All handles have the shard index in the high byte; see Start(). |
| 266 | + handleCounters[i].Store(uint64(i) << 56) |
| 267 | + maps[i] = xsync.NewMapOf[Handle, entry](xsync.WithPresize(mapPresize)) |
| 268 | + } |
| 269 | + return &Tracker{ |
| 270 | + maps: maps, |
| 271 | + handleCounters: handleCounters, |
| 272 | + } |
| 273 | +} |
0 commit comments