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//! The targets this crate records under are `wait`, `work`, `io`, `timer` and
38//! `timer-periodic` -- one per pool object -- plus `heal` for the self-heal
39//! registry, `syscall-enter` and `syscall-leave` for the bracketed Win32 calls
40//! themselves, and `exception` when exception observation is switched on.
41//! Targets are matched by substring, so `timer` selects the periodic timer as
42//! well. Dependent crates add their own; `windows-ioring-sys` records under
43//! `delivery` and, from its own tests, `postmortem`.
44//!
45//! Unset, empty, or matching nothing means no record is kept and the cost is
46//! one relaxed atomic load per call site.
47
48/// One observation. Deliberately `Copy` and free of owned data, so recording
49/// is a push and never an allocation.
50///
51/// Lives outside the feature gate so that [`Buffer`]'s eviction policy is
52/// built and tested in every build, not only in one nobody's `cargo test`
53/// selects. Without the feature the formatting that reads these fields is
54/// compiled out, which is what the `dead_code` allowance is for.
55#[cfg(any(feature = "trace", test))]
56#[cfg_attr(not(feature = "trace"), allow(dead_code))]
57#[derive(Clone, Copy)]
58struct Record {
59 at: std::time::Duration,
60 thread: u32,
61 target: &'static str,
62 event: &'static str,
63 a: u64,
64 b: u64,
65}
66
67/// The bounded record store and, with it, the whole of what happens when a
68/// trace outgrows the room it was given.
69///
70/// Separated from the global it backs so that the policy can be exercised at a
71/// capacity of four rather than of eight thousand. Filling the real buffer in a
72/// test would evict every record every other test had just recorded, which is
73/// the one thing a shared trace cannot tolerate.
74#[cfg(any(feature = "trace", test))]
75struct Buffer {
76 /// The records, as a ring once the buffer is full.
77 ///
78 /// Not in logical order after the first wrap -- read it through
79 /// [`iter`](Self::iter), which is the only thing that knows where the
80 /// oldest one is.
81 records: Vec<Record>,
82 /// Where the oldest record sits, and so where the next one overwrites.
83 ///
84 /// Zero until the buffer first fills, which is why a buffer that never
85 /// overflows needs nothing to know about the ring.
86 head: usize,
87 /// How many records were evicted to make room for later ones.
88 dropped: usize,
89 /// Whether the first eviction has already been reported.
90 announced: bool,
91}
92
93#[cfg(any(feature = "trace", test))]
94impl Buffer {
95 fn with_capacity(capacity: usize) -> Self {
96 Self {
97 records: Vec::with_capacity(capacity),
98 head: 0,
99 dropped: 0,
100 announced: false,
101 }
102 }
103
104 /// Append `record`, evicting the oldest first if the buffer is already at
105 /// `capacity`.
106 ///
107 /// Returns whether this call was the **first** eviction, so a caller can
108 /// report the loss once rather than on every subsequent push. The report
109 /// matters because the alternative is silence: a run that never dumps
110 /// never reads [`dump`]'s dropped-record line, so an overflow that
111 /// truncated the start of a capture would be discovered only by whoever
112 /// later wondered why the trace began in the middle.
113 ///
114 /// A `capacity` of zero stores nothing and counts every record as dropped.
115 /// Degenerate, and defined rather than left to fall out of the arithmetic.
116 ///
117 /// **Eviction overwrites in place; it does not shift.** This used to be
118 /// `Vec::remove(0)`, which moves every remaining record down one. At the
119 /// real capacity that is about 18 MB memmoved per record, under the trace
120 /// mutex, for every record after the buffer fills -- in an instrument whose
121 /// whole purpose is observing behaviour sensitive to timing. A buffer that
122 /// filled mid-capture would start perturbing, and plausibly manufacturing,
123 /// the stall it was being used to study. The buffer is sized not to fill in
124 /// an ordinary capture, which is what kept this invisible.
125 fn push(&mut self, record: Record, capacity: usize) -> bool {
126 if capacity == 0 {
127 self.dropped += 1;
128 let first = !self.announced;
129 self.announced = true;
130 return first;
131 }
132 if self.records.len() < capacity {
133 // Still filling. `with_capacity` reserved the room, so this does
134 // not reallocate and the ring has not started turning yet.
135 self.records.push(record);
136 return false;
137 }
138 // Full: the oldest record is at `head`, and is what this replaces.
139 //
140 // Indexed modulo the vector's own length rather than `capacity`,
141 // because the two can differ -- a buffer that reached a larger capacity
142 // keeps that length if a later push passes a smaller one, exactly as
143 // the remove-and-push it replaces did. Taking the modulus of
144 // `capacity` would index outside the vector.
145 let size = self.records.len();
146 self.records[self.head] = record;
147 self.head = (self.head + 1) % size;
148 self.dropped += 1;
149 let first = !self.announced;
150 self.announced = true;
151 first
152 }
153
154 /// The records in the order they were recorded, oldest first.
155 ///
156 /// The ring's logical order, which is the only order any reader wants: a
157 /// capture that reported its own records out of sequence would be worse
158 /// than one that reported nothing, because nothing about it looks wrong.
159 /// Before the first wrap `head` is zero and this is simply the vector.
160 fn iter(&self) -> impl Iterator<Item = &Record> {
161 let (wrapped, oldest_first) = self.records.split_at(self.head);
162 oldest_first.iter().chain(wrapped.iter())
163 }
164
165 fn clear(&mut self) {
166 self.records.clear();
167 self.head = 0;
168 self.dropped = 0;
169 self.announced = false;
170 }
171}
172
173/// Arm the trace **before `main`**.
174///
175/// `.CRT$XCU` is the C runtime's static-initialiser table; a function pointer
176/// placed in it is called during CRT startup, which for a Rust binary is
177/// before `main` and therefore before the test harness has created a single
178/// thread.
179///
180/// This exists because lazy arming was measured to be too late. The trace was
181/// previously armed on the first traced call, which is already inside the first
182/// test: in the `M26.13` reproducer that landed between 0.15 s and 0.58 s,
183/// while the fault under investigation is established in the first 15.7 ms. An
184/// instrument that arrives after the event cannot observe it.
185///
186/// It does nothing unless the environment asks for it: no
187/// `WINDOWS_THREADPOOL_TRACE`, no arming.
188#[cfg(feature = "trace")]
189#[used]
190#[unsafe(link_section = ".CRT$XCU")]
191static ARM_BEFORE_MAIN: extern "C" fn() = {
192 extern "C" fn arm() {
193 ARMED_BEFORE_MAIN.store(true, std::sync::atomic::Ordering::Relaxed);
194 // `enabled` is the single path that arms the trace, starts its clock
195 // and installs the exception observer. Calling it rather than any of
196 // those directly keeps one order of operations rather than two that
197 // have to be kept in step.
198 let _ = imp::enabled();
199 }
200 arm
201};
202
203/// Whether [`ARM_BEFORE_MAIN`] ran.
204///
205/// Set only from inside the static initialiser and never anywhere else, so it
206/// distinguishes "ran before `main`" from "was arranged and silently dropped".
207/// That is the failure this needs a guard for: a static nothing references is
208/// exactly what a linker is entitled to discard, `#[used]` is what asks it not
209/// to, and the symptom of getting that wrong is not a build error but an
210/// instrument that quietly reverts to installing too late.
211#[cfg(feature = "trace")]
212static ARMED_BEFORE_MAIN: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false);
213
214/// Whether the trace's static initialiser ran before `main`.
215#[cfg(all(test, feature = "trace"))]
216pub(crate) fn armed_before_main() -> bool {
217 ARMED_BEFORE_MAIN.load(std::sync::atomic::Ordering::Relaxed)
218}
219
220/// Run `body` in a child process launched with the trace armed for `filter`.
221///
222/// The filter is fixed by a pre-`main` initialiser, so a test cannot narrow it
223/// for itself: the process has to be *launched* with `WINDOWS_THREADPOOL_TRACE`
224/// already set. A test whose assertions read the trace therefore has three
225/// options, and two of them are traps. Asking `wants(..)` and skipping when it
226/// is unset makes the test inert on every ordinary run and in CI -- which is
227/// what `tests/obligation_report.rs`, the pool-object lifecycle test, and both
228/// of `io::tests`' trace blocks each did, independently. Running in a shared
229/// armed process is no better: `dump` returns one process-wide buffer and
230/// `counted` only asks for a non-zero count, so a sibling test can supply the
231/// records and the assertion passes without exercising anything.
232///
233/// This is the third option, and it is one site rather than a protocol each
234/// caller re-implements -- the first two copies disagreed about how to tell a
235/// child that ran from a child that matched nothing.
236///
237/// `name` is the libtest path of the calling test, used both to select the
238/// single test the child runs and to mark which body the child should execute.
239/// The child exits with a code that means "the body reached its end", so a
240/// `--exact` that matched nothing -- a rename -- fails loudly instead of
241/// exiting 0 and reading as a pass.
242#[cfg(all(test, feature = "trace"))]
243pub(crate) fn in_a_trace_armed_child(name: &str, filter: &str, body: impl FnOnce()) {
244 /// Names the body the child should run; absent in the parent.
245 const CHILD_VAR: &str = "WTPS_TRACE_ARMED_CHILD";
246 /// The child's exit code once the body has run to the end.
247 const BODY_RAN: i32 = 7;
248
249 if std::env::var(CHILD_VAR).as_deref() == Ok(name) {
250 body();
251 std::process::exit(BODY_RAN);
252 }
253
254 let exe = std::env::current_exe().expect("locate the test binary");
255 let status = std::process::Command::new(exe)
256 .env(CHILD_VAR, name)
257 .env("WINDOWS_THREADPOOL_TRACE", filter)
258 // One test, one thread: the child's trace buffer must carry this
259 // body's records and nothing else, or the assertions can be satisfied
260 // by a sibling.
261 .args(["--exact", name, "--test-threads", "1"])
262 .status()
263 .expect("run the trace-armed child");
264 assert_eq!(
265 status.code(),
266 Some(BODY_RAN),
267 "the trace-armed child did not reach the end of `{name}` (exit {:?}). Exit 0 means \
268 `--exact {name}` matched nothing -- the test was renamed and the string passed here \
269 was not -- and any other code means the body's own assertions failed; its output is \
270 above",
271 status.code()
272 );
273}
274
275#[cfg(feature = "trace")]
276mod imp {
277 use std::sync::Mutex;
278 use std::sync::atomic::{AtomicU8, Ordering};
279 use std::time::Instant;
280
281 use super::{Buffer, Record};
282
283 /// How many records are retained. Fixed and pre-allocated: growing a
284 /// buffer mid-trace would allocate on the path being measured, which is
285 /// the one thing this module exists to avoid. Nothing is allocated until
286 /// something is actually recorded, so a build carrying the feature with
287 /// the environment unset pays nothing for this.
288 ///
289 /// Oldest records are dropped first. The failures this was built for show
290 /// up in the first moments of a run, so keeping the most recent entries is
291 /// the wrong bias -- but keeping a bounded window is what stops a long run
292 /// consuming the machine, and an overflow now reports itself twice over:
293 /// once to stderr as it happens, and again at the head of every dump.
294 ///
295 /// **Set from measurement, and re-measured when the trace grows.** The
296 /// buffer is per-process and each test binary is its own process, so the
297 /// population that can fill it is one binary's own run. Two measurements,
298 /// both under `WINDOWS_THREADPOOL_TRACE` set to everything:
299 ///
300 /// | | records |
301 /// |---|---|
302 /// | `windows-ioring-sys`' `event_delivery`, the only binary that captures | 89 |
303 /// | this crate's own lib tests, 2026-09-26 | 14061 |
304 /// | this crate's own lib tests, after the call-boundary and exception targets | 47997 |
305 ///
306 /// The third figure is why this is not 65536 any more: adding
307 /// `syscall-enter`/`syscall-leave` and `exception` tripled the volume and
308 /// left only a third of a buffer spare. The figures, and what the smallest
309 /// value cost, are in [the archive entry for
310 /// M26.13.2](../../windows-ioring-sys/COMPLETED-CHECKLIST.md#m26132).
311 const CAPACITY: usize = 262_144;
312
313 static ARMED: AtomicU8 = AtomicU8::new(ARMED_UNKNOWN);
314 const ARMED_UNKNOWN: u8 = 0;
315 const ARMED_OFF: u8 = 1;
316 const ARMED_ON: u8 = 2;
317
318 static STATE: std::sync::OnceLock<Mutex<Buffer>> = std::sync::OnceLock::new();
319 static STARTED: std::sync::OnceLock<Instant> = std::sync::OnceLock::new();
320 static FILTERS: std::sync::OnceLock<Vec<String>> = std::sync::OnceLock::new();
321
322 fn state() -> &'static Mutex<Buffer> {
323 STATE.get_or_init(|| Mutex::new(Buffer::with_capacity(CAPACITY)))
324 }
325
326 fn started() -> Instant {
327 *STARTED.get_or_init(Instant::now)
328 }
329
330 fn filters() -> &'static Vec<String> {
331 FILTERS.get_or_init(|| {
332 std::env::var("WINDOWS_THREADPOOL_TRACE")
333 .unwrap_or_default()
334 .split(',')
335 .map(|piece| piece.trim().to_owned())
336 .filter(|piece| !piece.is_empty())
337 .collect()
338 })
339 }
340
341 /// Whether anything is being traced at all.
342 ///
343 /// Cached in a relaxed atomic after the first call, so the steady-state
344 /// cost at a disabled call site is one load and a branch. The environment
345 /// is read once: re-reading it per call would put a lock and a lookup on
346 /// the measured path.
347 #[inline(always)]
348 pub fn enabled() -> bool {
349 match ARMED.load(Ordering::Relaxed) {
350 ARMED_ON => true,
351 ARMED_OFF => false,
352 _ => {
353 let on = !filters().is_empty();
354 ARMED.store(if on { ARMED_ON } else { ARMED_OFF }, Ordering::Relaxed);
355 if on {
356 observe_exceptions();
357 }
358 on
359 }
360 }
361 }
362
363 /// Whether this specific target is being traced.
364 #[inline(always)]
365 pub fn wants(target: &str) -> bool {
366 enabled()
367 && filters()
368 .iter()
369 .any(|filter| filter == "*" || target.contains(filter.as_str()))
370 }
371
372 /// Record one observation. Cheap by construction: a clock read, a thread
373 /// id, and a push under a lock that is never held across anything slow.
374 #[inline]
375 pub fn record(target: &'static str, event: &'static str, a: u64, b: u64) {
376 if !wants(target) {
377 return;
378 }
379 let at = started().elapsed();
380 // SAFETY: no preconditions; returns the calling thread's id.
381 let thread = unsafe { windows_sys::Win32::System::Threading::GetCurrentThreadId() };
382 let first_eviction = {
383 let Ok(mut state) = state().lock() else {
384 return;
385 };
386 state.push(
387 Record {
388 at,
389 thread,
390 target,
391 event,
392 a,
393 b,
394 },
395 CAPACITY,
396 )
397 };
398 // Outside the lock, and only ever once: a capture that has begun
399 // discarding its start is a different artifact from one that has not,
400 // and a run that never dumps would otherwise never be told. This is
401 // the one place the module formats on the traced path, and it is
402 // reached only after `CAPACITY` records have already been taken.
403 if first_eviction {
404 eprintln!(
405 "windows-threadpool-sys trace: the {CAPACITY}-record buffer is full and is now \
406 evicting the oldest records, so this capture no longer reaches back to the \
407 start of the run. Narrow WINDOWS_THREADPOOL_TRACE, or raise CAPACITY."
408 );
409 }
410 }
411
412 /// Every record so far, oldest first, formatted for reading.
413 pub fn dump() -> String {
414 let Ok(state) = state().lock() else {
415 return "<trace lock poisoned>".to_owned();
416 };
417 let mut out = String::with_capacity(state.records.len() * 64);
418 if state.dropped > 0 {
419 out.push_str(&format!(
420 " ... {} earlier record(s) dropped; raise CAPACITY to keep them\n",
421 state.dropped
422 ));
423 }
424 for record in state.iter() {
425 out.push_str(&format!(
426 " {:>12.6}s t{:<6} {:<22} {:<36} {:>6} {:>6}\n",
427 record.at.as_secs_f64(),
428 record.thread,
429 record.target,
430 record.event,
431 record.a,
432 record.b
433 ));
434 }
435 out
436 }
437
438 /// Discard everything recorded so far.
439 pub fn clear() {
440 if let Ok(mut state) = state().lock() {
441 state.clear();
442 }
443 }
444
445 /// The target every exception observation is recorded under.
446 const EXCEPTION_TARGET: &str = "exception";
447
448 /// Tell the OS this handler did not handle the exception, so the search
449 /// continues exactly as it would have without us. Named rather than
450 /// written as a bare literal: this value is the whole of the promise that
451 /// installing the observer changes no behaviour.
452 const EXCEPTION_CONTINUE_SEARCH: i32 = 0;
453
454 /// Ask to be called *before* any previously installed handler, which is
455 /// what makes the timestamp the moment of the raise rather than the moment
456 /// some other handler declined it.
457 const CALL_FIRST: u32 = 1;
458
459 /// Record one observation from a context that must neither block nor
460 /// initialise anything.
461 ///
462 /// A vectored exception handler runs on whatever thread raised, at
463 /// whatever point it raised -- including, in principle, a thread that is
464 /// inside [`record`] holding the buffer lock. So this takes none of the
465 /// paths that could deadlock or allocate:
466 ///
467 /// - every `OnceLock` is read with `get`, never `get_or_init`, so a first
468 /// exception arriving before the trace has initialised is dropped rather
469 /// than initialising the trace from inside an exception handler;
470 /// - the buffer lock is taken with `try_lock`, so an exception raised by a
471 /// thread already holding it drops the record instead of deadlocking;
472 /// - the eviction announcement is deliberately ignored, because writing to
473 /// stderr from an exception handler is not something this facility
474 /// should do uninvited.
475 ///
476 /// The cost of all three is the same: a lost record, which is the right
477 /// trade for an observer whose entire purpose is to change nothing.
478 fn record_without_blocking(event: &'static str, a: u64, b: u64) {
479 if ARMED.load(Ordering::Relaxed) != ARMED_ON {
480 return;
481 }
482 let Some(filters) = FILTERS.get() else {
483 return;
484 };
485 if !filters
486 .iter()
487 .any(|filter| filter == "*" || EXCEPTION_TARGET.contains(filter.as_str()))
488 {
489 return;
490 }
491 let (Some(started), Some(state)) = (STARTED.get(), STATE.get()) else {
492 return;
493 };
494 let at = started.elapsed();
495 // SAFETY: no preconditions; returns the calling thread's id.
496 let thread = unsafe { windows_sys::Win32::System::Threading::GetCurrentThreadId() };
497 let Ok(mut state) = state.try_lock() else {
498 return;
499 };
500 let _ = state.push(
501 Record {
502 at,
503 thread,
504 target: EXCEPTION_TARGET,
505 event,
506 a,
507 b,
508 },
509 CAPACITY,
510 );
511 }
512
513 /// Note that an exception was raised, and decline to handle it.
514 ///
515 /// SAFETY: this is the `PVECTORED_EXCEPTION_HANDLER` ABI. `info` is
516 /// supplied by the OS and is valid for the duration of the call.
517 unsafe extern "system" fn exception_observer(
518 info: *mut windows_sys::Win32::System::Diagnostics::Debug::EXCEPTION_POINTERS,
519 ) -> i32 {
520 if !info.is_null() {
521 // SAFETY: non-null and OS-supplied for this call.
522 let record = unsafe { (*info).ExceptionRecord };
523 if !record.is_null() {
524 // SAFETY: as above; the record outlives this call.
525 let (code, address) =
526 unsafe { ((*record).ExceptionCode, (*record).ExceptionAddress) };
527 record_without_blocking("raised", code as u32 as u64, address as u64);
528 }
529 }
530 EXCEPTION_CONTINUE_SEARCH
531 }
532
533 /// Start noting every exception raised in this process, once.
534 ///
535 /// Installed when the trace turns on rather than on demand, so that no
536 /// caller has to remember: the window an investigation cares about has
537 /// usually opened before anyone would think to ask for this.
538 ///
539 /// **It observes and does nothing else.** The handler returns
540 /// `EXCEPTION_CONTINUE_SEARCH`, so every exception is dispatched exactly
541 /// as it would have been -- including first-chance exceptions a later
542 /// handler goes on to swallow, which is precisely the population a normal
543 /// debugger view hides and an investigation may want.
544 pub fn observe_exceptions() {
545 use std::sync::atomic::AtomicBool;
546 static INSTALLED: AtomicBool = AtomicBool::new(false);
547 if INSTALLED.swap(true, Ordering::SeqCst) {
548 return;
549 }
550 // Force the clock and the buffer into existence *here*, in an ordinary
551 // context, because the handler deliberately refuses to initialise
552 // either. Without this an exception raised before the first ordinary
553 // record would be dropped -- which is the window an investigation is
554 // most likely to care about, since it is the one before anything has
555 // happened yet.
556 let _ = started();
557 let _ = state();
558 // SAFETY: the handler matches the documented ABI, has static lifetime,
559 // and is never removed.
560 unsafe {
561 windows_sys::Win32::System::Diagnostics::Debug::AddVectoredExceptionHandler(
562 CALL_FIRST,
563 Some(exception_observer),
564 )
565 };
566 }
567}
568
569#[cfg(not(feature = "trace"))]
570mod imp {
571 /// Always false in this build: the feature is off.
572 #[inline(always)]
573 pub fn enabled() -> bool {
574 false
575 }
576 /// Always false in this build: the feature is off.
577 #[inline(always)]
578 pub fn wants(_target: &str) -> bool {
579 false
580 }
581 /// Does nothing in this build, and is expected to compile away entirely.
582 #[inline(always)]
583 pub fn record(_target: &'static str, _event: &'static str, _a: u64, _b: u64) {}
584 /// Reports that the build carries no trace, which is a different finding
585 /// from a build that traced and saw nothing.
586 pub fn dump() -> String {
587 "<built without the `trace` feature>".to_owned()
588 }
589 /// Does nothing in this build.
590 pub fn clear() {}
591 /// Does nothing in this build: there is no trace to attribute exceptions
592 /// to, so no handler is installed.
593 pub fn observe_exceptions() {}
594}
595
596pub use imp::{clear, dump, enabled, observe_exceptions, record, wants};
597
598/// How many records so far carry this target and this event.
599///
600/// Reads [`dump`] rather than the buffer behind it, so it sees exactly what a
601/// reader of a capture sees: a call site that records under a target other
602/// than the one it means to would be invisible to a check that went behind the
603/// formatting, and is the kind of mistake this is used to catch.
604// Carries the feature condition of its callers: every one of them is a
605// trace-gated test, so without race this is dead code in a build CI
606// compiles with `-D warnings`.
607#[cfg(all(test, feature = "trace"))]
608pub(crate) fn counted(target: &str, event: &str) -> usize {
609 dump()
610 .lines()
611 .filter(|line| {
612 let mut fields = line.split_whitespace();
613 // Elapsed time, then thread id, then the two labels.
614 fields.next();
615 fields.next();
616 fields.next() == Some(target) && fields.next() == Some(event)
617 })
618 .count()
619}
620
621/// Record one observation, evaluating its arguments only when the target is
622/// being traced.
623///
624/// Prefer this to calling [`record`] directly: the macro keeps argument
625/// evaluation behind the filter check, so a call site can compute a value that
626/// would itself be too expensive for the measured path.
627#[macro_export]
628macro_rules! trace_record {
629 ($target:expr, $event:expr) => {
630 $crate::trace::record($target, $event, 0, 0)
631 };
632 ($target:expr, $event:expr, $a:expr) => {
633 if $crate::trace::wants($target) {
634 $crate::trace::record($target, $event, $a as u64, 0);
635 }
636 };
637 ($target:expr, $event:expr, $a:expr, $b:expr) => {
638 if $crate::trace::wants($target) {
639 $crate::trace::record($target, $event, $a as u64, $b as u64);
640 }
641 };
642}
643
644/// Bracket a Win32 call that blocks, or that takes a lock inside the pool.
645///
646/// Records the call's name under `syscall-enter` before it and `syscall-leave`
647/// after, so a call that blocked shows up as an *interval* rather than as a
648/// record with a later timestamp than you expected. The difference matters:
649/// a single record stamped after the call returns cannot distinguish "this was
650/// issued late" from "this took four seconds to return".
651///
652/// Every thread-pool API touches the pool's own synchronisation, and several
653/// block outright -- the `WaitForThreadpool*Callbacks` family,
654/// `CloseThreadpoolCleanupGroupMembers`, `CloseThreadpool`, and
655/// `SetThreadpoolThreadMinimum`, which creates threads. Which of the rest can
656/// contend is not documented, so they are bracketed too rather than assumed
657/// cheap: the whole point is to catch synchronisation nobody expected.
658///
659/// **It is its own target**, so it can be switched on without it. A capture
660/// narrowed to `wait,delivery` is unchanged by this existing; one narrowed to
661/// `syscall` sees only the call boundaries. Argument expressions are evaluated
662/// only when the target is being traced, and the whole thing compiles to the
663/// call alone without the `trace` feature.
664///
665/// ```ignore
666/// crate::trace_call!("SetThreadpoolWait", wait, handle as usize, {
667/// // SAFETY: ...
668/// unsafe { SetThreadpoolWait(wait, handle, ptr::null()) }
669/// })
670/// ```
671#[macro_export]
672macro_rules! trace_call {
673 ($name:literal, $a:expr, $b:expr, $call:block) => {{
674 $crate::trace_record!("syscall-enter", $name, $a, $b);
675 let result = $call;
676 $crate::trace_record!("syscall-leave", $name, $a, $b);
677 result
678 }};
679}
680
681#[cfg(test)]
682mod tests;