1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
//! Per-builtin wall-time attribution.
//!
//! The categorical [`crate::profile`] rollup answers "LLM vs tools vs steps",
//! which is the right question for an agent run and the wrong one for a script
//! that is simply slow: every builtin a pipeline calls — a project scan, a
//! subprocess, a file read — lands in `vm/residual` alongside the script's own
//! bytecode. A run that spends ten seconds inside one builtin reports
//! `vm/residual 100.0%`, which names nothing.
//!
//! Builtins are called far too often to afford a [`crate::tracing::Span`] each
//! (a string name, a metadata map, a vector push). This records two integers per
//! builtin NAME instead — call count and total nanoseconds — behind an atomic
//! that is only set when the operator asked for a profile. When it is off, the
//! cost is one relaxed atomic load per builtin call.
//!
//! Two limits, stated so the table is not read for more than it says:
//!
//! Time is INCLUSIVE. A builtin that calls back into the VM (and so into other
//! builtins) counts its callees' time as well as its own. That is the honest
//! reading for the question this answers — "what is this run waiting on" — but
//! it means the column does not sum to wall time, and the renderer says so.
//!
//! Each timed call carries its own measurement cost (a clock read and a lock),
//! charged to the builtin being measured. That is noise against a builtin that
//! takes ten seconds and a meaningful fraction of one that takes a microsecond,
//! so this finds expensive builtins — it is not a microbenchmark of cheap ones.
//! Rank the table; do not read a cheap builtin's per-call average as its true
//! cost.
use std::collections::HashMap;
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::Mutex;
use std::time::Duration;
use serde::{Deserialize, Serialize};
/// Whether to record. Read once per builtin call, so it stays an atomic rather
/// than a lock.
static ENABLED: AtomicBool = AtomicBool::new(false);
static TOTALS: Mutex<Option<HashMap<String, BuiltinTotal>>> = Mutex::new(None);
#[derive(Debug, Clone, Copy, Default)]
struct BuiltinTotal {
calls: u64,
nanos: u128,
}
/// One builtin's aggregated cost across a run.
#[derive(Debug, Clone, Serialize, Deserialize, Default, PartialEq)]
pub struct BuiltinBucket {
pub name: String,
pub total_ms: u64,
pub calls: u64,
/// Mean call cost. The interesting split is one slow call versus a million
/// fast ones, and a total alone cannot tell them apart.
pub avg_ms: f64,
}
/// Start recording, discarding anything from a previous run.
pub fn enable() {
*TOTALS.lock().unwrap_or_else(|e| e.into_inner()) = Some(HashMap::new());
ENABLED.store(true, Ordering::Relaxed);
}
pub fn is_enabled() -> bool {
ENABLED.load(Ordering::Relaxed)
}
/// Record one completed builtin call.
///
/// Allocates only the first time a given builtin is seen. `entry()` would take
/// an owned key and so allocate on every call — and the cost of measuring a
/// builtin is charged to that builtin, so a per-call allocation shows up as the
/// hot spot instead of finding it. `len` called 200k times reported a second of
/// wall time that was almost entirely this function.
pub fn record(name: &str, elapsed: Duration) {
if !is_enabled() {
return;
}
let mut guard = TOTALS.lock().unwrap_or_else(|e| e.into_inner());
let Some(totals) = guard.as_mut() else {
return;
};
let nanos = elapsed.as_nanos();
if let Some(entry) = totals.get_mut(name) {
entry.calls += 1;
entry.nanos += nanos;
return;
}
totals.insert(name.to_string(), BuiltinTotal { calls: 1, nanos });
}
/// Times one builtin call and records it on drop.
///
/// Scope-guard shaped, like [`crate::vm::ScopeSpan`], so a dispatch path adopts
/// it with a binding rather than a matched pair of calls it could return early
/// between. A builtin that throws still reports the time it burned first.
///
/// Borrows the name rather than owning it: a dispatch path always has the name
/// alive across the call it is timing, and copying it per call would charge the
/// copy to the builtin being measured.
pub struct BuiltinTimer<'a> {
name: &'a str,
start: std::time::Instant,
}
impl<'a> BuiltinTimer<'a> {
/// `None` when profiling is off, which costs one relaxed atomic load and
/// keeps `Instant::now` off the hot path of every `to_string` call.
pub fn start(name: &'a str) -> Option<Self> {
if !is_enabled() {
return None;
}
Some(Self {
name,
start: std::time::Instant::now(),
})
}
}
impl Drop for BuiltinTimer<'_> {
fn drop(&mut self) {
record(self.name, self.start.elapsed());
}
}
/// The recorded buckets, most expensive first. Empty when profiling was off.
pub fn snapshot() -> Vec<BuiltinBucket> {
let guard = TOTALS.lock().unwrap_or_else(|e| e.into_inner());
let Some(totals) = guard.as_ref() else {
return Vec::new();
};
let mut buckets: Vec<BuiltinBucket> = totals
.iter()
.map(|(name, total)| {
let total_ms = (total.nanos / 1_000_000) as u64;
BuiltinBucket {
name: name.clone(),
total_ms,
calls: total.calls,
avg_ms: if total.calls == 0 {
0.0
} else {
(total.nanos as f64 / total.calls as f64) / 1_000_000.0
},
}
})
.collect();
// Ties broken by name so the rendered table is stable across runs.
buckets.sort_by(|a, b| {
b.total_ms
.cmp(&a.total_ms)
.then_with(|| a.name.cmp(&b.name))
});
buckets
}
/// Stop recording and drop the totals.
pub fn reset() {
ENABLED.store(false, Ordering::Relaxed);
*TOTALS.lock().unwrap_or_else(|e| e.into_inner()) = None;
}
/// The one lock serializing tests that touch the process-global recorder.
///
/// Lives outside `mod tests` because the lifecycle regression for this module
/// belongs with `reset_thread_local_state` — the single owner of process-global
/// resets — not here, and both sides must hold the SAME lock or they race each
/// other's `enable`/`reset` under cargo's test threads.
#[cfg(test)]
pub(crate) fn test_lock() -> &'static Mutex<()> {
static TEST_LOCK: Mutex<()> = Mutex::new(());
&TEST_LOCK
}
#[cfg(test)]
mod tests {
use super::*;
/// The global recorder is process-wide, so these run under one lock rather
/// than racing each other through `enable`/`reset`.
use super::test_lock as TEST_LOCK;
#[test]
fn records_nothing_until_enabled() {
let _guard = TEST_LOCK().lock().unwrap_or_else(|e| e.into_inner());
reset();
record("project_fingerprint", Duration::from_millis(10));
assert!(
snapshot().is_empty(),
"a run without --profile must not pay for bookkeeping it never reads"
);
}
#[test]
fn aggregates_calls_by_name_and_ranks_by_total() {
let _guard = TEST_LOCK().lock().unwrap_or_else(|e| e.into_inner());
enable();
record("to_string", Duration::from_millis(1));
record("to_string", Duration::from_millis(3));
record("project_fingerprint", Duration::from_millis(120));
let buckets = snapshot();
reset();
assert_eq!(buckets.len(), 2);
// One slow call outranks several fast ones: the ranking is by cost, not
// by how busy a builtin looks.
assert_eq!(buckets[0].name, "project_fingerprint");
assert_eq!(buckets[0].total_ms, 120);
assert_eq!(buckets[0].calls, 1);
assert_eq!(buckets[1].name, "to_string");
assert_eq!(buckets[1].total_ms, 4);
assert_eq!(buckets[1].calls, 2);
assert!((buckets[1].avg_ms - 2.0).abs() < 0.001);
}
#[test]
fn enable_discards_a_previous_run() {
let _guard = TEST_LOCK().lock().unwrap_or_else(|e| e.into_inner());
enable();
record("run_shell", Duration::from_millis(5));
enable();
let buckets = snapshot();
reset();
assert!(
buckets.is_empty(),
"a fresh run must not inherit stale totals"
);
}
}