rig_harness/
timings.rs

1//! How long each system ran, as data: [`SystemTimings`], read per plugin
2//! through [`PluginTimings`]. It is filled when the harness is built with
3//! its `trace` feature, which turns on Bevy's spans around every system and
4//! schedule run; a plugin crate turns it on by depending on rig-harness
5//! with `features = ["trace"]`. The spans are info level, so a `RUST_LOG`
6//! that sets `bevy_ecs` below info leaves it empty. A run is charged to the
7//! plugin that added the system or observer ([`PluginSystems`],
8//! [`ProvidedBy`]), and kept with the schedule it ran in: a run in
9//! `AgentPass` (a stage system, or an observer its commands set off) is
10//! work an agent's pass waited on.
11//!
12//! ```
13//! use rig_harness::prelude::*;
14//!
15//! /// The plugins whose systems took longest, slowest first.
16//! fn slowest(timings: PluginTimings, names: Query<&Name>) -> Vec<String> {
17//!     let mut totals: Vec<_> = timings.totals().into_iter().collect();
18//!     totals.sort_by_key(|(_, timing)| std::cmp::Reverse(timing.total));
19//!     let mut lines = Vec::new();
20//!     for ((plugin, schedule), timing) in totals {
21//!         let plugin = plugin.and_then(|plugin| names.get(plugin).ok());
22//!         let plugin = plugin.map_or("rig", Name::as_str);
23//!         let schedule = schedule.unwrap_or_default();
24//!         lines.push(format!("{plugin} in {schedule}: {:?}", timing.total));
25//!     }
26//!     lines
27//! }
28//! ```
29
30use std::collections::{BTreeMap, HashMap};
31use std::fmt::Debug;
32use std::mem;
33use std::sync::{Arc, Mutex, MutexGuard, PoisonError};
34use std::time::{Duration, Instant};
35
36use bevy_ecs::observer::Observer;
37use bevy_ecs::prelude::*;
38use bevy_ecs::system::SystemParam;
39use bevy_log::tracing::Subscriber;
40use bevy_log::tracing::field::{Field, Visit};
41use bevy_log::tracing::span::{Attributes, Id};
42use bevy_log::tracing_subscriber::layer::{Context, Layer};
43use bevy_log::tracing_subscriber::registry::LookupSpan;
44
45use crate::{PluginSystems, ProvidedBy};
46
47/// The name Bevy gives the span around a system's run.
48const SYSTEM: &str = "system";
49
50/// The name Bevy gives the span around a schedule's run.
51const SCHEDULE: &str = "schedule";
52
53/// How long each system ran, by the system's name, such as
54/// `rig_tui::input::read_input`, and the schedule it ran in: totals so far,
55/// and each run of the last whole frame. Clones share the timings; the log
56/// fills them from other threads as systems run.
57#[derive(Resource, Clone, Default)]
58pub struct SystemTimings(Arc<Mutex<Timings>>);
59
60/// What [`SystemTimings`] holds.
61#[derive(Default)]
62struct Timings {
63    /// Per system and schedule.
64    totals: BTreeMap<(String, Option<String>), Timing>,
65    /// The runs of this frame so far, in order.
66    frame: Vec<(String, Option<String>, Duration)>,
67    /// The runs of the last whole frame, in order.
68    last: Vec<(String, Option<String>, Duration)>,
69    /// The labels of the schedules running now, the innermost last: they
70    /// run one at a time, nested only inside exclusive systems.
71    schedules: Vec<String>,
72}
73
74/// How often a system, or the systems of a plugin, ran and for how long.
75#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)]
76pub struct Timing {
77    /// How many runs.
78    pub runs: u64,
79    /// Their time together.
80    pub total: Duration,
81    /// The longest run.
82    pub max: Duration,
83}
84
85impl Timing {
86    fn add(&mut self, took: Duration) {
87        self.runs += 1;
88        self.total += took;
89        self.max = self.max.max(took);
90    }
91}
92
93impl SystemTimings {
94    fn lock(&self) -> MutexGuard<'_, Timings> {
95        self.0.lock().unwrap_or_else(PoisonError::into_inner)
96    }
97
98    /// Each system's timing so far, by its name and its schedule's label.
99    pub fn systems(&self) -> BTreeMap<(String, Option<String>), Timing> {
100        self.lock().totals.clone()
101    }
102
103    /// Forgets every timing, such as to measure from now on.
104    pub fn clear(&self) {
105        let mut timings = self.lock();
106        timings.totals.clear();
107        timings.frame.clear();
108        timings.last.clear();
109    }
110
111    /// Ends the frame: its runs become the last whole frame's.
112    fn next_frame(&self) {
113        let mut timings = self.lock();
114        let frame = mem::take(&mut timings.frame);
115        timings.last = frame;
116    }
117
118    fn record(&self, system: &str, took: Duration) {
119        let mut timings = self.lock();
120        let schedule = timings.schedules.last().cloned();
121        let key = (system.to_owned(), schedule.clone());
122        timings.totals.entry(key).or_default().add(took);
123        timings.frame.push((system.to_owned(), schedule, took));
124    }
125}
126
127/// Ends each frame of [`SystemTimings`], in `First`.
128pub(crate) fn next_frame(timings: Res<SystemTimings>) {
129    timings.next_frame();
130}
131
132/// [`SystemTimings`] per plugin: each run charged to the plugin that added
133/// its system ([`PluginSystems`]) or observer ([`ProvidedBy`]); `None` for
134/// the harness's own and Bevy's.
135#[derive(SystemParam)]
136pub struct PluginTimings<'w, 's> {
137    timings: Res<'w, SystemTimings>,
138    systems: Option<Res<'w, PluginSystems>>,
139    observers: Query<'w, 's, (&'static Observer, &'static ProvidedBy)>,
140}
141
142/// One system run of the last whole frame, from [`PluginTimings::last_frame`].
143#[derive(Clone, Debug, PartialEq, Eq)]
144pub struct SystemRun {
145    /// The system's name.
146    pub system: String,
147    /// The plugin that added it; `None` for the harness's own and Bevy's.
148    pub plugin: Option<Entity>,
149    /// The label of the schedule it ran in, such as `AgentPass`.
150    pub schedule: Option<String>,
151    /// How long it ran.
152    pub took: Duration,
153}
154
155impl PluginTimings<'_, '_> {
156    /// The timings so far per plugin and schedule.
157    pub fn totals(&self) -> BTreeMap<(Option<Entity>, Option<String>), Timing> {
158        let plugin = self.plugin_of();
159        let mut totals = BTreeMap::<_, Timing>::new();
160        for ((system, schedule), timing) in self.timings.lock().totals.iter() {
161            let total = totals.entry((plugin(system, schedule), schedule.clone()));
162            let total = total.or_default();
163            total.runs += timing.runs;
164            total.total += timing.total;
165            total.max = total.max.max(timing.max);
166        }
167        totals
168    }
169
170    /// Each system run of the last whole frame, in order.
171    pub fn last_frame(&self) -> Vec<SystemRun> {
172        let plugin = self.plugin_of();
173        let last = self.timings.lock().last.clone();
174        let runs = last.into_iter().map(|(system, schedule, took)| SystemRun {
175            plugin: plugin(&system, &schedule),
176            system,
177            schedule,
178            took,
179        });
180        runs.collect()
181    }
182
183    /// The plugin a run of a system in a schedule is charged to.
184    fn plugin_of(&self) -> impl Fn(&str, &Option<String>) -> Option<Entity> + '_ {
185        let mut observers = HashMap::<String, Option<Entity>>::new();
186        for (observer, &ProvidedBy(plugin)) in &self.observers {
187            let by = observers.entry(observer.system_name().to_string());
188            let by = by.or_insert(Some(plugin));
189            if *by != Some(plugin) {
190                *by = None;
191            }
192        }
193        move |system, schedule| {
194            let added = schedule.as_ref().and_then(|schedule| {
195                let systems = self.systems.as_ref()?;
196                systems.plugin(system, schedule)
197            });
198            added.or_else(|| observers.get(system).copied().flatten())
199        }
200    }
201}
202
203/// The log layer that times each system span from entering it to leaving
204/// it into its [`SystemTimings`].
205pub(crate) struct TimeSystems(pub(crate) SystemTimings);
206
207/// A system span's name, and when it was entered while it runs.
208struct Running {
209    system: String,
210    since: Option<Instant>,
211}
212
213/// A schedule span's label.
214struct Scheduled(String);
215
216/// Reads the `name` field of a system or schedule span.
217#[derive(Default)]
218struct SpanName(String);
219
220impl Visit for SpanName {
221    fn record_str(&mut self, field: &Field, value: &str) {
222        if field.name() == "name" {
223            value.clone_into(&mut self.0);
224        }
225    }
226
227    fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
228        if field.name() == "name" && self.0.is_empty() {
229            self.0 = format!("{value:?}");
230        }
231    }
232}
233
234impl<S: Subscriber + for<'a> LookupSpan<'a>> Layer<S> for TimeSystems {
235    fn on_new_span(&self, attributes: &Attributes<'_>, id: &Id, context: Context<'_, S>) {
236        let kind = attributes.metadata().name();
237        if kind != SYSTEM && kind != SCHEDULE {
238            return;
239        }
240        let mut name = SpanName::default();
241        attributes.record(&mut name);
242        let Some(span) = context.span(id) else {
243            return;
244        };
245        let mut extensions = span.extensions_mut();
246        if kind == SYSTEM {
247            extensions.insert(Running {
248                system: name.0,
249                since: None,
250            });
251        } else {
252            extensions.insert(Scheduled(name.0));
253        }
254    }
255
256    fn on_enter(&self, id: &Id, context: Context<'_, S>) {
257        let Some(span) = context.span(id) else {
258            return;
259        };
260        let mut extensions = span.extensions_mut();
261        if let Some(running) = extensions.get_mut::<Running>() {
262            running.since = Some(Instant::now());
263        } else if let Some(Scheduled(label)) = extensions.get_mut::<Scheduled>() {
264            self.0.lock().schedules.push(label.clone());
265        }
266    }
267
268    fn on_exit(&self, id: &Id, context: Context<'_, S>) {
269        let Some(span) = context.span(id) else {
270            return;
271        };
272        let mut extensions = span.extensions_mut();
273        if let Some(running) = extensions.get_mut::<Running>()
274            && let Some(since) = running.since.take()
275        {
276            self.0.record(&running.system, since.elapsed());
277        } else if extensions.get_mut::<Scheduled>().is_some() {
278            self.0.lock().schedules.pop();
279        }
280    }
281}
282
283#[cfg(test)]
284mod tests;
rig_harness/timings.rs

rig_harness/
timings.rs
