From da6c2fb04e59ad6fb2c0d6048ea162828d80d47d Mon Sep 17 00:00:00 2001 From: Daniel Chia Date: Sat, 11 Feb 2023 22:51:37 -0800 Subject: [PATCH] introduce detailed_trace macro, use in TrackedRenderPass 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 --- 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 266831b4af5f2..0a33f87baba3b 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 238956006f11d..24f7d954584ea 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 f228e46ef2690..c9fcc1e77b33a 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 5a019dbc38455..07a7a7ae9f409 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 3ac14689731f5..e8ce5bdd84d76 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)*); + } + } +}