Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Merged by Bors] - Cleanups in diagnostics #3871

Closed
wants to merge 21 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -48,6 +48,6 @@ impl<T: Asset> AssetCountDiagnosticsPlugin<T> {
}

pub fn diagnostic_system(mut diagnostics: ResMut<Diagnostics>, assets: Res<Assets<T>>) {
diagnostics.add_measurement(Self::diagnostic_id(), assets.len() as f64);
diagnostics.add_measurement(Self::diagnostic_id(), || assets.len() as f64);
mockersf marked this conversation as resolved.
Show resolved Hide resolved
}
}
56 changes: 44 additions & 12 deletions crates/bevy_diagnostic/src/diagnostic.rs
Original file line number Diff line number Diff line change
Expand Up @@ -37,22 +37,30 @@ pub struct Diagnostic {
history: VecDeque<DiagnosticMeasurement>,
sum: f64,
max_history_length: usize,
pub is_enabled: bool,
}

impl Diagnostic {
mockersf marked this conversation as resolved.
Show resolved Hide resolved
/// Add a new value as a [`DiagnosticMeasurement`]. Its timestamp will be [`Instant::now`].
pub fn add_measurement(&mut self, value: f64) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am really not thrilled with the fact that all measurements are assumed to be f64, but that's probably out of scope.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yup me neither 🙁

let time = Instant::now();
if self.history.len() == self.max_history_length {
if let Some(removed_diagnostic) = self.history.pop_front() {
self.sum -= removed_diagnostic.value;
if self.max_history_length > 1 {
if self.history.len() == self.max_history_length {
if let Some(removed_diagnostic) = self.history.pop_front() {
self.sum -= removed_diagnostic.value;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel like there's a possibility of getting a consistent bias towards the numbers increasing, due to floating point ordering/precision madness.

OTOH, I don't care enough to come up with a clever way to fix it, unless someone runs into it in practise.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A potential solution would be to switch form storing the sum to storing the simple moving average directly. An incremental SMA is calculated as

$$ SMA_t = \frac{ X_t + SMA_{t-1} \times (n-1) }{ n } $$

where the impact of any rounding error trends towards zero.

The main advantage of the incremental SMA over the typical and current $\frac{ X_t + X_{t-1} + \cdots + X_{t-n} }{ n }$ is not needing to store the historical readings, though, and it's perhaps useful to have the history, especially for discrete diagnostics rather than continuous.

Perhaps the best solution really is to separate discrete from continuous diagnostics.

Copy link
Contributor

@CAD97 CAD97 Oct 21, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Strike that formula that's what I get for going off of memory. That's not a correct simple moving average; the SMA does require keeping track of the history. The correct incremental SMA formula is $$SMA_{k,\text{next}} = SMA_{k,\text{prev}} + \frac{1}{k}\left( p_{n+1} - p_{n-k+1} \right)$$. What I wrote above is some odd form of a weighted moving average where each sample contributes IIUC $1/(n+\text{age})$. This might be the standard weighted moving average; I'm not sure and my math brain is not on enough to determine that for sure.

}
}
}

self.sum += value;
self.sum += value;
} else {
self.history.clear();
self.sum = value;
}
self.history
.push_back(DiagnosticMeasurement { time, value });
}

/// Create a new diagnostic with the given ID, name and maximum history.
pub fn new(
id: DiagnosticId,
name: impl Into<Cow<'static, str>>,
Expand All @@ -74,28 +82,30 @@ impl Diagnostic {
history: VecDeque::with_capacity(max_history_length),
max_history_length,
sum: 0.0,
is_enabled: true,
}
}

/// Add a suffix to use when logging the value, can be used to show a unit.
#[must_use]
pub fn with_suffix(mut self, suffix: impl Into<Cow<'static, str>>) -> Self {
self.suffix = suffix.into();
self
}

/// Get the latest measurement from this diagnostic.
#[inline]
pub fn measurement(&self) -> Option<&DiagnosticMeasurement> {
self.history.back()
}

/// Get the latest value from this diagnostic.
pub fn value(&self) -> Option<f64> {
mockersf marked this conversation as resolved.
Show resolved Hide resolved
self.measurement().map(|measurement| measurement.value)
}

pub fn sum(&self) -> f64 {
self.sum
}

/// Return the mean (average) of this diagnostic's values.
/// N.B. this a cheap operation as the sum is cached.
pub fn average(&self) -> Option<f64> {
if !self.history.is_empty() {
Some(self.sum / self.history.len() as f64)
Expand All @@ -104,10 +114,12 @@ impl Diagnostic {
}
}

/// Return the number of elements for this diagnostic.
pub fn history_len(&self) -> usize {
self.history.len()
}

/// Return the duration between the oldest and most recent values for this diagnostic.
pub fn duration(&self) -> Option<Duration> {
if self.history.len() < 2 {
return None;
Expand All @@ -122,6 +134,7 @@ impl Diagnostic {
None
}

/// Return the maximum number of elements for this diagnostic.
pub fn get_max_history_length(&self) -> usize {
self.max_history_length
}
Expand All @@ -133,6 +146,11 @@ impl Diagnostic {
pub fn measurements(&self) -> impl Iterator<Item = &DiagnosticMeasurement> {
self.history.iter()
}

/// Clear the history of this diagnostic.
pub fn clear_history(&mut self) {
self.history.clear();
}
}

/// A collection of [Diagnostic]s
Expand All @@ -144,6 +162,7 @@ pub struct Diagnostics {
}

impl Diagnostics {
/// Add a new [`Diagnostic`].
pub fn add(&mut self, diagnostic: Diagnostic) {
self.diagnostics.insert(diagnostic.id, diagnostic);
}
Expand All @@ -156,18 +175,31 @@ impl Diagnostics {
self.diagnostics.get_mut(&id)
}

/// Get the latest [`DiagnosticMeasurement`] from an enabled [`Diagnostic`].
pub fn get_measurement(&self, id: DiagnosticId) -> Option<&DiagnosticMeasurement> {
self.diagnostics
.get(&id)
.filter(|diagnostic| diagnostic.is_enabled)
.and_then(|diagnostic| diagnostic.measurement())
}

pub fn add_measurement(&mut self, id: DiagnosticId, value: f64) {
if let Some(diagnostic) = self.diagnostics.get_mut(&id) {
diagnostic.add_measurement(value);
/// Add a measurement to an enabled [`Diagnostic`]. The measurement is passed as a function so that
/// it will be evaluated only if the [`Diagnostic`] is enabled. This can be useful if the value is
/// costly to calculate.
pub fn add_measurement<F>(&mut self, id: DiagnosticId, value: F)
where
F: FnOnce() -> f64,
{
if let Some(diagnostic) = self
.diagnostics
.get_mut(&id)
.filter(|diagnostic| diagnostic.is_enabled)
{
diagnostic.add_measurement(value());
}
}

/// Return an iterator over all [`Diagnostic`].
pub fn iter(&self) -> impl Iterator<Item = &Diagnostic> {
self.diagnostics.values()
}
Expand Down
14 changes: 4 additions & 10 deletions crates/bevy_diagnostic/src/entity_count_diagnostics_plugin.rs
Original file line number Diff line number Diff line change
@@ -1,8 +1,5 @@
use bevy_app::{App, Plugin};
use bevy_ecs::{
system::{IntoExclusiveSystem, ResMut},
world::World,
};
use bevy_ecs::{entity::Entities, system::ResMut};

use crate::{Diagnostic, DiagnosticId, Diagnostics};

Expand All @@ -13,7 +10,7 @@ pub struct EntityCountDiagnosticsPlugin;
impl Plugin for EntityCountDiagnosticsPlugin {
fn build(&self, app: &mut App) {
app.add_startup_system(Self::setup_system)
.add_system(Self::diagnostic_system.exclusive_system());
.add_system(Self::diagnostic_system);
}
}

Expand All @@ -25,10 +22,7 @@ impl EntityCountDiagnosticsPlugin {
diagnostics.add(Diagnostic::new(Self::ENTITY_COUNT, "entity_count", 20));
}

pub fn diagnostic_system(world: &mut World) {
let entity_count = world.entities().len();
if let Some(mut diagnostics) = world.get_resource_mut::<Diagnostics>() {
diagnostics.add_measurement(Self::ENTITY_COUNT, entity_count as f64);
}
pub fn diagnostic_system(mut diagnostics: ResMut<Diagnostics>, entities: &Entities) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

diagnostics.add_measurement(Self::ENTITY_COUNT, || entities.len() as f64);
}
}
32 changes: 13 additions & 19 deletions crates/bevy_diagnostic/src/frame_time_diagnostics_plugin.rs
Original file line number Diff line number Diff line change
Expand Up @@ -37,29 +37,23 @@ impl FrameTimeDiagnosticsPlugin {
time: Res<Time>,
mut state: ResMut<FrameTimeDiagnosticsState>,
) {
state.frame_count = state.frame_count.wrapping_add(1);
diagnostics.add_measurement(Self::FRAME_COUNT, state.frame_count as f64);
diagnostics.add_measurement(Self::FRAME_COUNT, || {
state.frame_count = state.frame_count.wrapping_add(1);
state.frame_count as f64
});

if time.delta_seconds_f64() == 0.0 {
return;
}

diagnostics.add_measurement(Self::FRAME_TIME, time.delta_seconds_f64());
if let Some(fps) = diagnostics
.get(Self::FRAME_TIME)
.and_then(|frame_time_diagnostic| {
frame_time_diagnostic
.average()
.and_then(|frame_time_average| {
if frame_time_average > 0.0 {
Some(1.0 / frame_time_average)
} else {
None
}
})
})
{
diagnostics.add_measurement(Self::FPS, fps);
}
diagnostics.add_measurement(Self::FRAME_TIME, || time.delta_seconds_f64());

diagnostics.add_measurement(Self::FPS, || 1.0 / time.delta_seconds_f64());
}
}

impl FrameTimeDiagnosticsState {
pub fn reset_frame_count(&mut self) {
self.frame_count = 0;
}
}
67 changes: 40 additions & 27 deletions crates/bevy_diagnostic/src/log_diagnostics_plugin.rs
Original file line number Diff line number Diff line change
Expand Up @@ -53,30 +53,29 @@ impl LogDiagnosticsPlugin {

fn log_diagnostic(diagnostic: &Diagnostic) {
if let Some(value) = diagnostic.value() {
if let Some(average) = diagnostic.average() {
info!(
target: "bevy diagnostic",
// Suffix is only used for 's' as in seconds currently,
// so we reserve one column for it; however,
// Do not reserve one column for the suffix in the average
// The ) hugging the value is more aesthetically pleasing
"{name:<name_width$}: {value:>11.6}{suffix:1} (avg {average:>.6}{suffix:})",
name = diagnostic.name,
value = value,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔥

It took me longer than I'd like to understand this change, as I thought you were removing it from printing. This confused me greatly.
A reminder in case anyone else is in the same situation: https://blog.rust-lang.org/2022/01/13/Rust-1.58.0.html#captured-identifiers-in-format-strings

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just to make sure that Bevy MSRV is latest!

suffix = diagnostic.suffix,
average = average,
name_width = crate::MAX_DIAGNOSTIC_NAME_WIDTH,
);
} else {
info!(
target: "bevy diagnostic",
"{name:<name_width$}: {value:>.6}{suffix:}",
name = diagnostic.name,
value = value,
suffix = diagnostic.suffix,
name_width = crate::MAX_DIAGNOSTIC_NAME_WIDTH,
);
if diagnostic.get_max_history_length() > 1 {
if let Some(average) = diagnostic.average() {
info!(
target: "bevy diagnostic",
// Suffix is only used for 's' as in seconds currently,
// so we reserve one column for it; however,
// Do not reserve one column for the suffix in the average
// The ) hugging the value is more aesthetically pleasing
"{name:<name_width$}: {value:>11.6}{suffix:1} (avg {average:>.6}{suffix:})",
name = diagnostic.name,
suffix = diagnostic.suffix,
name_width = crate::MAX_DIAGNOSTIC_NAME_WIDTH,
);
return;
}
}
info!(
target: "bevy diagnostic",
"{name:<name_width$}: {value:>.6}{suffix:}",
name = diagnostic.name,
suffix = diagnostic.suffix,
name_width = crate::MAX_DIAGNOSTIC_NAME_WIDTH,
);
}
}

Expand All @@ -87,11 +86,18 @@ impl LogDiagnosticsPlugin {
) {
if state.timer.tick(time.delta()).finished() {
if let Some(ref filter) = state.filter {
for diagnostic in filter.iter().map(|id| diagnostics.get(*id).unwrap()) {
for diagnostic in filter.iter().flat_map(|id| {
diagnostics
.get(*id)
.filter(|diagnostic| diagnostic.is_enabled)
}) {
Self::log_diagnostic(diagnostic);
}
} else {
for diagnostic in diagnostics.iter() {
for diagnostic in diagnostics
.iter()
.filter(|diagnostic| diagnostic.is_enabled)
{
Self::log_diagnostic(diagnostic);
}
}
Expand All @@ -105,11 +111,18 @@ impl LogDiagnosticsPlugin {
) {
if state.timer.tick(time.delta()).finished() {
if let Some(ref filter) = state.filter {
for diagnostic in filter.iter().map(|id| diagnostics.get(*id).unwrap()) {
for diagnostic in filter.iter().flat_map(|id| {
diagnostics
.get(*id)
.filter(|diagnostic| diagnostic.is_enabled)
}) {
debug!("{:#?}\n", diagnostic);
}
} else {
for diagnostic in diagnostics.iter() {
for diagnostic in diagnostics
.iter()
.filter(|diagnostic| diagnostic.is_enabled)
{
debug!("{:#?}\n", diagnostic);
}
}
Expand Down
2 changes: 1 addition & 1 deletion examples/diagnostics/custom_diagnostic.rs
Original file line number Diff line number Diff line change
Expand Up @@ -33,5 +33,5 @@ fn setup_diagnostic_system(mut diagnostics: ResMut<Diagnostics>) {

fn my_system(mut diagnostics: ResMut<Diagnostics>) {
// Add a measurement of 10.0 for our diagnostic each time this system runs.
diagnostics.add_measurement(SYSTEM_ITERATION_COUNT, 10.0);
diagnostics.add_measurement(SYSTEM_ITERATION_COUNT, || 10.0);
}