Introduction
About
I have recently been making a game using the bevy engine. Along the way I have been helped by community with many issues I have encountered both within the broader Rust Community as well as the Bevy community.
Structure
As I have spent more time working with Rust, I have moved from using println! to using the tracing crate for logging. My Objectives are to
- Describe the transition from basic methods to more advanced tools.
- Explain the reasons that prompted this change in practice.
Motivation
A common slogan with Rust is "if it compiles it usually works", however I have found this is not as much the case with Bevy.
While Rust's compile-time checks catch many errors, Bevy's ECS can introduce runtime issues:
- Queries breaking due to component changes
- Systems running in an unexpected order
Advanced logging and tracing help catch these issues earlier and provide more context for debugging.
I hope to help the reader fix issues with their games quicker and give something back to the community.
The documentation around Tracing is overwhelming for me and talks a lot about async which I have not used.
What this book is not
This book will not talk about debugging tools beyond logging.
Please note this document is not an official document of bevy's
Referenced code can be found here Or you could follow along on your own project.
Completion state
This book is in a state of generally good enough for my game development. I prefer to stay on track with my game rather then add to this book, therefore unless others contribute, updates will appear as they are useful to me.
Println! and eprintln
Println!
The first tool which you may reach for when you experience unexpected behaviour is println!.
println! can be used, as the name suggests, to print values at key points of your program where your issue might lie.
However
- Typing, or more likely copying and pasting
println!'s everywhere gets quite tedious. - Each
println!should, in most cases, have some marking string that lets you know which one triggered, otherwise you have to do additional searching. - At some point, these
println!'s need to be removed, or they will block up the logging.
Redirecting output to a file
You may already know stdout can be redirected to a file using the > operator.
When there is a lot of logging, the screen can fill quickly, so redirecting can help
you manage all that information.
An example below.
Cargo run > output.txt
This gives you two major benefits
- You can search in the file
- you can use a diff program 1 to compare outputs for different executions
Lots of text editors and IDE's have a built-in diff editor. Alternatively, I use Delta.
Dbg macro
The dbg! macro introduced in version 1.32 is pretty much a println! made for debugging.
An example from the official docs page
let a = 2;
let b = dbg!(a * 2) + 1;
// ^-- prints: [src/main.rs:2:9] a * 2 = 4
assert_eq!(b, 5);Notice that the file path and line numbers are printed. This metadata is generated at compile time, so it will keep up with changes made in your program.
This means it is less essential to make your dbg statements unique.
However, there are still some disadvantages (same as println!)
- Typing or more likely copying and pasting
dbg!'s everywhere gets quite tedious - At some point these
dbg!'s need to removed or they will block up the logging
The log Plugin
One of Bevy's default plugins is the log plugin.
Let's configure the plugin, then explain as we see what happens
fn main() {
App::new()
.add_plugins(DefaultPlugins.set(LogPlugin {
filter: "".to_string(),
level: Level::TRACE,
..Default::default()
}))
.add_systems(Startup, setup)
.run();
}
// The rest of the code...Code can also be found here.
use bevy::{log::LogPlugin, prelude::*};
use rand::prelude::*;
use tracing::Level;
//main snip
fn setup(
mut commands: Commands,
mut meshes: ResMut<Assets<Mesh>>,
mut materials: ResMut<Assets<StandardMaterial>>,
) {
// Camera
commands.spawn(Camera3dBundle {
transform: Transform::from_xyz(0.0, 50.0, 100.0).looking_at(Vec3::ZERO, Vec3::Y),
..default()
});
// Light
commands.spawn(PointLightBundle {
point_light: PointLight {
intensity: 1500.0,
shadows_enabled: true,
..default()
},
transform: Transform::from_xyz(4.0, 8.0, 4.0),
..default()
});
let mut rng = rand::thread_rng();
// Create spiral galaxy
for i in 0..10000 {
let t = i as f32 * 0.005;
let r = 20.0 * t.sqrt();
let theta = t * 2.5;
let x = r * theta.cos();
let z = r * theta.sin();
let y = (rng.gen::<f32>() - 0.5) * 2.0; // Add some vertical spread
let size = (0.05 + rng.gen::<f32>() * 0.1) * (1.0 - t / 50.0); // Smaller stars towards the edge
let brightness = 1.0 - t / 50.0; // Dimmer stars towards the edge
let color = Color::srgb(brightness, brightness * 0.8 + 0.2, brightness * 0.6 + 0.4);
let emissive = Color::srgb(
brightness * 5.0,
(brightness * 0.8 + 0.2) * 5.0,
(brightness * 0.6 + 0.4) * 5.0,
);
commands.spawn(PbrBundle {
mesh: meshes.add(Mesh::from(Sphere { radius: size })),
material: materials.add(StandardMaterial {
base_color: color,
emissive: emissive.into(), // Make stars glow
..default()
}),
transform: Transform::from_xyz(x, y, z),
..default()
});
}
}
Run the code and see what happens.
//snip
2024-10-19T21:46:13.389733Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(1573,1,vk)
2024-10-19T21:46:13.389739Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389745Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389751Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389757Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389763Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389769Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(6992,1,vk)
2024-10-19T21:46:13.389774Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(3085,1,vk)
2024-10-19T21:46:13.389780Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389786Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389792Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389801Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389807Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389813Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(8504,1,vk)
2024-10-19T21:46:13.389818Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(4597,1,vk)
2024-10-19T21:46:13.389824Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(690,1,vk)
2024-10-19T21:46:13.389830Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389836Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389842Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389848Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389854Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389860Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389866Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(6109,1,vk)
2024-10-19T21:46:13.389872Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) Id(2202,1,vk)
2024-10-19T21:46:13.389877Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389883Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
2024-10-19T21:46:13.389889Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Vertex Buffer"
2024-10-19T21:46:13.389895Z TRACE wgpu_core::resource: Destroy raw Buffer (dropped) "Mesh Index Buffer"
The console is absolutely flooded with debug messages from the Bevy engine itself, along with its dependencies. Libraries use a similar logging scheme to what is about to be shown below. The idea is that you can filter out the irrelevant logs. In order to start filtering, we need to learn about levels and the Env filter.
Log Levels
Tracing (The default Log plugin used for most Bevy Supported platforms with the major exceptions of the web and mobile) has the below log levels from highest (most detailed) to lowest (most important)
Trace(Not printed by default)Debug(Not printed by default)Info(default level that is printed)WarnErrorNone(you turned off logging)
It's up to you what these mean exactly, but here is how I use them in Bevy.
Tracedetails inside a loopDebugstart or end of loopsInfousually what I am working on currently, I then set it to either debug or trace. I also use this for information I want to display but haven't built the UI for yetWarnI never useErrorlet else fail when I don't expect it to
Lower levels are more important, while higher levels (by convention, not enforcement!) are more verbose.
For example, at the default level Info the levels below Warn and Error will also print.
Extract from the Tracing library
use tracing_core::Level;
assert!(Level::TRACE > Level::DEBUG);
assert!(Level::ERROR < Level::WARN);
assert!(Level::INFO <= Level::DEBUG);
assert_eq!(Level::TRACE, Level::TRACE);Env Filter
An env filter is used to put specific filters per target, span and fields. For now just equate targets with modules.
Spans will be discussed later.
I have not needed fields, until I use them or someone else supplies an example fields are an excercise for the reader.
To start with let's put a global env filter set all to warn, this can give you useful messages such as a UI-node without an appropriate parent node
fn main() {
App::new()
.add_plugins(DefaultPlugins.set(LogPlugin {
filter: "warn".to_string(),
level: Level::TRACE,
..Default::default()
}))
.add_systems(Startup, setup)
.run();
}The output in full is
Running `target/debug/test_spiral`
2024-10-19T22:03:13.935127Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:03:13.944920Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:03:13.944940Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x57584e197e60, name: ?)
2024-10-19T22:03:13.952153Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:03:13.952167Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
The level field
The level field in the log plugin is a quick way to set all logs globally. A major use case is having release and debug modes with different log levels.
Adding our own logging
Ok, so let's add in our own startup warning message, warning because only they and errors will show.
We can print a Warn message using Tracing's supplied macros
fn setup(
mut commands: Commands,
mut meshes: ResMut<Assets<Mesh>>,
mut materials: ResMut<Assets<StandardMaterial>>,
) {
warn!("Hello Log");
// Camera
commands.spawn(Camera3dBundle {
transform: Transform::from_xyz(0.0, 50.0, 100.0).looking_at(Vec3::ZERO, Vec3::Y),
..default()
});
The output is
Running `target/debug/test_spiral`
2024-10-19T22:06:51.489315Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:06:51.499177Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:06:51.499190Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x61ce04f0ff20, name: ?)
2024-10-19T22:06:51.506179Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:06:51.506193Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-19T22:06:52.007886Z WARN test_spiral: Hello Log
Great. We can put a message there, but it's not really a warning, so we can move it to the info level.
We use Tracing's info! macro
info!("Hello Log")
Now let's run
Running `target/debug/test_spiral`
2024-10-19T22:08:28.501325Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:08:28.511056Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:08:28.511070Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x63e8b387ee10, name: ?)
2024-10-19T22:08:28.518035Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:08:28.518049Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
Perhaps unsurprisingly, The message did not appear as it is at a higher level than warning.
Therefore, our settings have declared this to be too verbose.
Higher level logging for our application
First, let's add the depenencies
cargo add tracing
cargo add tracing-subscriber
In order to show our applications logging, we need to change the env filter to show our applications at the info level or above.
The syntax introduced will be to change targets
cratename::modulename
I called my example crate test_spiral
So, the target we supply to the env filter will be test_spiral. Since there is no module name, it is left blank.
Env filters are comma separated so warn,test_spiral=info will mean "run warn level for as normal, for module test_spiral info"
fn main() {
App::new()
//Disable the defaults
.add_plugins(DefaultPlugins.set(LogPlugin {
filter: "warn,test_spiral=info".to_string(),
level: Level::TRACE,
..Default::default()
}))
.add_systems(Startup, setup)
.run();
}Let's run
Running `target/debug/test_spiral`
2024-10-19T22:12:21.298476Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:12:21.307716Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:12:21.307730Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x57003740c3c0, name: ?)
2024-10-19T22:12:21.314793Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:12:21.314807Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-19T22:12:21.812880Z INFO test_spiral: Hello Log
Excellent
Module
We are going to make a second module we will keep it in the same file for simplicity but it will work for separate files
use bevy::{log::LogPlugin, prelude::*};
use rand::prelude::*;
use tracing::Level;
fn main() {
App::new()
.add_plugins(DefaultPlugins.set(LogPlugin {
filter: "warn,test_spiral=info".to_string(),
level: Level::TRACE,
..Default::default()
}))
.add_systems(Startup, setup)
.add_systems(Startup, spammy::print_trash)
.run();
}
fn setup(
mut commands: Commands,
mut meshes: ResMut<Assets<Mesh>>,
mut materials: ResMut<Assets<StandardMaterial>>,
) {
info!("Hello Log");
// Camera
commands.spawn(Camera3dBundle {
transform: Transform::from_xyz(0.0, 50.0, 100.0).looking_at(Vec3::ZERO, Vec3::Y),
..default()
});
// Light
commands.spawn(PointLightBundle {
point_light: PointLight {
intensity: 1500.0,
shadows_enabled: true,
..default()
},
transform: Transform::from_xyz(4.0, 8.0, 4.0),
..default()
});
let mut rng = rand::thread_rng();
// Create spiral galaxy
for i in 0..10000 {
let t = i as f32 * 0.005;
let r = 20.0 * t.sqrt();
let theta = t * 2.5;
let x = r * theta.cos();
let z = r * theta.sin();
let y = (rng.gen::<f32>() - 0.5) * 2.0; // Add some vertical spread
let size = (0.05 + rng.gen::<f32>() * 0.1) * (1.0 - t / 50.0); // Smaller stars towards the edge
let brightness = 1.0 - t / 50.0; // Dimmer stars towards the edge
let color = Color::srgb(brightness, brightness * 0.8 + 0.2, brightness * 0.6 + 0.4);
let emissive = Color::srgb(
brightness * 5.0,
(brightness * 0.8 + 0.2) * 5.0,
(brightness * 0.6 + 0.4) * 5.0,
);
commands.spawn(PbrBundle {
mesh: meshes.add(Mesh::from(Sphere { radius: size })),
material: materials.add(StandardMaterial {
base_color: color,
emissive: emissive.into(), // Make stars glow
..default()
}),
transform: Transform::from_xyz(x, y, z),
..default()
});
}
}
mod spammy {
use tracing::{debug, trace};
pub fn print_trash() {
debug!("I am going to print trash");
for i in 0..10 {
trace!(?i);
}
}
}?i just means use debug of that variable to print. Otherwise you can use the macros the same way as println!
Let's first change the log level for our application to be at trace
filter: "warn,test_spiral=trace".to_string(),now run
Running `target/debug/test_spiral`
2024-10-19T22:24:05.510403Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:24:05.520203Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:24:05.520217Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x59c6f223c5c0, name: ?)
2024-10-19T22:24:05.527234Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:24:05.527248Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-19T22:24:06.016182Z DEBUG test_spiral::spammy: I am going to print trash
2024-10-19T22:24:06.016204Z TRACE test_spiral::spammy: i=0
2024-10-19T22:24:06.016210Z TRACE test_spiral::spammy: i=1
2024-10-19T22:24:06.016206Z INFO test_spiral: Hello Log
2024-10-19T22:24:06.016215Z TRACE test_spiral::spammy: i=2
2024-10-19T22:24:06.016225Z TRACE test_spiral::spammy: i=3
2024-10-19T22:24:06.016230Z TRACE test_spiral::spammy: i=4
2024-10-19T22:24:06.016234Z TRACE test_spiral::spammy: i=5
2024-10-19T22:24:06.016238Z TRACE test_spiral::spammy: i=6
2024-10-19T22:24:06.016243Z TRACE test_spiral::spammy: i=7
2024-10-19T22:24:06.016247Z TRACE test_spiral::spammy: i=8
2024-10-19T22:24:06.016251Z TRACE test_spiral::spammy: i=9
In this case, you can see that the print_trash module ran before my setup code.
Also note that the crate module path was printed test_spiral::spammy. This will soon be relevant
Filter out by module
Clearly we have a problem with spammy. We could just delete the spammy logs like we would have to do with techniques in the previous chapter. However, for the sake of the excercie, let's pretend that we sometimes is useful.
Let's put in a log code so we cannot just change the application's logging levels
fn setup(
mut commands: Commands,
mut meshes: ResMut<Assets<Mesh>>,
mut materials: ResMut<Assets<StandardMaterial>>,
) {
info!("Hello Log");
debug!("Don't hide me");How do we just hide spammy's messages?
We do it like so, using the path that was printed test_spiral::spammy
filter: "warn,test_spiral=trace,test_spiral::spammy=info".to_string(),
Running `target/debug/test_spiral`
2024-10-19T22:32:16.697718Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:32:16.707200Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:32:16.707214Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x55916143c550, name: ?)
2024-10-19T22:32:16.714329Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:32:16.714344Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-19T22:32:17.218967Z INFO test_spiral: Hello Log
2024-10-19T22:32:17.218988Z DEBUG test_spiral: Don't hide me
If a log does not appear as I think it should, I usually just put it as an error and copy the path.
We can now selectively hide messages when we need to! This exciting idea is what lead me to learning more about the tracing crate.
But what about showing line numbers and extra details? This will be covered in the next chapter.
Introduction to Tracing
About Tracing
Tracing tracing is a framework for instrumenting Rust programs to collect structured, event-based diagnostic information."
Tracing is made for and often talked about in regards to asynchronous code, which is where a lot of documentation and discussion is addresses.
However, you don't need to use async code to benefit from this crate. I expect I will use this crate for every non-trivial program I write in Rust!
Why use Tracing
- Instead of deleting logs that you are not actively using, you can stop sending those logs until they are needed.
- You can log to multiple files by category
Next Steps from what we have learned
So far, we have learned about logging levels and filtering by module. Our next goal is to learn how to add more context to our logs.
instrument
instrument adds more context to your functions
use bevy::{log::LogPlugin, prelude::*};
use rand::prelude::*;
use tracing::Level;
fn main() {
App::new()
.add_plugins(DefaultPlugins.set(LogPlugin {
filter: "warn,test_spiral=trace,test_spiral::spammy=info".to_string(),
level: Level::TRACE,
..Default::default()
}))
.add_systems(Startup, setup)
.add_systems(Startup, spammy::print_trash)
.run();
}
fn setup(
mut commands: Commands,
mut meshes: ResMut<Assets<Mesh>>,
mut materials: ResMut<Assets<StandardMaterial>>,
) {
info!("Hello Log");
debug!("Don't hide me");
// Camera
commands.spawn(Camera3dBundle {
transform: Transform::from_xyz(0.0, 50.0, 100.0).looking_at(Vec3::ZERO, Vec3::Y),
..default()
});
// Light
commands.spawn(PointLightBundle {
point_light: PointLight {
intensity: 1500.0,
shadows_enabled: true,
..default()
},
transform: Transform::from_xyz(4.0, 8.0, 4.0),
..default()
});
let mut rng = rand::thread_rng();
// Create spiral galaxy
for i in 0..10000 {
let t = i as f32 * 0.005;
let r = 20.0 * t.sqrt();
let theta = t * 2.5;
let x = r * theta.cos();
let z = r * theta.sin();
let y = (rng.gen::<f32>() - 0.5) * 2.0; // Add some vertical spread
let size = (0.05 + rng.gen::<f32>() * 0.1) * (1.0 - t / 50.0); // Smaller stars towards the edge
let brightness = 1.0 - t / 50.0; // Dimmer stars towards the edge
let color = Color::srgb(brightness, brightness * 0.8 + 0.2, brightness * 0.6 + 0.4);
let emissive = Color::srgb(
brightness * 5.0,
(brightness * 0.8 + 0.2) * 5.0,
(brightness * 0.6 + 0.4) * 5.0,
);
commands.spawn(PbrBundle {
mesh: meshes.add(Mesh::from(Sphere { radius: size })),
material: materials.add(StandardMaterial {
base_color: color,
emissive: emissive.into(), // Make stars glow
..default()
}),
transform: Transform::from_xyz(x, y, z),
..default()
});
}
}
mod spammy {
use tracing::{debug, info, instrument, trace};
pub fn print_trash() {
debug!("I am going to print trash");
for i in 0..10 {
trace!(?i);
some_function(i);
}
}
#[instrument]
fn some_function(i: u8) {
if i == 3 {
info!("Fizz");
}
}
}Of particular note is instrument
#[instrument]
fn some_function(i: u8) {
if i == 3 {
info!("Fizz");
}
}Let's run
Running `target/debug/test_spiral`
2024-10-19T22:42:47.680435Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:42:47.690495Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:42:47.690509Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x56938d752410, name: ?)
2024-10-19T22:42:47.697443Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:42:47.697458Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-19T22:42:48.169391Z INFO test_spiral: Hello Log
2024-10-19T22:42:48.169411Z DEBUG test_spiral: Don't hide me
2024-10-19T22:42:48.169448Z INFO some_function{i=3}: test_spiral::spammy: Fizz
Notice that some_function is now printing along with its argument some more context.
We can skip the arguments using skip_all, which can be useful if some arguments don't implement Debug.
#[instrument(skip_all)]
I tend to use skip_all for all my systems as queries can be quite spammy.
If I, for example, create a system to query all transforms
.add_systems(Update, some_queries.run_if(run_once()))
#[instrument]
fn some_queries(transformers: Query<&Transform>) {
info!("not actually going to run");
}The output gets quite verbose per query.
Running `target/debug/test_spiral`
2024-10-19T22:49:03.036115Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T22:49:03.046122Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T22:49:03.046136Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x57ca2fa1e580, name: ?)
2024-10-19T22:49:03.053094Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T22:49:03.053108Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-19T22:49:03.537979Z INFO setup: test_spiral: Hello Log
2024-10-19T22:49:03.538003Z DEBUG setup: test_spiral: Don't hide me
2024-10-19T22:49:03.537998Z INFO some_function{i=3}: test_spiral::spammy: Fizz
2024-10-19T22:49:04.866039Z INFO some_queries{transformers=Query
{ matched_entities: 10002, state: QueryState { world_id: WorldId(0), matched_table_count: 3, matched_archetype_count: 3, .. },
last_run: Tick { tick: 1036800056 }, this_run: Tick { tick: 57 },
world: World { id: WorldId(0), entity_count: 10003, archetype_count: 8, component_count: 239, resource_count: 190 } }}:
test_spiral: not actually going to run
Note I added the line breaks to fit the margins
So let's add skip_all
#[instrument(skip_all)]
The output
Running `target/debug/test_spiral`
2024-10-21T08:12:11.871245Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-21T08:12:11.880725Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-21T08:12:11.880740Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x56a5fc78b4c0, name: ?)
2024-10-21T08:12:11.887924Z WARN wgpu_hal::gles::egl: No config found!
2024-10-21T08:12:11.887939Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-21T08:12:12.345086Z INFO test_spiral: Hello Log
2024-10-21T08:12:12.345107Z DEBUG test_spiral: Don't hide me
2024-10-21T08:12:12.345155Z INFO some_function{i=3}: test_spiral::spammy: Fizz
2024-10-21T08:12:13.653510Z INFO some_queries: test_spiral: not actually going to run
If you recall, an earlier section of the book says to equate targets with modules for now.
You can change that using arguments to instruments. This will not be demonstrated, however, as I have never had a need for it yet.
More about instruments here
Spans
I think of spans as tags, I don't have a lot of experience with them so this will be brief and incomplete.
My main use case for tags is grouping structually unrelated code that has a common theme such as timing or system type.
The examples for me are
- Startup systems
- Yearly or montly systems in my stratergy games
- Related ui or input handling
You can use as many spans as you want.
Now lets look at the syntax to use a span inside a fuction. You need code that looks like this
let span = span!(Level::DEBUG, "start");
let _guard = span.enter();Spans only apply when the logging level is set at it or above.
Note _guard is there to stop the variable being dropped immediately.
The underscore is to stop unused errors as its drop behaviour is what really makes it work!
While _guard is valid(undropped) the span is entered.
While span is valid the span is created.
There are shorthands for all logging levels, such as trace_span!
You cannot combine the span(/* snip*/).enter into one line as entering a span and creating
are distinct things. A span is only created once while a span can be entered many times.
Entering and exiting spans is stuff I don't have much idea about beyond the scope this tutorial(mostly async stuff).
Spans exit when the variable holding the enter is dropped in this example the _guard
spans close when the span variable is dropped.
We can use square brackets to filter by span
filter: "warn,test_spiral=trace,test_spiral::spammy=info,test_spiral[start]=trace"
Now for the entire code
use bevy::{log::LogPlugin, prelude::*};
use rand::prelude::*;
use tracing::{instrument, span, Level};
fn main() {
App::new()
.add_plugins(
DefaultPlugins.set(LogPlugin {
filter: "warn,test_spiral=debug,test_spiral::spammy=info,test_spiral[start]=trace"
.to_string(),
level: Level::TRACE,
..Default::default()
}),
)
.add_systems(Startup, setup)
.add_systems(Startup, spammy::print_trash)
.add_systems(Update, some_queries.run_if(run_once()))
.run();
}
#[instrument(skip_all)]
fn setup(
mut commands: Commands,
mut meshes: ResMut<Assets<Mesh>>,
mut materials: ResMut<Assets<StandardMaterial>>,
) {
let span = span!(Level::DEBUG, "start");
let _guard = span.enter();
info!("Hello Log");
debug!("Don't hide me");
// Camera
commands.spawn(Camera3dBundle {
transform: Transform::from_xyz(0.0, 50.0, 100.0).looking_at(Vec3::ZERO, Vec3::Y),
..default()
});
// Light
commands.spawn(PointLightBundle {
point_light: PointLight {
intensity: 1500.0,
shadows_enabled: true,
..default()
},
transform: Transform::from_xyz(4.0, 8.0, 4.0),
..default()
});
let mut rng = rand::thread_rng();
// Create spiral galaxy
for i in 0..10000 {
let t = i as f32 * 0.005;
let r = 20.0 * t.sqrt();
let theta = t * 2.5;
let x = r * theta.cos();
let z = r * theta.sin();
let y = (rng.gen::<f32>() - 0.5) * 2.0; // Add some vertical spread
let size = (0.05 + rng.gen::<f32>() * 0.1) * (1.0 - t / 50.0); // Smaller stars towards the edge
let brightness = 1.0 - t / 50.0; // Dimmer stars towards the edge
let color = Color::srgb(brightness, brightness * 0.8 + 0.2, brightness * 0.6 + 0.4);
let emissive = Color::srgb(
brightness * 5.0,
(brightness * 0.8 + 0.2) * 5.0,
(brightness * 0.6 + 0.4) * 5.0,
);
commands.spawn(PbrBundle {
mesh: meshes.add(Mesh::from(Sphere { radius: size })),
material: materials.add(StandardMaterial {
base_color: color,
emissive: emissive.into(), // Make stars glow
..default()
}),
transform: Transform::from_xyz(x, y, z),
..default()
});
}
}
#[instrument(skip_all)]
fn some_queries(transformers: Query<&Transform>) {
info!("not actually going to run");
trace!("shouldn't appear");
}
mod spammy {
use tracing::{debug, info, instrument, span, trace, Level};
pub fn print_trash() {
let span = span!(Level::DEBUG, "start");
let _guard = span.enter();
debug!("I am going to print trash");
for i in 0..10 {
trace!(?i);
some_function(i);
}
}
#[instrument]
fn some_function(i: u8) {
if i == 3 {
info!("Fizz");
}
}
}
The output
Running `target/debug/test_spiral`
2024-10-19T23:11:16.601564Z WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
2024-10-19T23:11:16.611283Z WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
2024-10-19T23:11:16.611297Z WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x5662f0635080, name: ?)
2024-10-19T23:11:16.618229Z WARN wgpu_hal::gles::egl: No config found!
2024-10-19T23:11:16.618243Z WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
2024-10-19T23:11:17.119600Z DEBUG start: test_spiral::spammy: I am going to print trash
2024-10-19T23:11:17.119605Z INFO setup:start: test_spiral: Hello Log
2024-10-19T23:11:17.119626Z TRACE start: test_spiral::spammy: i=0
2024-10-19T23:11:17.119633Z DEBUG setup:start: test_spiral: Don't hide me
2024-10-19T23:11:17.119652Z TRACE start: test_spiral::spammy: i=1
2024-10-19T23:11:17.119665Z TRACE start: test_spiral::spammy: i=2
2024-10-19T23:11:17.119678Z TRACE start: test_spiral::spammy: i=3
2024-10-19T23:11:17.119688Z INFO start:some_function{i=3}: test_spiral::spammy: Fizz
2024-10-19T23:11:17.119698Z TRACE start: test_spiral::spammy: i=4
2024-10-19T23:11:17.119711Z TRACE start: test_spiral::spammy: i=5
2024-10-19T23:11:17.119723Z TRACE start: test_spiral::spammy: i=6
2024-10-19T23:11:17.119736Z TRACE start: test_spiral::spammy: i=7
2024-10-19T23:11:17.119748Z TRACE start: test_spiral::spammy: i=8
2024-10-19T23:11:17.119760Z TRACE start: test_spiral::spammy: i=9
2024-10-19T23:11:18.441500Z INFO some_queries: test_spiral: not actually going to run
Using Tracing on its own
For the sake of learning we will disable the default plugin and use the tracing crate itself.
This also means you can use what you learned here on other applications using tracing.
Tracing uses a subscriber made up of layers (I don't really understand the details)
use bevy::{log::LogPlugin, prelude::*};
use rand::prelude::*;
use tracing::{instrument, span, Level};
fn main() {
tracing_subscriber::fmt().init();
App::new()
//Disable the defaults
.add_plugins(DefaultPlugins.build().disable::<LogPlugin>())
.add_systems(Startup, setup)
.add_systems(Startup, spammy::print_trash)
.add_systems(Update, some_queries.run_if(run_once()))
.run();
}Let's modify Tracing
tracing_subscriber::fmt()
.without_time()
.with_file(true)
.with_line_number(true)
.pretty()
.with_env_filter(
EnvFilter::from_str(
"warn,test_spiral=debug,test_spiral::spammy=info,test_spiral[start]=trace",
)
.unwrap(),
)
.init();
-
I find timestamp is spammy with diff files so thats why
without_timeis there. -
I mentioned that
dbg!had line numbers and file names,with_file(true),with_line_numbers(true). -
Pretty is useful for console, remove if you are redirecting to a txt file
Now, let's run
Running `target/debug/test_spiral`
WARN wgpu_hal::vulkan::instance: InstanceFlags::VALIDATION requested, but unable to find layer: VK_LAYER_KHRONOS_validation
at /home/lyndonm/.cargo/registry/src/index.crates.io-6f17d22bba15001f/wgpu-hal-0.21.1/src/vulkan/instance.rs:724
WARN wgpu_hal::vulkan::instance: GENERAL [Loader Message (0x0)]
terminator_CreateInstance: Failed to CreateInstance in ICD 4. Skipping ICD.
at /home/lyndonm/.cargo/registry/src/index.crates.io-6f17d22bba15001f/wgpu-hal-0.21.1/src/vulkan/instance.rs:89
WARN wgpu_hal::vulkan::instance: objects: (type: INSTANCE, hndl: 0x5fb6876377c0, name: ?)
at /home/lyndonm/.cargo/registry/src/index.crates.io-6f17d22bba15001f/wgpu-hal-0.21.1/src/vulkan/instance.rs:148
WARN wgpu_hal::gles::egl: No config found!
at /home/lyndonm/.cargo/registry/src/index.crates.io-6f17d22bba15001f/wgpu-hal-0.21.1/src/gles/egl.rs:269
WARN wgpu_hal::gles::egl: EGL says it can present to the window but not natively
at /home/lyndonm/.cargo/registry/src/index.crates.io-6f17d22bba15001f/wgpu-hal-0.21.1/src/gles/egl.rs:258
DEBUG test_spiral::spammy: I am going to print trash
at src/main.rs:107
in test_spiral::spammy::start
INFO test_spiral: Hello Log
at src/main.rs:40
in test_spiral::start
in test_spiral::setup
TRACE test_spiral::spammy: i: 0
at src/main.rs:109
in test_spiral::spammy::start
DEBUG test_spiral: Don't hide me
at src/main.rs:41
in test_spiral::start
in test_spiral::setup
TRACE test_spiral::spammy: i: 1
at src/main.rs:109
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 2
at src/main.rs:109
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 3
at src/main.rs:109
in test_spiral::spammy::start
INFO test_spiral::spammy: Fizz
at src/main.rs:116
in test_spiral::spammy::some_function with i: 3
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 4
at src/main.rs:109
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 5
at src/main.rs:109
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 6
at src/main.rs:109
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 7
at src/main.rs:109
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 8
at src/main.rs:109
in test_spiral::spammy::start
TRACE test_spiral::spammy: i: 9
at src/main.rs:109
in test_spiral::spammy::start
INFO test_spiral: not actually going to run
at src/main.rs:96
in test_spiral::some_queries
Line numbers and file names. You may be happy to just work on your game from this point. Next chapters is basically breaking Tracing up into layers so you can have multiple specialized files.
Tracing multiple files
Using our powers of span, we can "Tag" our logs to go to separate files per span. First, we need to learn about layers.
Subscribers
Subscribers carry many layers. I am not entirely sure about the definition of a subscriber, but I believe it's basically a consumer of tracing logs that decides how to output them. I have only used the one on the tracing crate, but there are other variations, such as tree logging.
Let's read the documentation "A subscriber is responsible for the following:
Registering new spans as they are created, and providing them with span IDs. Implicitly, this means the subscriber may determine the strategy for determining span equality.
Recording the attachment of field values and follows-from annotations to spans.
Filtering spans and events, and determining when those filters must be invalidated.
Observing spans as they are entered, exited, and closed, and events as they occur.
"
Layers
I will just start with an example.
let stdout_layer = tracing_subscriber::fmt::layer()
.with_line_number(true)
.with_file(true)
.without_time()
.pretty()
/* Put less important stuff info files */
.with_filter(EnvFilter::from_str("warn,test_spiral=info").unwrap());Layers do the presentation and filtering of data, in the example above this sends data to the standard output.
let log_file = File::create("logs/start.log").unwrap();
let start_layer = tracing_subscriber::fmt::layer()
.with_line_number(true)
.with_file(true)
.without_time()
.with_ansi(false)
.with_writer(Mutex::new(log_file))
.with_filter(EnvFilter::from_str("none,test_spiral::[start]=trace").unwrap());This above layer will send the file to a file by output log based on all spans that have start
we can add them as below, just above your main application,
//code for layers above
tracing_subscriber::registry()
.with(stdout_layer)
.with(start_layer)
.init();
App::new()
//Disable the defaults
.add_plugins(DefaultPlugins.build().disable::<LogPlugin>())
.add_systems(Startup, setup)
.add_systems(Startup, spammy::print_trash)
.add_systems(Update, some_queries.run_if(run_once()))
.run();
Putting layers in you default plugin
TODO: I am getting errors trying to do achieve this
I have got logging working as expected via previous techniques so this is not a high priority for me.
Other features I have thought of using
Filtering logs by value
Lets say an argument or a variable when set to a certain value is causing issues. I think you can use {field=value} with field being the variable name. I have not however tested this or used this yet.
Further Info
You have reached the limit of my undestanding with Tracing useful links below.
I had never heard of Tracing prior to this video. This video spends a lot more time covering the details especially around layers. It also covers async Jon Gjengset "decrusting" tracing
Design patterns
Log let else queries
The typical quick way when prototyping queries with only one expected item is to just use unwrap
However a slighter better option is to use let else statements.
lets start with an example
based on our code here.
use std::str::FromStr;
use bevy::{log::LogPlugin, prelude::*};
use rand::prelude::*;
fn main() {
App::new()
//Disable the defaults
.add_plugins(DefaultPlugins)
.add_systems(Startup, setup)
.add_systems(Startup, spammy::print_trash)
.add_systems(Update, some_queries.run_if(run_once()))
.add_systems(Update, query_light.run_if(run_once()))
.run();
}
fn setup(
mut commands: Commands,
mut meshes: ResMut<Assets<Mesh>>,
mut materials: ResMut<Assets<StandardMaterial>>,
) {
// Camera
commands.spawn(Camera3dBundle {
transform: Transform::from_xyz(0.0, 50.0, 100.0).looking_at(Vec3::ZERO, Vec3::Y),
..default()
});
// Light
// commands.spawn(PointLightBundle {
// point_light: PointLight {
// intensity: 1500.0,
// shadows_enabled: true,
// ..default()
// },
// transform: Transform::from_xyz(4.0, 8.0, 4.0),
// ..default()
// });
let mut rng = rand::thread_rng();
// Create spiral galaxy
for i in 0..10000 {
let t = i as f32 * 0.005;
let r = 20.0 * t.sqrt();
let theta = t * 2.5;
let x = r * theta.cos();
let z = r * theta.sin();
let y = (rng.gen::<f32>() - 0.5) * 2.0; // Add some vertical spread
let size = (0.05 + rng.gen::<f32>() * 0.1) * (1.0 - t / 50.0); // Smaller stars towards the edge
let brightness = 1.0 - t / 50.0; // Dimmer stars towards the edge
let color = Color::srgb(brightness, brightness * 0.8 + 0.2, brightness * 0.6 + 0.4);
let emissive = Color::srgb(
brightness * 5.0,
(brightness * 0.8 + 0.2) * 5.0,
(brightness * 0.6 + 0.4) * 5.0,
);
commands.spawn(PbrBundle {
mesh: meshes.add(Mesh::from(Sphere { radius: size })),
material: materials.add(StandardMaterial {
base_color: color,
emissive: emissive.into(), // Make stars glow
..default()
}),
transform: Transform::from_xyz(x, y, z),
..default()
});
}
}
fn some_queries(transformers: Query<&Transform>) {}
fn query_light(light_query: Query<&PointLight>) {
let light = light_query.get_single().unwrap();
info!("found the light");
}
mod spammy {
pub fn print_trash() {
for i in 0..10 {
some_function(i);
}
}
fn some_function(i: u8) {
if i == 3 {}
}
}A query has been added for the pointlight but it no longer is created we can see what happens
Running `target/debug/test_spiral`
2024-10-20T23:47:00.160263Z INFO bevy_diagnostic::system_information_diagnostics_plugin::internal: SystemInfo { os: "Linux 22.04 KDE neon", kernel: "6.8.0-45-generic", cpu: "AMD Ryzen 7 7800X3D 8-Core Processor", core_count: "8", memory: "30.5 GiB" }
2024-10-20T23:47:00.274629Z INFO bevy_render::renderer: AdapterInfo { name: "NVIDIA GeForce RTX 3070", vendor: 4318, device: 9348, device_type: DiscreteGpu, driver: "NVIDIA", driver_info: "535.183.01", backend: Vulkan }
2024-10-20T23:47:00.691667Z INFO bevy_winit::system: Creating new window "App" (Entity { index: 0, generation: 1 })
2024-10-20T23:47:00.692031Z INFO winit::platform_impl::linux::x11::window: Guessed window scale factor: 1
thread 'Compute Task Pool (3)' panicked at src/main.rs:77:42:
called `Result::unwrap()` on an `Err` value: NoEntities("bevy_ecs::query::state::QueryState<&bevy_pbr::light::point_light::PointLight>")
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Encountered a panic in system `test_spiral::query_light`!
Encountered a panic in system `bevy_app::main_schedule::Main::run_main`!
A crash its good we got the issue pointed out to us straight away but we could change the query_light function to be as below.
fn query_light(light_query: Query<&PointLight>) {
let light = light_query.get_single() else {
error!("no light found");
return;
};
info!("found the light");
}By stopping crashing but logging the issues we can keep the game going and possibly find multiple issues in one run.
Plus if the system is not that vital, we don't need to ruin the user's experience.
Running `target/debug/test_spiral`
2024-10-20T23:53:21.775972Z INFO bevy_diagnostic::system_information_diagnostics_plugin::internal: SystemInfo { os: "Linux 22.04 KDE neon", kernel: "6.8.0-45-generic", cpu: "AMD Ryzen 7 7800X3D 8-Core Processor", core_count: "8", memory: "30.5 GiB" }
2024-10-20T23:53:21.904099Z INFO bevy_render::renderer: AdapterInfo { name: "NVIDIA GeForce RTX 3070", vendor: 4318, device: 9348, device_type: DiscreteGpu, driver: "NVIDIA", driver_info: "535.183.01", backend: Vulkan }
2024-10-20T23:53:22.316914Z INFO bevy_winit::system: Creating new window "App" (Entity { index: 0, generation: 1 })
2024-10-20T23:53:22.317300Z INFO winit::platform_impl::linux::x11::window: Guessed window scale factor: 1
2024-10-20T23:53:23.645988Z INFO test_spiral: found the light
Prefer to use continue over return in loops otherwise one bad apple will destroy bunch
Other Subscribers
So far all that has been presented is the fmt subscriber for text output but Tracing can do more then that. Note I haven't needed to use multiple subscribers, so far I just change globabl subscriber and leave it at that.
Bunyan Subscriber
I don't know what bunyan the format is, just someone1 thought it was worth mentioning, who am I to disagree? bunyan
Gizmo Subscriber
Use to draw gizmos quickly, I have not yet used but I am likely to in future. I am interested in using Gizmos for debugging if I ever get to them, I will write about them.
My understanding of Gizmo's is
They are graphics drawn in immediate mode as opposed to retained;
Therefore they are not fast but can be use for marking places such as where your lights are, or testing rotations.
(Plans are for 0.16 to change this to retained, this is written just before 0.15)
Thanks to Discord user ThierryBerger
Performance
Disclaimer
I have not empirically measured any performance at all, so this is all a matter of if very obvious impacts. If I do measure it later I will update it.
Logging statements runtime ignored
I have not experienced any issues with just having lots of logging that is ignored at runtime. It is possible to set levels at compile time, I haven't yet got around to doing it (that is why there is no instructions yet). Tracing from what was said in Jon Gjensets video goes to great pains to minimise performance costs.
Logging multiple files.
Previous chapters discussed how its possible to have files throughly recording everything you can possibly care about; However I noticed massive performance gains just by commenting out the layers that print to the file.
Mitigating the perfomance issues.
TODO: Test if I can somehow make an IO logging thread in bevy work with tracing.
Contributing
I welcome all contributions to the book whether it is via a pull request or raising an issue.
Ideally it would come with an example using the test_spiral