windows_threadpool_sys/trace.rs
1// Copyright (c) Mike Grier
2//! A trace that is cheap enough to use on a timing-sensitive defect.
3//!
4//! # Why this is not `eprintln!`
5//!
6//! It exists for one class of problem: a fault that only appears under
7//! concurrency, where the obvious instrument destroys the thing it is
8//! measuring. Formatting and writing a line takes microseconds and a lock on
9//! stderr; the window being investigated may be shorter than that, so an
10//! `eprintln!` in the wrong place does not observe a race, it prevents one.
11//!
12//! Three properties follow, and each is a deliberate cost:
13//!
14//! 1. **It compiles to nothing unless the `trace` feature is on.** Every entry
15//! point below is `#[inline(always)]` and has an empty body without the
16//! feature, so a published build carries no branch, no atomic, and no
17//! storage. This is what makes it safe to leave the call sites in place.
18//! 2. **Recording does not format and does not allocate.** An entry is a
19//! timestamp, a thread id, two `&'static str` labels and two `u64` slots.
20//! Text is produced only when a dump is asked for, which happens after the
21//! interesting moment has passed.
22//! 3. **It is off at runtime even when compiled in**, and when on it is
23//! *narrowed* rather than global -- see [`crate::trace::enabled`]. A trace that records
24//! everything is a trace that changes the schedule of everything.
25//!
26//! # Narrowing to one scenario
27//!
28//! Set `WINDOWS_THREADPOOL_TRACE` to a comma-separated list of target
29//! substrings. Only records whose target contains one of them are kept:
30//!
31//! ```text
32//! $env:WINDOWS_THREADPOOL_TRACE = 'wait' # just the wait object
33//! $env:WINDOWS_THREADPOOL_TRACE = 'wait,delivery' # two subsystems
34//! $env:WINDOWS_THREADPOOL_TRACE = '*' # everything
35//! ```
36//!
37//! Unset, empty, or matching nothing means no record is kept and the cost is
38//! one relaxed atomic load per call site.
39
40#[cfg(feature = "trace")]
41mod imp {
42 use std::sync::Mutex;
43 use std::sync::atomic::{AtomicU8, Ordering};
44 use std::time::Instant;
45
46 /// How many records are retained. Fixed and pre-allocated: growing a
47 /// buffer mid-trace would allocate on the path being measured, which is
48 /// the one thing this module exists to avoid.
49 ///
50 /// Oldest records are dropped first. The failures this was built for show
51 /// up in the first moments of a run, so keeping the most recent entries is
52 /// the wrong bias -- but keeping a bounded window is what stops a long run
53 /// consuming the machine, and a dump reports how many were lost.
54 const CAPACITY: usize = 8192;
55
56 /// One observation. Deliberately `Copy` and free of owned data, so
57 /// recording is a push and never an allocation.
58 #[derive(Clone, Copy)]
59 pub struct Record {
60 pub at: std::time::Duration,
61 pub thread: u32,
62 pub target: &'static str,
63 pub event: &'static str,
64 pub a: u64,
65 pub b: u64,
66 }
67
68 struct State {
69 records: Vec<Record>,
70 dropped: usize,
71 }
72
73 static ARMED: AtomicU8 = AtomicU8::new(ARMED_UNKNOWN);
74 const ARMED_UNKNOWN: u8 = 0;
75 const ARMED_OFF: u8 = 1;
76 const ARMED_ON: u8 = 2;
77
78 fn state() -> &'static Mutex<State> {
79 static STATE: std::sync::OnceLock<Mutex<State>> = std::sync::OnceLock::new();
80 STATE.get_or_init(|| {
81 Mutex::new(State {
82 records: Vec::with_capacity(CAPACITY),
83 dropped: 0,
84 })
85 })
86 }
87
88 fn started() -> Instant {
89 static STARTED: std::sync::OnceLock<Instant> = std::sync::OnceLock::new();
90 *STARTED.get_or_init(Instant::now)
91 }
92
93 fn filters() -> &'static Vec<String> {
94 static FILTERS: std::sync::OnceLock<Vec<String>> = std::sync::OnceLock::new();
95 FILTERS.get_or_init(|| {
96 std::env::var("WINDOWS_THREADPOOL_TRACE")
97 .unwrap_or_default()
98 .split(',')
99 .map(|piece| piece.trim().to_owned())
100 .filter(|piece| !piece.is_empty())
101 .collect()
102 })
103 }
104
105 /// Whether anything is being traced at all.
106 ///
107 /// Cached in a relaxed atomic after the first call, so the steady-state
108 /// cost at a disabled call site is one load and a branch. The environment
109 /// is read once: re-reading it per call would put a lock and a lookup on
110 /// the measured path.
111 #[inline(always)]
112 pub fn enabled() -> bool {
113 match ARMED.load(Ordering::Relaxed) {
114 ARMED_ON => true,
115 ARMED_OFF => false,
116 _ => {
117 let on = !filters().is_empty();
118 ARMED.store(if on { ARMED_ON } else { ARMED_OFF }, Ordering::Relaxed);
119 on
120 }
121 }
122 }
123
124 /// Whether this specific target is being traced.
125 #[inline(always)]
126 pub fn wants(target: &str) -> bool {
127 enabled()
128 && filters()
129 .iter()
130 .any(|filter| filter == "*" || target.contains(filter.as_str()))
131 }
132
133 /// Record one observation. Cheap by construction: a clock read, a thread
134 /// id, and a push under a lock that is never held across anything slow.
135 #[inline]
136 pub fn record(target: &'static str, event: &'static str, a: u64, b: u64) {
137 if !wants(target) {
138 return;
139 }
140 let at = started().elapsed();
141 // SAFETY: no preconditions; returns the calling thread's id.
142 let thread = unsafe { windows_sys::Win32::System::Threading::GetCurrentThreadId() };
143 let Ok(mut state) = state().lock() else {
144 return;
145 };
146 if state.records.len() == CAPACITY {
147 state.records.remove(0);
148 state.dropped += 1;
149 }
150 state.records.push(Record {
151 at,
152 thread,
153 target,
154 event,
155 a,
156 b,
157 });
158 }
159
160 /// Every record so far, oldest first, formatted for reading.
161 pub fn dump() -> String {
162 let Ok(state) = state().lock() else {
163 return "<trace lock poisoned>".to_owned();
164 };
165 let mut out = String::with_capacity(state.records.len() * 64);
166 if state.dropped > 0 {
167 out.push_str(&format!(
168 " ... {} earlier record(s) dropped; raise CAPACITY to keep them\n",
169 state.dropped
170 ));
171 }
172 for record in &state.records {
173 out.push_str(&format!(
174 " {:>12.6}s t{:<6} {:<22} {:<28} {:>6} {:>6}\n",
175 record.at.as_secs_f64(),
176 record.thread,
177 record.target,
178 record.event,
179 record.a,
180 record.b
181 ));
182 }
183 out
184 }
185
186 /// Discard everything recorded so far.
187 pub fn clear() {
188 if let Ok(mut state) = state().lock() {
189 state.records.clear();
190 state.dropped = 0;
191 }
192 }
193}
194
195#[cfg(not(feature = "trace"))]
196mod imp {
197 /// Always false in this build: the feature is off.
198 #[inline(always)]
199 pub fn enabled() -> bool {
200 false
201 }
202 /// Always false in this build: the feature is off.
203 #[inline(always)]
204 pub fn wants(_target: &str) -> bool {
205 false
206 }
207 /// Does nothing in this build, and is expected to compile away entirely.
208 #[inline(always)]
209 pub fn record(_target: &'static str, _event: &'static str, _a: u64, _b: u64) {}
210 /// Reports that the build carries no trace, which is a different finding
211 /// from a build that traced and saw nothing.
212 pub fn dump() -> String {
213 "<built without the `trace` feature>".to_owned()
214 }
215 /// Does nothing in this build.
216 pub fn clear() {}
217}
218
219pub use imp::{clear, dump, enabled, record, wants};
220
221/// Record one observation, evaluating its arguments only when the target is
222/// being traced.
223///
224/// Prefer this to calling [`record`] directly: the macro keeps argument
225/// evaluation behind the filter check, so a call site can compute a value that
226/// would itself be too expensive for the measured path.
227#[macro_export]
228macro_rules! trace_record {
229 ($target:expr, $event:expr) => {
230 $crate::trace::record($target, $event, 0, 0)
231 };
232 ($target:expr, $event:expr, $a:expr) => {
233 if $crate::trace::wants($target) {
234 $crate::trace::record($target, $event, $a as u64, 0);
235 }
236 };
237 ($target:expr, $event:expr, $a:expr, $b:expr) => {
238 if $crate::trace::wants($target) {
239 $crate::trace::record($target, $event, $a as u64, $b as u64);
240 }
241 };
242}
243
244#[cfg(test)]
245mod tests;