des_sim/modeling/hook/instance/
trace.rs

1//! The `trace` module provides the `TraceHook`, a built-in `Hook` implementation
2//! for logging and tracing simulation events and state changes.
3//!
4//! This hook outputs detailed information about the simulation's progression,
5//! including tick and micro-step transitions, source firings, event processing,
6//! and model summaries. It is highly configurable via feature flags for verbosity.
7
8use crate::modeling::event::Event;
9use crate::modeling::hook::Hook;
10use crate::modeling::model::Model;
11use crate::primitive::time::{Duration, MicroStep, SimTime};
12use crate::source_handler::{SourceReadyEntry, SourceView};
13use log::{debug, info, trace};
14use std::fmt;
15
16/// A trait for providing a concise summary representation of a model.
17pub trait ModelSummary {
18    /// Formats the model's summary for display.
19    fn summary(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result;
20}
21
22/// An adapter that bridges the `ModelSummary` trait with `fmt::Display`.
23struct ModelLogAdapter<'a, M>(&'a M);
24
25impl<'a, M: ModelSummary> fmt::Display for ModelLogAdapter<'a, M> {
26    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
27        self.0.summary(f)
28    }
29}
30
31/// A [Hook] that traces the simulation state.
32/// If the `verbose_debug` feature is enabled, it also outputs the model's detailed state
33/// using the [Debug] trait.
34pub struct TraceHook;
35
36impl<E, M> Hook<E, M> for TraceHook
37where
38    E: fmt::Debug,
39    M: Model<E> + ModelSummary + fmt::Debug,
40{
41    fn before_simulation(&self, model: &M) {
42        info!("--- [SIMULATION START] Time: {:?} ---", SimTime::zero());
43        self.info_log_model(model, "");
44    }
45
46    fn after_simulation(&self, model: &M, end_tick: SimTime) {
47        info!("--- [SIMULATION END] Time: {:?} ---", end_tick);
48        self.info_log_model(model, "");
49    }
50
51    fn before_tick(&self, model: &M, current_tick: SimTime, skipped_duration: Duration) {
52        info!(
53            "  >>> Tick at {:?} (skipped: {} ticks)",
54            current_tick, skipped_duration
55        );
56        self.info_log_model(model, "  ");
57    }
58
59    fn after_tick(&self, model: &M, current_tick: SimTime, last_micro_step: MicroStep) {
60        info!(
61            "  <<< Tick at {:?} finished (last μSteps: {})",
62            current_tick, last_micro_step
63        );
64        self.info_log_model(model, "  ");
65    }
66
67    fn before_micro_step(&self, model: &M, current_tick: SimTime, current_micro_step: MicroStep) {
68        debug!(
69            "  [μStep: {} at {:?}] START",
70            current_micro_step, current_tick
71        );
72        self.debug_log_model(model, "  ");
73    }
74
75    fn after_micro_step(&self, model: &M, current_tick: SimTime, current_micro_step: MicroStep) {
76        debug!(
77            "  [μStep: {} at {:?}] END",
78            current_micro_step, current_tick
79        );
80        self.debug_log_model(model, "  ");
81    }
82
83    fn on_discard_remain_micro_step(
84        &self,
85        model: &M,
86        current_tick: SimTime,
87        first_discarded_micro_step: MicroStep,
88        discarded_sources: &[SourceReadyEntry],
89        discarded_events: &[Event<E>],
90    ) {
91        debug!(
92            "  !!! [DISCARD REMAINS at {:?}] Start μStep: {}, Sources: {:?}, Events: {:?}",
93            current_tick, first_discarded_micro_step, discarded_sources, discarded_events
94        );
95        self.debug_log_model(model, "  ");
96    }
97
98    fn before_register_source(&self, model: &M, name: &str) {
99        debug!("> Start Register Source: {}", name);
100        self.debug_log_model(model, "");
101    }
102
103    fn after_register_source(&self, model: &M, name: &str) {
104        debug!("< After Register Source: {}", name);
105        self.debug_log_model(model, "");
106    }
107
108    fn before_source_phase(&self, model: &M, current_tick: SimTime, current_micro_step: MicroStep) {
109        debug!(
110            "    > Source Phase at {:?} (μStep: {})",
111            current_tick, current_micro_step
112        );
113        self.debug_log_model(model, "    ");
114    }
115
116    fn before_source(
117        &self,
118        model: &M,
119        _current_tick: SimTime,
120        _current_micro_step: MicroStep,
121        source_view: &SourceView,
122    ) {
123        trace!("      + Source firing | Source: {:?}", source_view);
124        self.trace_log_model(model, "      ");
125    }
126
127    fn after_source(
128        &self,
129        model: &M,
130        _current_tick: SimTime,
131        _current_micro_step: MicroStep,
132        source_view: &SourceView,
133        computed_next_fire: Option<SimTime>,
134    ) {
135        trace!(
136            "      - Source finished (next: after {:?} tick) | Source: {:?}",
137            computed_next_fire, source_view
138        );
139        self.trace_log_model(model, "      ");
140    }
141
142    fn cancel_source(
143        &self,
144        model: &M,
145        current_tick: SimTime,
146        current_micro_step: MicroStep,
147        scheduled_at: SimTime,
148        source_view: &SourceView,
149    ) {
150        debug!(
151            "    ! Source canceled at {:?} (current μStep: {}) | Source: {:?} at scheduled: {}",
152            current_tick, current_micro_step, source_view, scheduled_at
153        );
154        self.debug_log_model(model, "    ");
155    }
156
157    fn discard_source(
158        &self,
159        model: &M,
160        current_tick: SimTime,
161        current_micro_step: MicroStep,
162        source_view: &SourceView,
163    ) {
164        debug!(
165            "    ! Source discarded at {:?} (last handle μStep: {}) | Source: {:?}",
166            current_tick, current_micro_step, source_view
167        );
168        self.debug_log_model(model, "    ");
169    }
170
171    fn after_source_phase(&self, model: &M, current_tick: SimTime, current_micro_step: MicroStep) {
172        debug!(
173            "    < Source Phase finished at {:?} (μStep: {})",
174            current_tick, current_micro_step,
175        );
176        self.debug_log_model(model, "    ");
177    }
178
179    fn before_event_phase(&self, model: &M, current_tick: SimTime, current_micro_step: MicroStep) {
180        debug!(
181            "    > Event Phase at {:?} (μStep: {})",
182            current_tick, current_micro_step
183        );
184        self.debug_log_model(model, "    ");
185    }
186
187    fn before_event(
188        &self,
189        model: &M,
190        _current_tick: SimTime,
191        _micro_step: MicroStep,
192        event: &Event<E>,
193    ) {
194        trace!("      + Event firing | Event: {:?}", event);
195        self.trace_log_model(model, "      ");
196    }
197
198    fn after_event(
199        &self,
200        model: &M,
201        _current_tick: SimTime,
202        _micro_step: MicroStep,
203        event: &Event<E>,
204    ) {
205        trace!("      - Event finished | Event: {:?}", event);
206        self.trace_log_model(model, "      ");
207    }
208
209    fn cancel_event(
210        &self,
211        model: &M,
212        current_tick: SimTime,
213        current_micro_step: MicroStep,
214        scheduled_at: SimTime,
215        event: &Event<E>,
216    ) {
217        debug!(
218            "    ! Event canceled at {:?} (current μStep: {}) | Event: {:?} at scheduled: {}",
219            current_tick, current_micro_step, event, scheduled_at
220        );
221        self.debug_log_model(model, "    ");
222    }
223
224    fn discard_event(
225        &self,
226        model: &M,
227        current_tick: SimTime,
228        current_micro_step: MicroStep,
229        event: &Event<E>,
230    ) {
231        debug!(
232            "    ! Event canceled at {:?} (last handle μStep: {}) | Event: {:?}",
233            current_tick, current_micro_step, event
234        );
235        self.debug_log_model(model, "    ");
236    }
237
238    fn after_event_phase(&self, model: &M, current_tick: SimTime, current_micro_step: MicroStep) {
239        debug!(
240            "    < Event Phase finished at {:?} (μStep: {})",
241            current_tick, current_micro_step,
242        );
243        self.debug_log_model(model, "    ");
244    }
245}
246
247impl TraceHook {
248    fn info_log_model<M>(&self, model: &M, prefix: &'static str)
249    where
250        M: ModelSummary + fmt::Debug,
251    {
252        info!("{}  model summary: {}", prefix, ModelLogAdapter(model));
253
254        if cfg!(feature = "verbose_debug") {
255            info!("{}  model: {:?}", prefix, model);
256        }
257    }
258
259    fn debug_log_model<M>(&self, model: &M, prefix: &'static str)
260    where
261        M: ModelSummary + fmt::Debug,
262    {
263        debug!("{}  model summary: {}", prefix, ModelLogAdapter(model));
264
265        if cfg!(feature = "verbose_debug") {
266            debug!("{}  model: {:?}", prefix, model);
267        }
268    }
269
270    fn trace_log_model<M>(&self, model: &M, prefix: &'static str)
271    where
272        M: ModelSummary + fmt::Debug,
273    {
274        trace!("{}  model summary: {}", prefix, ModelLogAdapter(model));
275
276        if cfg!(feature = "verbose_debug") {
277            trace!("{}  model: {:?}", prefix, model);
278        }
279    }
280}
des_sim/modeling/hook/instance/trace.rs

des_sim/modeling/hook/instance/
trace.rs
