From 40bbbbb34e55b940550185d1fe46788f62f66ccd Mon Sep 17 00:00:00 2001 From: Daniel Chia Date: Mon, 13 Feb 2023 18:20:27 +0000 Subject: [PATCH] Introduce detailed_trace macro, use in TrackedRenderPass (#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 #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 --- Cargo.toml | 4 ++ crates/bevy_internal/Cargo.toml | 1 + .../src/render_phase/draw_state.rs | 48 +++++++++---------- crates/bevy_utils/Cargo.toml | 3 ++ crates/bevy_utils/src/lib.rs | 10 ++++ 5 files changed, 42 insertions(+), 24 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index f3228c4a1e..bcd8f51acd 100644 --- a/Cargo.toml +++ b/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 } diff --git a/crates/bevy_internal/Cargo.toml b/crates/bevy_internal/Cargo.toml index 238956006f..24f7d95458 100644 --- a/crates/bevy_internal/Cargo.toml +++ b/crates/bevy_internal/Cargo.toml @@ -23,6 +23,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"] diff --git a/crates/bevy_render/src/render_phase/draw_state.rs b/crates/bevy_render/src/render_phase/draw_state.rs index f228e46ef2..c9fcc1e77b 100644 --- a/crates/bevy_render/src/render_phase/draw_state.rs +++ b/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,7 +151,7 @@ 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, @@ -159,7 +159,7 @@ impl<'a> TrackedRenderPass<'a> { ); return; } - trace!( + detailed_trace!( "set bind_group {}: {:?} ({:?})", index, bind_group, @@ -188,7 +188,7 @@ 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(), @@ -196,7 +196,7 @@ impl<'a> TrackedRenderPass<'a> { ); 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, instances: Range) { - 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, base_vertex: i32, instances: Range) { - 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,7 +477,7 @@ 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); } @@ -485,7 +485,7 @@ impl<'a> TrackedRenderPass<'a> { /// /// 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); } @@ -493,7 +493,7 @@ impl<'a> TrackedRenderPass<'a> { /// /// `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,7 +587,7 @@ 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(); } @@ -595,7 +595,7 @@ impl<'a> TrackedRenderPass<'a> { /// /// 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)); } } diff --git a/crates/bevy_utils/Cargo.toml b/crates/bevy_utils/Cargo.toml index 5a019dbc38..07a7a7ae9f 100644 --- a/crates/bevy_utils/Cargo.toml +++ b/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"] } diff --git a/crates/bevy_utils/src/lib.rs b/crates/bevy_utils/src/lib.rs index 3ac1468973..e8ce5bdd84 100644 --- a/crates/bevy_utils/src/lib.rs +++ b/crates/bevy_utils/src/lib.rs @@ -292,3 +292,13 @@ impl Drop for OnDrop { 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)*); + } + } +}