Introduce detailed_trace macro, use in TrackedRenderPass (bevyengine#7639)

Profiles show that in extremely hot loops, like the draw loops in the renderer, invoking the trace! macro has noticeable overhead, even if the trace log level is not enabled.

Solve this by introduce a 'wrapper' detailed_trace macro around trace, that wraps the trace! log statement in a trivially false if statement unless a cargo feature is enabled

# Objective

- Eliminate significant overhead observed with trace-level logging in render hot loops, even when trace log level is not enabled.
- This is an alternative solution to the one proposed in bevyengine#7223 

## Solution

- Introduce a wrapper around the `trace!` macro called `detailed_trace!`. This macro wraps the `trace!` macro with an if statement that is conditional on a new cargo feature, `detailed_trace`. When the feature is not enabled (the default), then the if statement is trivially false and should be optimized away at compile time.
- Convert the observed hot occurrences of trace logging in `TrackedRenderPass` with this new macro.

Testing the results of 

```
cargo run --profile stress-test --features bevy/trace_tracy --example many_cubes -- spheres
```

![image](https://user-images.githubusercontent.com/1222141/218298552-38551717-b062-4c64-afdc-a60267ac984d.png)

shows significant improvement of the `main_opaque_pass_3d`  of the renderer, a median time decrease from 6.0ms to 3.5ms. 

---

## Changelog

- For performance reasons, some detailed renderer trace logs now require the use of cargo feature `detailed_trace` in addition to setting the log level to `TRACE` in order to be shown.

## Migration Guide

- Some detailed bevy trace events now require the use of the cargo feature `detailed_trace` in addition to enabling `TRACE` level logging to view. Should you wish to see these logs, please compile your code with the bevy feature `detailed_trace`. Currently, the only logs that are affected are the renderer logs pertaining to `TrackedRenderPass` functions

Author: danchia

Cargo.toml

@@ -121,6 +121,10 @@ animation = ["bevy_internal/animation"]
 # Enable using a shared stdlib for cxx on Android.
 android_shared_stdcxx = ["bevy_internal/android_shared_stdcxx"]
 
+# Enable detailed trace event logging.
+# These trace events are expensive even when off, thus they require compile time opt-in.
+detailed_trace = ["bevy_internal/detailed_trace"]
+
 [dependencies]
 bevy_dylib = { path = "crates/bevy_dylib", version = "0.9.0", default-features = false, optional = true }
 bevy_internal = { path = "crates/bevy_internal", version = "0.9.0", default-features = false }

crates/bevy_internal/Cargo.toml

@@ -24,6 +24,7 @@ trace_chrome = [ "bevy_log/tracing-chrome" ]
 trace_tracy = ["bevy_render?/tracing-tracy", "bevy_log/tracing-tracy" ]
 wgpu_trace = ["bevy_render/wgpu_trace"]
 debug_asset_server = ["bevy_asset/debug_asset_server"]
+detailed_trace = ["bevy_utils/detailed_trace"]
 
 # Image format support for texture loading (PNG and HDR are enabled by default)
 hdr = ["bevy_render/hdr"]

crates/bevy_render/src/render_phase/draw_state.rs

@@ -7,7 +7,7 @@ use crate::{
     },
     renderer::RenderDevice,
 };
-use bevy_utils::{default, tracing::trace};
+use bevy_utils::{default, detailed_trace};
 use std::ops::Range;
 use wgpu::{IndexFormat, RenderPass};
 use wgpu_hal::{MAX_BIND_GROUPS, MAX_VERTEX_BUFFERS};
@@ -126,7 +126,7 @@ impl<'a> TrackedRenderPass<'a> {
     ///
     /// Subsequent draw calls will exhibit the behavior defined by the `pipeline`.
     pub fn set_render_pipeline(&mut self, pipeline: &'a RenderPipeline) {
-        trace!("set pipeline: {:?}", pipeline);
+        detailed_trace!("set pipeline: {:?}", pipeline);
         if self.state.is_pipeline_set(pipeline.id()) {
             return;
         }
@@ -151,15 +151,15 @@ impl<'a> TrackedRenderPass<'a> {
             .state
             .is_bind_group_set(index, bind_group.id(), dynamic_uniform_indices)
         {
-            trace!(
+            detailed_trace!(
                 "set bind_group {} (already set): {:?} ({:?})",
                 index,
                 bind_group,
                 dynamic_uniform_indices
             );
             return;
         }
-        trace!(
+        detailed_trace!(
             "set bind_group {}: {:?} ({:?})",
             index,
             bind_group,
@@ -188,15 +188,15 @@ impl<'a> TrackedRenderPass<'a> {
             .state
             .is_vertex_buffer_set(slot_index, buffer_slice.id(), offset)
         {
-            trace!(
+            detailed_trace!(
                 "set vertex buffer {} (already set): {:?} ({})",
                 slot_index,
                 buffer_slice.id(),
                 offset
             );
             return;
         }
-        trace!(
+        detailed_trace!(
             "set vertex buffer {}: {:?} ({})",
             slot_index,
             buffer_slice.id(),
@@ -223,14 +223,14 @@ impl<'a> TrackedRenderPass<'a> {
             .state
             .is_index_buffer_set(buffer_slice.id(), offset, index_format)
         {
-            trace!(
+            detailed_trace!(
                 "set index buffer (already set): {:?} ({})",
                 buffer_slice.id(),
                 offset
             );
             return;
         }
-        trace!("set index buffer: {:?} ({})", buffer_slice.id(), offset);
+        detailed_trace!("set index buffer: {:?} ({})", buffer_slice.id(), offset);
         self.pass.set_index_buffer(*buffer_slice, index_format);
         self.state
             .set_index_buffer(buffer_slice.id(), offset, index_format);
@@ -240,7 +240,7 @@ impl<'a> TrackedRenderPass<'a> {
     ///
     /// The active vertex buffer(s) can be set with [`TrackedRenderPass::set_vertex_buffer`].
     pub fn draw(&mut self, vertices: Range<u32>, instances: Range<u32>) {
-        trace!("draw: {:?} {:?}", vertices, instances);
+        detailed_trace!("draw: {:?} {:?}", vertices, instances);
         self.pass.draw(vertices, instances);
     }
 
@@ -249,7 +249,7 @@ impl<'a> TrackedRenderPass<'a> {
     /// The active index buffer can be set with [`TrackedRenderPass::set_index_buffer`], while the
     /// active vertex buffer(s) can be set with [`TrackedRenderPass::set_vertex_buffer`].
     pub fn draw_indexed(&mut self, indices: Range<u32>, base_vertex: i32, instances: Range<u32>) {
-        trace!(
+        detailed_trace!(
             "draw indexed: {:?} {} {:?}",
             indices,
             base_vertex,
@@ -276,7 +276,7 @@ impl<'a> TrackedRenderPass<'a> {
     /// }
     /// ```
     pub fn draw_indirect(&mut self, indirect_buffer: &'a Buffer, indirect_offset: u64) {
-        trace!("draw indirect: {:?} {}", indirect_buffer, indirect_offset);
+        detailed_trace!("draw indirect: {:?} {}", indirect_buffer, indirect_offset);
         self.pass.draw_indirect(indirect_buffer, indirect_offset);
     }
 
@@ -300,7 +300,7 @@ impl<'a> TrackedRenderPass<'a> {
     /// }
     /// ```
     pub fn draw_indexed_indirect(&mut self, indirect_buffer: &'a Buffer, indirect_offset: u64) {
-        trace!(
+        detailed_trace!(
             "draw indexed indirect: {:?} {}",
             indirect_buffer,
             indirect_offset
@@ -332,7 +332,7 @@ impl<'a> TrackedRenderPass<'a> {
         indirect_offset: u64,
         count: u32,
     ) {
-        trace!(
+        detailed_trace!(
             "multi draw indirect: {:?} {}, {}x",
             indirect_buffer,
             indirect_offset,
@@ -372,7 +372,7 @@ impl<'a> TrackedRenderPass<'a> {
         count_offset: u64,
         max_count: u32,
     ) {
-        trace!(
+        detailed_trace!(
             "multi draw indirect count: {:?} {}, ({:?} {})x, max {}x",
             indirect_buffer,
             indirect_offset,
@@ -414,7 +414,7 @@ impl<'a> TrackedRenderPass<'a> {
         indirect_offset: u64,
         count: u32,
     ) {
-        trace!(
+        detailed_trace!(
             "multi draw indexed indirect: {:?} {}, {}x",
             indirect_buffer,
             indirect_offset,
@@ -456,7 +456,7 @@ impl<'a> TrackedRenderPass<'a> {
         count_offset: u64,
         max_count: u32,
     ) {
-        trace!(
+        detailed_trace!(
             "multi draw indexed indirect count: {:?} {}, ({:?} {})x, max {}x",
             indirect_buffer,
             indirect_offset,
@@ -477,23 +477,23 @@ impl<'a> TrackedRenderPass<'a> {
     ///
     /// Subsequent stencil tests will test against this value.
     pub fn set_stencil_reference(&mut self, reference: u32) {
-        trace!("set stencil reference: {}", reference);
+        detailed_trace!("set stencil reference: {}", reference);
         self.pass.set_stencil_reference(reference);
     }
 
     /// Sets the scissor region.
     ///
     /// Subsequent draw calls will discard any fragments that fall outside this region.
     pub fn set_scissor_rect(&mut self, x: u32, y: u32, width: u32, height: u32) {
-        trace!("set_scissor_rect: {} {} {} {}", x, y, width, height);
+        detailed_trace!("set_scissor_rect: {} {} {} {}", x, y, width, height);
         self.pass.set_scissor_rect(x, y, width, height);
     }
 
     /// Set push constant data.
     ///
     /// `Features::PUSH_CONSTANTS` must be enabled on the device in order to call these functions.
     pub fn set_push_constants(&mut self, stages: ShaderStages, offset: u32, data: &[u8]) {
-        trace!(
+        detailed_trace!(
             "set push constants: {:?} offset: {} data.len: {}",
             stages,
             offset,
@@ -514,7 +514,7 @@ impl<'a> TrackedRenderPass<'a> {
         min_depth: f32,
         max_depth: f32,
     ) {
-        trace!(
+        detailed_trace!(
             "set viewport: {} {} {} {} {} {}",
             x,
             y,
@@ -545,7 +545,7 @@ impl<'a> TrackedRenderPass<'a> {
     ///
     /// This is a GPU debugging feature. This has no effect on the rendering itself.
     pub fn insert_debug_marker(&mut self, label: &str) {
-        trace!("insert debug marker: {}", label);
+        detailed_trace!("insert debug marker: {}", label);
         self.pass.insert_debug_marker(label);
     }
 
@@ -570,7 +570,7 @@ impl<'a> TrackedRenderPass<'a> {
     /// [`push_debug_group`]: TrackedRenderPass::push_debug_group
     /// [`pop_debug_group`]: TrackedRenderPass::pop_debug_group
     pub fn push_debug_group(&mut self, label: &str) {
-        trace!("push_debug_group marker: {}", label);
+        detailed_trace!("push_debug_group marker: {}", label);
         self.pass.push_debug_group(label);
     }
 
@@ -587,15 +587,15 @@ impl<'a> TrackedRenderPass<'a> {
     /// [`push_debug_group`]: TrackedRenderPass::push_debug_group
     /// [`pop_debug_group`]: TrackedRenderPass::pop_debug_group
     pub fn pop_debug_group(&mut self) {
-        trace!("pop_debug_group");
+        detailed_trace!("pop_debug_group");
         self.pass.pop_debug_group();
     }
 
     /// Sets the blend color as used by some of the blending modes.
     ///
     /// Subsequent blending tests will test against this value.
     pub fn set_blend_constant(&mut self, color: Color) {
-        trace!("set blend constant: {:?}", color);
+        detailed_trace!("set blend constant: {:?}", color);
         self.pass.set_blend_constant(wgpu::Color::from(color));
     }
 }

crates/bevy_utils/Cargo.toml

@@ -8,6 +8,9 @@ repository = "https://github.com/bevyengine/bevy"
 license = "MIT OR Apache-2.0"
 keywords = ["bevy"]
 
+[features]
+detailed_trace = []
+
 [dependencies]
 ahash = "0.7.0"
 tracing = { version = "0.1", default-features = false, features = ["std"] }

crates/bevy_utils/src/lib.rs

@@ -292,3 +292,13 @@ impl<F: FnOnce()> Drop for OnDrop<F> {
         callback();
     }
 }
+
+/// Like [`tracing::trace`], but conditional on cargo feature `detailed_trace`.
+#[macro_export]
+macro_rules! detailed_trace {
+    ($($tts:tt)*) => {
+        if cfg!(detailed_trace) {
+            bevy_utils::tracing::trace!($($tts)*);
+        }
+    }
+}