vortex_array/test_harness/trace/
mod.rs

1// SPDX-License-Identifier: Apache-2.0
2// SPDX-FileCopyrightText: Copyright the Vortex contributors
3
4//! Snapshot-friendly tracing harness for the optimizer and executor.
5//!
6//! # What this records
7//!
8//! [`trace_op`] runs a closure with a thread-local recorder installed. While the recorder is
9//! active, calls to the `trace_op!` macro inside the optimizer and executor push
10//! structured events into the recorder. The recorder produces a [`TraceDisplay`] that renders
11//! as a deterministic, hierarchical text trace suitable for `insta` snapshot assertions.
12//!
13//! Events cover:
14//!
15//! - **Optimization**: optimize/recursive-optimize entry, fixpoint loop iterations, applied
16//!   reduce rules, applied parent-reduce rules.
17//! - **Execution**: `execute_until` iterations, single-step entries, parent kernel attempts and
18//!   matches, slot transitions, builder start/append/finish, and the eventual canonical output.
19//!
20//! Despite the name `trace_op`, the harness is *not* a generic logging facility: it is closely
21//! coupled to the optimizer/executor state machines so that the resulting trace is stable enough
22//! to commit as a snapshot.
23//!
24//! # When to use it
25//!
26//! Use [`trace_op`] to write a regression test that asserts on the sequence of optimizer
27//! rewrites or executor steps an array goes through. Typical scenarios:
28//!
29//! - A reduce rule should fire exactly once on a specific input shape.
30//! - A parent kernel should be tried in a specific order and the first match should win.
31//! - The executor should walk into a slot, finish it, and pop back to the parent without
32//!   building a canonical intermediate.
33//! - A chunked array should drive the builder path rather than the stack path.
34//!
35//! Two resolutions are available:
36//!
37//! - [`TraceResolution::ExecutedOnly`] (default) — only events that actually fired (rule
38//!   rewrites that matched, kernels that succeeded, execution steps that ran). Optimizer
39//!   passes that produced no change are elided.
40//! - [`TraceResolution::Attempts`] — also records declined rule attempts, kernels that did
41//!   not match, and per-loop bookkeeping. Use this when ordering or fall-through matters.
42//!
43//! # Cost and scope
44//!
45//! - Capture is thread-local. Worker threads spawned inside `f` do not inherit the recorder.
46//! - Nested captures return an error so that unrelated traces never merge.
47//! - In release builds and CodSpeed benchmark builds, every `trace_op!` invocation is compiled
48//!   away by the macro's `cfg` gating; this module is then unused. See
49//!   `trace_op!` for the gating rules.
50//!
51//! # Example
52//!
53//! ```ignore
54//! use vortex_array::test_harness::trace::trace_op;
55//!
56//! let traced = trace_op(|| filter_array.optimize())?;
57//! assert!(traced.output.is::<Primitive>());
58//! insta::assert_snapshot!(traced.trace.to_string(), @r"
59//! optimize root=vortex.filter(i32, len=4) session=false
60//!   reduce TrivialFilterRule: vortex.filter(i32, len=4) -> vortex.primitive(i32, len=4)
61//!   done output=vortex.primitive(i32, len=4)
62//! ");
63//! ```
64
65use std::cell::Cell;
66use std::cell::RefCell;
67use std::fmt;
68use std::fmt::Debug;
69use std::fmt::Display;
70use std::sync::atomic::AtomicUsize;
71use std::sync::atomic::Ordering;
72
73use vortex_error::VortexExpect;
74use vortex_error::VortexResult;
75use vortex_error::vortex_err;
76
77use crate::ArrayRef;
78
79/// Controls how much rule and kernel resolution detail is captured.
80#[derive(Clone, Copy, Debug, Default, Eq, PartialEq)]
81pub enum TraceResolution {
82    /// Record only the operations that actually executed.
83    #[default]
84    ExecutedOnly,
85    /// Also record rule and kernel attempts that matched but declined, or did not match.
86    Attempts,
87}
88
89/// Options for [`trace_op_with`].
90#[derive(Clone, Copy, Debug, Default, Eq, PartialEq)]
91pub struct TraceOptions {
92    /// The amount of rule and kernel resolution detail to include.
93    pub resolution: TraceResolution,
94}
95
96/// The result of a traced operation.
97#[derive(Clone, Debug)]
98pub struct Traced<T> {
99    /// The value returned by the traced closure.
100    pub output: T,
101    /// A stable, snapshot-friendly rendering of optimizer and execution activity.
102    pub trace: TraceDisplay,
103}
104
105/// A stable, snapshot-friendly trace.
106#[derive(Clone, Debug, Default)]
107pub struct TraceDisplay {
108    options: TraceOptions,
109    events: Vec<TraceEvent>,
110}
111
112impl Display for TraceDisplay {
113    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
114        let hidden_events = self.hidden_events();
115        let mut optimize_depth = 0usize;
116        let mut wrote_event = false;
117
118        for (idx, event) in self.events.iter().enumerate() {
119            if hidden_events[idx] {
120                continue;
121            }
122
123            if event.closes_before(self.options.resolution) {
124                optimize_depth = optimize_depth.saturating_sub(1);
125            }
126
127            if event.is_hidden(self.options.resolution) {
128                continue;
129            }
130
131            if wrote_event {
132                writeln!(f)?;
133            } else {
134                wrote_event = true;
135            }
136
137            write_indent(
138                f,
139                optimize_depth + event.relative_indent(self.options.resolution, optimize_depth > 0),
140            )?;
141            event.fmt_line(f, self.options.resolution)?;
142
143            if event.opens_after(self.options.resolution) {
144                optimize_depth += 1;
145            }
146            if event.closes_after(self.options.resolution) {
147                optimize_depth = optimize_depth.saturating_sub(1);
148            }
149        }
150        Ok(())
151    }
152}
153
154impl TraceDisplay {
155    fn hidden_events(&self) -> Vec<bool> {
156        let mut hidden = vec![false; self.events.len()];
157        if self.options.resolution != TraceResolution::ExecutedOnly {
158            return hidden;
159        }
160
161        let mut optimize_stack = Vec::new();
162        for (idx, event) in self.events.iter().enumerate() {
163            match event {
164                TraceEvent::OptimizeStart { .. } => optimize_stack.push(idx),
165                TraceEvent::OptimizeDone { changed, .. } => {
166                    let Some(start) = optimize_stack.pop() else {
167                        continue;
168                    };
169                    if !changed {
170                        hidden[start..=idx].fill(true);
171                    }
172                }
173                _ => {}
174            }
175        }
176        hidden
177    }
178}
179
180fn write_indent(f: &mut fmt::Formatter<'_>, depth: usize) -> fmt::Result {
181    for _ in 0..depth {
182        f.write_str("  ")?;
183    }
184    Ok(())
185}
186
187/// Run `f` while capturing a trace of the optimizer and executor work it performs.
188///
189/// `f` typically invokes an operation that drives the executor or optimizer, such as
190/// [`ArrayOptimizer::optimize`][crate::optimizer::ArrayOptimizer::optimize] or
191/// [`ArrayRef::execute`][crate::ArrayRef::execute]. While `f` runs,
192/// the optimizer and executor emit structured events via the `trace_op!`
193/// macro into a thread-local recorder. When `f` returns, the recorder is finalized and
194/// returned alongside the closure's output as a [`Traced<T>`].
195///
196/// The default resolution ([`TraceResolution::ExecutedOnly`]) records the rule rewrites,
197/// parent kernels, execution steps, and builder activity that actually executed. Optimizer
198/// passes that produced no change are hidden from the rendered trace. Use [`trace_op_with`]
199/// with [`TraceResolution::Attempts`] when a test needs to assert on declined rule attempts,
200/// kernels that did not match, or other fall-through detail.
201///
202/// # Examples
203///
204/// ```ignore
205/// let traced = trace_op(|| filter_array.optimize())?;
206/// assert!(traced.output.is::<Primitive>());
207/// insta::assert_snapshot!(traced.trace.to_string(), @r"
208/// optimize root=vortex.filter(i32, len=4) session=false
209///   reduce TrivialFilterRule: vortex.filter(i32, len=4) -> vortex.primitive(i32, len=4)
210///   done output=vortex.primitive(i32, len=4)
211/// ");
212/// ```
213///
214/// # Errors
215///
216/// Returns whatever error `f` produces. Returns an error if a recorder is already active on
217/// the current thread — nested traces are not supported.
218pub fn trace_op<T>(f: impl FnOnce() -> VortexResult<T>) -> VortexResult<Traced<T>> {
219    trace_op_with(TraceOptions::default(), f)
220}
221
222/// Run `f` while capturing a trace using `options`.
223///
224/// See [`trace_op`] for the common case. Use this when you need to override the default
225/// [`TraceResolution`] to capture declined rules and unmatched kernels.
226///
227/// Trace capture is thread-local and intentionally does not propagate to worker threads. Nested
228/// trace captures return an error so tests do not accidentally merge unrelated traces.
229pub fn trace_op_with<T>(
230    options: TraceOptions,
231    f: impl FnOnce() -> VortexResult<T>,
232) -> VortexResult<Traced<T>> {
233    let interest = TraceInterest::from(options.resolution);
234    ACTIVE_TRACE.with(|active| {
235        let mut active = active.borrow_mut();
236        if active.is_some() {
237            return Err(vortex_err!("trace_op captures cannot be nested"));
238        }
239        *active = Some(TraceRecorder::new(options));
240        Ok(())
241    })?;
242    TRACE_INTEREST.with(|trace_interest| trace_interest.set(interest));
243    ACTIVE_TRACE_COUNT.fetch_add(1, Ordering::Relaxed);
244    if interest == TraceInterest::Attempts {
245        ATTEMPTS_TRACE_COUNT.fetch_add(1, Ordering::Relaxed);
246    }
247
248    let guard = ActiveTraceGuard { interest };
249    let output = f();
250    let recorder = ACTIVE_TRACE.with(|active| {
251        active
252            .borrow_mut()
253            .take()
254            .vortex_expect("trace recorder must be installed")
255    });
256    drop(guard);
257
258    output.map(|output| Traced {
259        output,
260        trace: recorder.finish(),
261    })
262}
263
264/// Returns true when the current thread has an active trace recorder.
265#[inline(always)]
266pub(crate) fn is_active() -> bool {
267    if ACTIVE_TRACE_COUNT.load(Ordering::Relaxed) == 0 {
268        return false;
269    }
270    TRACE_INTEREST.with(|interest| interest.get().is_active())
271}
272
273#[inline(always)]
274fn attempts_enabled() -> bool {
275    if ATTEMPTS_TRACE_COUNT.load(Ordering::Relaxed) == 0 {
276        return false;
277    }
278    TRACE_INTEREST.with(|interest| interest.get() == TraceInterest::Attempts)
279}
280
281#[derive(Clone, Copy, Debug)]
282enum TraceSource {
283    Static,
284    Session(usize),
285}
286
287impl Display for TraceSource {
288    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
289        match self {
290            TraceSource::Static => f.write_str("static"),
291            TraceSource::Session(idx) => write!(f, "session[{idx}]"),
292        }
293    }
294}
295
296#[derive(Clone, Copy, Debug)]
297enum AttemptOutcome {
298    Declined,
299    NoMatch,
300}
301
302impl Display for AttemptOutcome {
303    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
304        match self {
305            AttemptOutcome::Declined => f.write_str("declined"),
306            AttemptOutcome::NoMatch => f.write_str("no-match"),
307        }
308    }
309}
310
311#[derive(Clone, Copy, Debug, Default, Eq, PartialEq)]
312enum TraceInterest {
313    #[default]
314    Off,
315    ExecutedOnly,
316    Attempts,
317}
318
319impl TraceInterest {
320    #[inline]
321    fn is_active(self) -> bool {
322        self != Self::Off
323    }
324}
325
326impl From<TraceResolution> for TraceInterest {
327    fn from(resolution: TraceResolution) -> Self {
328        match resolution {
329            TraceResolution::ExecutedOnly => Self::ExecutedOnly,
330            TraceResolution::Attempts => Self::Attempts,
331        }
332    }
333}
334
335/// Snapshot-friendly wrapper around [`ArrayRef`] that renders the encoding, dtype, and length
336/// using the canonical [`Display`] format (`vortex.primitive(i32, len=4)`).
337///
338/// Carries a clone of the [`ArrayRef`] instead of duplicating fields,
339/// so trace events stay small and share the same rendering as every other `{array}` print in
340/// the codebase.
341#[derive(Clone, Debug)]
342pub(crate) struct ArraySummary(ArrayRef);
343
344impl ArraySummary {
345    pub(crate) fn new(array: &ArrayRef) -> Self {
346        Self(array.clone())
347    }
348}
349
350impl Display for ArraySummary {
351    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
352        Display::fmt(&self.0, f)
353    }
354}
355
356pub(crate) fn record_optimize_start(root: &ArrayRef, session: bool) {
357    record(TraceEvent::OptimizeStart {
358        root: ArraySummary::new(root),
359        session,
360    });
361}
362
363pub(crate) fn record_optimize_loop_start(array: &ArrayRef) {
364    if !attempts_enabled() {
365        return;
366    }
367    record(TraceEvent::OptimizeLoopStart {
368        array: ArraySummary::new(array),
369    });
370}
371
372pub(crate) fn record_optimize_loop_end() {
373    if !attempts_enabled() {
374        return;
375    }
376    record(TraceEvent::OptimizeLoopEnd);
377}
378
379pub(crate) fn record_optimize_reduce_none(array: &ArrayRef) {
380    if !attempts_enabled() {
381        return;
382    }
383    record(TraceEvent::PhaseNone {
384        indent: 0,
385        phase: "reduce",
386        subject: "array",
387        array: ArraySummary::new(array),
388    });
389}
390
391pub(crate) fn record_optimize_parent_reduce_none(array: &ArrayRef) {
392    if !attempts_enabled() {
393        return;
394    }
395    record(TraceEvent::PhaseNone {
396        indent: 0,
397        phase: "reduce_parent",
398        subject: "array",
399        array: ArraySummary::new(array),
400    });
401}
402
403pub(crate) fn record_optimize_done(output: &ArrayRef, changed: bool) {
404    record(TraceEvent::OptimizeDone {
405        output: ArraySummary::new(output),
406        changed,
407    });
408}
409
410pub(crate) fn record_optimize_recursive_start(root: &ArrayRef) {
411    record(TraceEvent::OptimizeRecursiveStart {
412        root: ArraySummary::new(root),
413    });
414}
415
416pub(crate) fn record_optimize_recursive_slot(slot_idx: usize, input: &ArrayRef, output: &ArrayRef) {
417    record(TraceEvent::OptimizeRecursiveSlot {
418        slot_idx,
419        input: ArraySummary::new(input),
420        output: ArraySummary::new(output),
421    });
422}
423
424pub(crate) fn record_reduce_applied(array: &ArrayRef, rule: &dyn Debug, output: &ArrayRef) {
425    record(TraceEvent::ReduceApplied {
426        array: ArraySummary::new(array),
427        rule: compact_label(rule),
428        output: ArraySummary::new(output),
429    });
430}
431
432pub(crate) fn record_reduce_declined(array: &ArrayRef, rule: &dyn Debug) {
433    if !attempts_enabled() {
434        return;
435    }
436    record(TraceEvent::ReduceAttempt {
437        array: ArraySummary::new(array),
438        rule: compact_label(rule),
439        outcome: AttemptOutcome::Declined,
440    });
441}
442
443pub(crate) fn record_session_parent_reduce_applied(
444    parent: &ArrayRef,
445    child: &ArrayRef,
446    slot_idx: usize,
447    plugin_idx: usize,
448    output: &ArrayRef,
449) {
450    record_parent_reduce_applied(
451        parent,
452        child,
453        slot_idx,
454        TraceSource::Session(plugin_idx),
455        "reduce_parent_fn",
456        output,
457    );
458}
459
460pub(crate) fn record_session_parent_reduce_declined(
461    parent: &ArrayRef,
462    child: &ArrayRef,
463    slot_idx: usize,
464    plugin_idx: usize,
465) {
466    record_parent_reduce_attempt(
467        parent,
468        child,
469        slot_idx,
470        TraceSource::Session(plugin_idx),
471        "reduce_parent_fn",
472        AttemptOutcome::Declined,
473    );
474}
475
476pub(crate) fn record_static_parent_reduce_no_match(
477    parent: &ArrayRef,
478    child: &ArrayRef,
479    slot_idx: usize,
480    rule: &dyn Debug,
481) {
482    record_parent_reduce_attempt(
483        parent,
484        child,
485        slot_idx,
486        TraceSource::Static,
487        compact_label(rule),
488        AttemptOutcome::NoMatch,
489    );
490}
491
492pub(crate) fn record_static_parent_reduce_applied(
493    parent: &ArrayRef,
494    child: &ArrayRef,
495    slot_idx: usize,
496    rule: &dyn Debug,
497    output: &ArrayRef,
498) {
499    record_parent_reduce_applied(
500        parent,
501        child,
502        slot_idx,
503        TraceSource::Static,
504        compact_label(rule),
505        output,
506    );
507}
508
509pub(crate) fn record_static_parent_reduce_declined(
510    parent: &ArrayRef,
511    child: &ArrayRef,
512    slot_idx: usize,
513    rule: &dyn Debug,
514) {
515    record_parent_reduce_attempt(
516        parent,
517        child,
518        slot_idx,
519        TraceSource::Static,
520        compact_label(rule),
521        AttemptOutcome::Declined,
522    );
523}
524
525fn record_parent_reduce_attempt(
526    parent: &ArrayRef,
527    child: &ArrayRef,
528    slot_idx: usize,
529    source: TraceSource,
530    rule: impl Into<String>,
531    outcome: AttemptOutcome,
532) {
533    if !attempts_enabled() {
534        return;
535    }
536    record(TraceEvent::ParentReduceAttempt {
537        parent: ArraySummary::new(parent),
538        child: ArraySummary::new(child),
539        slot_idx,
540        source,
541        rule: rule.into(),
542        outcome,
543    });
544}
545
546fn record_parent_reduce_applied(
547    parent: &ArrayRef,
548    child: &ArrayRef,
549    slot_idx: usize,
550    source: TraceSource,
551    rule: impl Into<String>,
552    output: &ArrayRef,
553) {
554    record(TraceEvent::ParentReduceApplied {
555        parent: ArraySummary::new(parent),
556        child: ArraySummary::new(child),
557        slot_idx,
558        source,
559        rule: rule.into(),
560        output: ArraySummary::new(output),
561    });
562}
563
564pub(crate) fn record_execute_until_start<M>(root: &ArrayRef) {
565    record(TraceEvent::ExecuteUntilStart {
566        target: short_type_name::<M>(),
567        root: ArraySummary::new(root),
568    });
569}
570
571pub(crate) fn record_execute_until_iteration(
572    iteration: usize,
573    current: &ArrayRef,
574    stack_parent: Option<(&ArrayRef, usize)>,
575    builder_active: bool,
576) {
577    record(TraceEvent::ExecuteUntilIteration {
578        iteration,
579        current: ArraySummary::new(current),
580        stack_parent: stack_parent.map(|(array, slot_idx)| (ArraySummary::new(array), slot_idx)),
581        builder_active,
582    });
583}
584
585pub(crate) fn record_execute_until_done_check(target: bool, canonical: bool) {
586    if !attempts_enabled() {
587        return;
588    }
589    record(TraceEvent::ExecuteUntilDoneCheck { target, canonical });
590}
591
592pub(crate) fn record_execute_until_return(output: &ArrayRef) {
593    record(TraceEvent::ExecuteUntilReturn {
594        output: ArraySummary::new(output),
595    });
596}
597
598pub(crate) fn record_execute_until_pop_frame(slot_idx: usize, output: &ArrayRef) {
599    record(TraceEvent::ExecuteUntilPopFrame {
600        slot_idx,
601        output: ArraySummary::new(output),
602    });
603}
604
605pub(crate) fn record_session_execute_parent_applied(
606    phase: &'static str,
607    parent: &ArrayRef,
608    child: &ArrayRef,
609    slot_idx: usize,
610    plugin_idx: usize,
611    output: &ArrayRef,
612) {
613    record_execute_parent_applied(
614        phase,
615        parent,
616        child,
617        slot_idx,
618        TraceSource::Session(plugin_idx),
619        "execute_parent_fn",
620        output,
621    );
622}
623
624pub(crate) fn record_session_execute_parent_declined(
625    phase: &'static str,
626    parent: &ArrayRef,
627    child: &ArrayRef,
628    slot_idx: usize,
629    plugin_idx: usize,
630) {
631    record_execute_parent_attempt(
632        phase,
633        parent,
634        child,
635        slot_idx,
636        TraceSource::Session(plugin_idx),
637        "execute_parent_fn",
638        AttemptOutcome::Declined,
639    );
640}
641
642fn record_execute_parent_attempt(
643    phase: &'static str,
644    parent: &ArrayRef,
645    child: &ArrayRef,
646    slot_idx: usize,
647    source: TraceSource,
648    kernel: impl Into<String>,
649    outcome: AttemptOutcome,
650) {
651    if !attempts_enabled() {
652        return;
653    }
654    record(TraceEvent::ExecuteParentAttempt {
655        phase,
656        parent: ArraySummary::new(parent),
657        child: ArraySummary::new(child),
658        slot_idx,
659        source,
660        kernel: kernel.into(),
661        outcome,
662    });
663}
664
665fn record_execute_parent_applied(
666    phase: &'static str,
667    parent: &ArrayRef,
668    child: &ArrayRef,
669    slot_idx: usize,
670    source: TraceSource,
671    kernel: impl Into<String>,
672    output: &ArrayRef,
673) {
674    record(TraceEvent::ExecuteParentApplied {
675        phase,
676        parent: ArraySummary::new(parent),
677        child: ArraySummary::new(child),
678        slot_idx,
679        source,
680        kernel: kernel.into(),
681        output: ArraySummary::new(output),
682    });
683}
684
685pub(crate) fn record_execute_parent_none(phase: &'static str, current: &ArrayRef) {
686    if !attempts_enabled() {
687        return;
688    }
689    record(TraceEvent::PhaseNone {
690        indent: 2,
691        phase,
692        subject: "current",
693        array: ArraySummary::new(current),
694    });
695}
696
697pub(crate) fn record_execute_optimized(input: &ArrayRef, output: &ArrayRef) {
698    let changed = !ArrayRef::ptr_eq(input, output);
699    if !changed && !attempts_enabled() {
700        return;
701    }
702    record(TraceEvent::ExecuteOptimized {
703        input: ArraySummary::new(input),
704        output: ArraySummary::new(output),
705        changed,
706    });
707}
708
709pub(crate) fn record_execute_encoding(array: &ArrayRef) {
710    if !attempts_enabled() {
711        return;
712    }
713    record(TraceEvent::ExecuteEncoding {
714        array: ArraySummary::new(array),
715    });
716}
717
718pub(crate) fn record_execute_slot(slot_idx: usize, parent: &ArrayRef, child: &ArrayRef) {
719    record(TraceEvent::SlotTransition {
720        step: "ExecuteSlot",
721        slot_idx,
722        parent: ArraySummary::new(parent),
723        child: ArraySummary::new(child),
724    });
725}
726
727pub(crate) fn record_builder_start(array: &ArrayRef) {
728    record(TraceEvent::BuilderEvent {
729        action: "start",
730        subject: "array",
731        array: ArraySummary::new(array),
732    });
733}
734
735pub(crate) fn record_append_child(slot_idx: usize, parent: &ArrayRef, child: &ArrayRef) {
736    record(TraceEvent::SlotTransition {
737        step: "AppendChild",
738        slot_idx,
739        parent: ArraySummary::new(parent),
740        child: ArraySummary::new(child),
741    });
742}
743
744pub(crate) fn record_builder_append(child: &ArrayRef) {
745    record(TraceEvent::BuilderEvent {
746        action: "append",
747        subject: "child",
748        array: ArraySummary::new(child),
749    });
750}
751
752pub(crate) fn record_execute_done(array: &ArrayRef) {
753    record(TraceEvent::ExecuteDone {
754        array: ArraySummary::new(array),
755    });
756}
757
758pub(crate) fn record_builder_finish(output: &ArrayRef) {
759    record(TraceEvent::BuilderEvent {
760        action: "finish",
761        subject: "output",
762        array: ArraySummary::new(output),
763    });
764}
765
766pub(crate) fn record_single_step_start(array: &ArrayRef) {
767    record(TraceEvent::SingleStepStart {
768        array: ArraySummary::new(array),
769    });
770}
771
772pub(crate) fn record_single_step_phase_none(phase: &'static str, array: &ArrayRef) {
773    if !attempts_enabled() {
774        return;
775    }
776    record(TraceEvent::PhaseNone {
777        indent: 1,
778        phase,
779        subject: "array",
780        array: ArraySummary::new(array),
781    });
782}
783
784pub(crate) fn record_single_step_applied(phase: &'static str, input: &ArrayRef, output: &ArrayRef) {
785    record(TraceEvent::SingleStepApplied {
786        phase,
787        input: ArraySummary::new(input),
788        output: ArraySummary::new(output),
789    });
790}
791
792fn record(event: TraceEvent) {
793    ACTIVE_TRACE.with(|active| {
794        if let Some(recorder) = active.borrow_mut().as_mut() {
795            recorder.events.push(event);
796        }
797    });
798}
799
800fn compact_label(value: &dyn Debug) -> String {
801    let label = format!("{value:?}");
802    if let Some(label) = adapter_field(&label, "rule") {
803        return label.to_string();
804    }
805    if let Some(label) = adapter_field(&label, "kernel") {
806        return label.to_string();
807    }
808    label
809}
810
811fn adapter_field<'a>(label: &'a str, field: &str) -> Option<&'a str> {
812    let marker = format!("{field}: ");
813    let start = label.find(&marker)? + marker.len();
814    let rest = &label[start..];
815    let end = rest.rfind(" }")?;
816    Some(&rest[..end])
817}
818
819fn short_type_name<T>() -> String {
820    std::any::type_name::<T>()
821        .rsplit("::")
822        .next()
823        .vortex_expect("type names are never empty")
824        .to_string()
825}
826
827thread_local! {
828    static TRACE_INTEREST: Cell<TraceInterest> = const { Cell::new(TraceInterest::Off) };
829    static ACTIVE_TRACE: RefCell<Option<TraceRecorder>> = const { RefCell::new(None) };
830}
831
832static ACTIVE_TRACE_COUNT: AtomicUsize = AtomicUsize::new(0);
833static ATTEMPTS_TRACE_COUNT: AtomicUsize = AtomicUsize::new(0);
834
835struct ActiveTraceGuard {
836    interest: TraceInterest,
837}
838
839impl Drop for ActiveTraceGuard {
840    fn drop(&mut self) {
841        if self.interest == TraceInterest::Attempts {
842            ATTEMPTS_TRACE_COUNT.fetch_sub(1, Ordering::Relaxed);
843        }
844        ACTIVE_TRACE_COUNT.fetch_sub(1, Ordering::Relaxed);
845        TRACE_INTEREST.with(|interest| interest.set(TraceInterest::Off));
846        ACTIVE_TRACE.with(|active| {
847            active.borrow_mut().take();
848        });
849    }
850}
851
852#[derive(Debug)]
853struct TraceRecorder {
854    options: TraceOptions,
855    events: Vec<TraceEvent>,
856}
857
858impl TraceRecorder {
859    fn new(options: TraceOptions) -> Self {
860        Self {
861            options,
862            events: Vec::new(),
863        }
864    }
865
866    fn finish(self) -> TraceDisplay {
867        TraceDisplay {
868            options: self.options,
869            events: self.events,
870        }
871    }
872}
873
874#[derive(Clone, Debug)]
875enum TraceEvent {
876    OptimizeStart {
877        root: ArraySummary,
878        session: bool,
879    },
880    OptimizeLoopStart {
881        array: ArraySummary,
882    },
883    OptimizeLoopEnd,
884    OptimizeDone {
885        output: ArraySummary,
886        changed: bool,
887    },
888    OptimizeRecursiveStart {
889        root: ArraySummary,
890    },
891    OptimizeRecursiveSlot {
892        slot_idx: usize,
893        input: ArraySummary,
894        output: ArraySummary,
895    },
896    ReduceAttempt {
897        array: ArraySummary,
898        rule: String,
899        outcome: AttemptOutcome,
900    },
901    ReduceApplied {
902        array: ArraySummary,
903        rule: String,
904        output: ArraySummary,
905    },
906    ParentReduceAttempt {
907        parent: ArraySummary,
908        child: ArraySummary,
909        slot_idx: usize,
910        source: TraceSource,
911        rule: String,
912        outcome: AttemptOutcome,
913    },
914    ParentReduceApplied {
915        parent: ArraySummary,
916        child: ArraySummary,
917        slot_idx: usize,
918        source: TraceSource,
919        rule: String,
920        output: ArraySummary,
921    },
922    ExecuteUntilStart {
923        target: String,
924        root: ArraySummary,
925    },
926    ExecuteUntilIteration {
927        iteration: usize,
928        current: ArraySummary,
929        stack_parent: Option<(ArraySummary, usize)>,
930        builder_active: bool,
931    },
932    ExecuteUntilDoneCheck {
933        target: bool,
934        canonical: bool,
935    },
936    ExecuteUntilReturn {
937        output: ArraySummary,
938    },
939    ExecuteUntilPopFrame {
940        slot_idx: usize,
941        output: ArraySummary,
942    },
943    ExecuteParentAttempt {
944        phase: &'static str,
945        parent: ArraySummary,
946        child: ArraySummary,
947        slot_idx: usize,
948        source: TraceSource,
949        kernel: String,
950        outcome: AttemptOutcome,
951    },
952    ExecuteParentApplied {
953        phase: &'static str,
954        parent: ArraySummary,
955        child: ArraySummary,
956        slot_idx: usize,
957        source: TraceSource,
958        kernel: String,
959        output: ArraySummary,
960    },
961    PhaseNone {
962        indent: usize,
963        phase: &'static str,
964        subject: &'static str,
965        array: ArraySummary,
966    },
967    ExecuteOptimized {
968        input: ArraySummary,
969        output: ArraySummary,
970        changed: bool,
971    },
972    ExecuteEncoding {
973        array: ArraySummary,
974    },
975    SlotTransition {
976        step: &'static str,
977        slot_idx: usize,
978        parent: ArraySummary,
979        child: ArraySummary,
980    },
981    BuilderEvent {
982        action: &'static str,
983        subject: &'static str,
984        array: ArraySummary,
985    },
986    ExecuteDone {
987        array: ArraySummary,
988    },
989    SingleStepStart {
990        array: ArraySummary,
991    },
992    SingleStepApplied {
993        phase: &'static str,
994        input: ArraySummary,
995        output: ArraySummary,
996    },
997}
998
999impl TraceEvent {
1000    fn is_hidden(&self, resolution: TraceResolution) -> bool {
1001        match resolution {
1002            TraceResolution::Attempts => matches!(self, TraceEvent::OptimizeLoopEnd),
1003            TraceResolution::ExecutedOnly => matches!(
1004                self,
1005                TraceEvent::OptimizeLoopStart { .. }
1006                    | TraceEvent::OptimizeLoopEnd
1007                    | TraceEvent::PhaseNone { .. }
1008                    | TraceEvent::ExecuteUntilDoneCheck { .. }
1009                    | TraceEvent::ExecuteEncoding { .. }
1010                    | TraceEvent::ExecuteOptimized { changed: false, .. }
1011                    | TraceEvent::ExecuteParentAttempt { .. }
1012                    | TraceEvent::ReduceAttempt { .. }
1013                    | TraceEvent::ParentReduceAttempt { .. }
1014            ),
1015        }
1016    }
1017
1018    fn opens_after(&self, resolution: TraceResolution) -> bool {
1019        match resolution {
1020            TraceResolution::Attempts => matches!(
1021                self,
1022                TraceEvent::OptimizeStart { .. } | TraceEvent::OptimizeLoopStart { .. }
1023            ),
1024            TraceResolution::ExecutedOnly => matches!(self, TraceEvent::OptimizeStart { .. }),
1025        }
1026    }
1027
1028    fn closes_before(&self, resolution: TraceResolution) -> bool {
1029        match resolution {
1030            TraceResolution::Attempts => matches!(self, TraceEvent::OptimizeLoopEnd),
1031            TraceResolution::ExecutedOnly => false,
1032        }
1033    }
1034
1035    fn closes_after(&self, _resolution: TraceResolution) -> bool {
1036        matches!(self, TraceEvent::OptimizeDone { .. })
1037    }
1038
1039    fn relative_indent(&self, _resolution: TraceResolution, in_optimize_scope: bool) -> usize {
1040        match self {
1041            TraceEvent::OptimizeStart { .. }
1042            | TraceEvent::OptimizeLoopStart { .. }
1043            | TraceEvent::OptimizeDone { .. } => 0,
1044            TraceEvent::ReduceAttempt { .. }
1045            | TraceEvent::ReduceApplied { .. }
1046            | TraceEvent::ParentReduceAttempt { .. }
1047            | TraceEvent::ParentReduceApplied { .. }
1048                if in_optimize_scope =>
1049            {
1050                0
1051            }
1052            TraceEvent::PhaseNone { indent, .. } => *indent,
1053            TraceEvent::ReduceAttempt { .. }
1054            | TraceEvent::ReduceApplied { .. }
1055            | TraceEvent::ParentReduceAttempt { .. }
1056            | TraceEvent::ParentReduceApplied { .. }
1057            | TraceEvent::ExecuteUntilDoneCheck { .. }
1058            | TraceEvent::ExecuteUntilPopFrame { .. }
1059            | TraceEvent::ExecuteParentAttempt { .. }
1060            | TraceEvent::ExecuteParentApplied { .. }
1061            | TraceEvent::ExecuteOptimized { .. }
1062            | TraceEvent::ExecuteEncoding { .. }
1063            | TraceEvent::SlotTransition { .. }
1064            | TraceEvent::BuilderEvent { .. }
1065            | TraceEvent::ExecuteDone { .. } => 2,
1066            TraceEvent::OptimizeRecursiveSlot { .. }
1067            | TraceEvent::ExecuteUntilIteration { .. }
1068            | TraceEvent::ExecuteUntilReturn { .. }
1069            | TraceEvent::SingleStepApplied { .. } => 1,
1070            TraceEvent::OptimizeLoopEnd
1071            | TraceEvent::OptimizeRecursiveStart { .. }
1072            | TraceEvent::ExecuteUntilStart { .. }
1073            | TraceEvent::SingleStepStart { .. } => 0,
1074        }
1075    }
1076
1077    fn fmt_line(&self, f: &mut fmt::Formatter<'_>, resolution: TraceResolution) -> fmt::Result {
1078        match self {
1079            TraceEvent::OptimizeStart { root, session } => {
1080                write!(f, "optimize root={root} session={session}")
1081            }
1082            TraceEvent::OptimizeLoopStart { array } => {
1083                write!(f, "loop input={array}")
1084            }
1085            TraceEvent::OptimizeLoopEnd => Ok(()),
1086            TraceEvent::OptimizeDone { output, changed } => match resolution {
1087                TraceResolution::Attempts => write!(f, "done output={output} changed={changed}"),
1088                TraceResolution::ExecutedOnly => write!(f, "done output={output}"),
1089            },
1090            TraceEvent::OptimizeRecursiveStart { root } => {
1091                write!(f, "optimize_recursive root={root}")
1092            }
1093            TraceEvent::OptimizeRecursiveSlot {
1094                slot_idx,
1095                input,
1096                output,
1097            } => write!(f, "recursive slot={slot_idx} input={input} output={output}"),
1098            TraceEvent::ReduceAttempt {
1099                array,
1100                rule,
1101                outcome,
1102            } => write!(
1103                f,
1104                "reduce attempt array={array} source=static rule={rule} outcome={outcome}"
1105            ),
1106            TraceEvent::ReduceApplied {
1107                array,
1108                rule,
1109                output,
1110            } => match resolution {
1111                TraceResolution::Attempts => write!(
1112                    f,
1113                    "reduce applied array={array} source=static rule={rule} output={output}"
1114                ),
1115                TraceResolution::ExecutedOnly => {
1116                    write!(f, "reduce {rule}: {array} -> {output}")
1117                }
1118            },
1119            TraceEvent::ParentReduceAttempt {
1120                parent,
1121                child,
1122                slot_idx,
1123                source,
1124                rule,
1125                outcome,
1126            } => write!(
1127                f,
1128                "reduce_parent attempt slot={slot_idx} parent={parent} child={child} source={source} rule={rule} outcome={outcome}"
1129            ),
1130            TraceEvent::ParentReduceApplied {
1131                parent,
1132                child,
1133                slot_idx,
1134                source,
1135                rule,
1136                output,
1137            } => match resolution {
1138                TraceResolution::Attempts => write!(
1139                    f,
1140                    "reduce_parent applied slot={slot_idx} parent={parent} child={child} source={source} rule={rule} output={output}"
1141                ),
1142                TraceResolution::ExecutedOnly => write!(
1143                    f,
1144                    "reduce_parent {source}:{rule} slot={slot_idx} parent={parent} child={child} -> {output}"
1145                ),
1146            },
1147            TraceEvent::ExecuteUntilStart { target, root } => {
1148                write!(f, "execute_until target={target} root={root}")
1149            }
1150            TraceEvent::ExecuteUntilIteration {
1151                iteration,
1152                current,
1153                stack_parent,
1154                builder_active,
1155            } => {
1156                write!(f, "iter {iteration} current={current}")?;
1157                if let Some((parent, slot_idx)) = stack_parent {
1158                    write!(f, " stack_parent={parent} slot={slot_idx}")?;
1159                }
1160                write!(f, " builder_active={builder_active}")
1161            }
1162            TraceEvent::ExecuteUntilDoneCheck { target, canonical } => {
1163                write!(f, "done_check target={target} canonical={canonical}")
1164            }
1165            TraceEvent::ExecuteUntilReturn { output } => {
1166                write!(f, "return output={output}")
1167            }
1168            TraceEvent::ExecuteUntilPopFrame { slot_idx, output } => {
1169                write!(f, "pop_frame slot={slot_idx} output={output}")
1170            }
1171            TraceEvent::ExecuteParentAttempt {
1172                phase,
1173                parent,
1174                child,
1175                slot_idx,
1176                source,
1177                kernel,
1178                outcome,
1179            } => write!(
1180                f,
1181                "{phase} attempt slot={slot_idx} parent={parent} child={child} source={source} kernel={kernel} outcome={outcome}"
1182            ),
1183            TraceEvent::ExecuteParentApplied {
1184                phase,
1185                parent,
1186                child,
1187                slot_idx,
1188                source,
1189                kernel,
1190                output,
1191            } => match resolution {
1192                TraceResolution::Attempts => write!(
1193                    f,
1194                    "{phase} applied slot={slot_idx} parent={parent} child={child} source={source} kernel={kernel} output={output}"
1195                ),
1196                TraceResolution::ExecutedOnly => write!(
1197                    f,
1198                    "{phase} {source}:{kernel} slot={slot_idx} parent={parent} child={child} -> {output}"
1199                ),
1200            },
1201            TraceEvent::PhaseNone {
1202                phase,
1203                subject,
1204                array,
1205                ..
1206            } => {
1207                write!(f, "{phase} none {subject}={array}")
1208            }
1209            TraceEvent::ExecuteOptimized {
1210                input,
1211                output,
1212                changed,
1213            } => match resolution {
1214                TraceResolution::Attempts => write!(
1215                    f,
1216                    "optimize_ctx input={input} output={output} changed={changed}"
1217                ),
1218                TraceResolution::ExecutedOnly => write!(f, "optimize_ctx {input} -> {output}"),
1219            },
1220            TraceEvent::ExecuteEncoding { array } => {
1221                write!(f, "execute encoding={array}")
1222            }
1223            TraceEvent::SlotTransition {
1224                step,
1225                slot_idx,
1226                parent,
1227                child,
1228            } => write!(f, "{step} slot={slot_idx} parent={parent} child={child}"),
1229            TraceEvent::ExecuteDone { array } => {
1230                write!(f, "Done array={array}")
1231            }
1232            TraceEvent::BuilderEvent {
1233                action,
1234                subject,
1235                array,
1236            } => {
1237                write!(f, "builder {action} {subject}={array}")
1238            }
1239            TraceEvent::SingleStepStart { array } => {
1240                write!(f, "execute_step input={array}")
1241            }
1242            TraceEvent::SingleStepApplied {
1243                phase,
1244                input,
1245                output,
1246            } => match resolution {
1247                TraceResolution::Attempts => {
1248                    write!(f, "{phase} applied input={input} output={output}")
1249                }
1250                TraceResolution::ExecutedOnly => write!(f, "{phase} {input} -> {output}"),
1251            },
1252        }
1253    }
1254}
1255
1256#[cfg(test)]
1257mod tests;
vortex_array/test_harness/trace/mod.rs

vortex_array/test_harness/trace/
mod.rs
