From cb485f3798bf5c25676c6161310caa808ff6b570 Mon Sep 17 00:00:00 2001 From: Connor Fitzgerald Date: Fri, 24 Jul 2020 10:25:56 -0400 Subject: [PATCH] Convert all logging to tracing and add fmt logger --- Cargo.lock | 2 +- player/Cargo.toml | 2 +- player/src/bin/play.rs | 7 +- wgpu-core/Cargo.toml | 4 +- wgpu-core/src/command/allocator.rs | 10 +- wgpu-core/src/command/bind.rs | 6 +- wgpu-core/src/command/bundle.rs | 2 +- wgpu-core/src/command/compute.rs | 2 +- wgpu-core/src/command/mod.rs | 2 +- wgpu-core/src/command/render.rs | 4 +- wgpu-core/src/command/transfer.rs | 8 +- wgpu-core/src/device/life.rs | 22 +- wgpu-core/src/device/mod.rs | 48 ++--- wgpu-core/src/device/queue.rs | 10 +- wgpu-core/src/device/trace.rs | 4 +- wgpu-core/src/hub.rs | 2 +- wgpu-core/src/instance.rs | 16 +- wgpu-core/src/logging/subscriber.rs | 195 ++---------------- wgpu-core/src/logging/subscriber/chrome.rs | 170 +++++++++++++++ wgpu-core/src/logging/subscriber/fmt_layer.rs | 100 +++++++++ wgpu-core/src/resource.rs | 2 +- wgpu-core/src/track/mod.rs | 4 +- wgpu-core/src/validation.rs | 2 +- 23 files changed, 368 insertions(+), 256 deletions(-) create mode 100644 wgpu-core/src/logging/subscriber/chrome.rs create mode 100644 wgpu-core/src/logging/subscriber/fmt_layer.rs diff --git a/Cargo.lock b/Cargo.lock index 1d6dd9f3e8..5c0185e14c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1610,7 +1610,6 @@ dependencies = [ "gfx-descriptor", "gfx-hal", "gfx-memory", - "log", "loom", "naga", "parking_lot", @@ -1621,6 +1620,7 @@ dependencies = [ "thiserror", "thread-id", "tracing", + "tracing-log", "tracing-subscriber", "wgpu-types", ] diff --git a/player/Cargo.toml b/player/Cargo.toml index 6e625a7c9b..4d203a7338 100644 --- a/player/Cargo.toml +++ b/player/Cargo.toml @@ -32,7 +32,7 @@ features = ["replay"] path = "../wgpu-core" package = "wgpu-core" version = "0.5" -features = ["replay", "raw-window-handle"] +features = ["replay", "raw-window-handle", "subscriber"] [target.'cfg(all(unix, not(target_os = "ios"), not(target_os = "macos")))'.dependencies] gfx-backend-vulkan = { version = "0.5", features = ["x11"] } diff --git a/player/src/bin/play.rs b/player/src/bin/play.rs index 97a7b64f31..279681220c 100644 --- a/player/src/bin/play.rs +++ b/player/src/bin/play.rs @@ -17,7 +17,12 @@ fn main() { #[cfg(feature = "winit")] use winit::{event_loop::EventLoop, window::WindowBuilder}; - env_logger::init(); + wgc::logging::subscriber::initialize_default_subscriber( + std::env::var("WGPU_CHROME_TRACE") + .as_ref() + .map(Path::new) + .ok(), + ); #[cfg(feature = "renderdoc")] #[cfg_attr(feature = "winit", allow(unused))] diff --git a/wgpu-core/Cargo.toml b/wgpu-core/Cargo.toml index 2f64c13ba0..75ee794ff5 100644 --- a/wgpu-core/Cargo.toml +++ b/wgpu-core/Cargo.toml @@ -20,14 +20,13 @@ replay = ["serde", "wgt/replay"] # Enable serializable compute/render passes, and bundle encoders. serial-pass = ["serde", "wgt/serde", "arrayvec/serde"] # Enable chrome-tracing backend and default tracing subscriber -subscriber = ["thread-id", "tracing-subscriber"] +subscriber = ["thread-id", "tracing-log", "tracing-subscriber"] [dependencies] arrayvec = "0.5" bitflags = "1.0" copyless = "0.1" fxhash = "0.2" -log = "0.4" hal = { package = "gfx-hal", version = "0.5.3" } gfx-backend-empty = "0.5" parking_lot = "0.10" @@ -37,6 +36,7 @@ serde = { version = "1.0", features = ["serde_derive"], optional = true } smallvec = "1" thread-id = { version = "3", optional = true } tracing = { version = "0.1", default-features = false, features = ["std"] } +tracing-log = { version = "0.1", optional = true } tracing-subscriber = { version = "0.2", optional = true } thiserror = "1" diff --git a/wgpu-core/src/command/allocator.rs b/wgpu-core/src/command/allocator.rs index 21c71cd61b..4c922140cf 100644 --- a/wgpu-core/src/command/allocator.rs +++ b/wgpu-core/src/command/allocator.rs @@ -28,7 +28,7 @@ impl CommandPool { for i in (0..self.pending.len()).rev() { if self.pending[i].1 <= last_done_index { let (cmd_buf, index) = self.pending.swap_remove(i); - log::trace!( + tracing::trace!( "recycling comb submitted in {} when {} is last done", index, last_done_index, @@ -90,7 +90,7 @@ impl CommandAllocator { .entry(thread_id) .or_insert_with(|| CommandPool { raw: unsafe { - log::info!("Starting on thread {:?}", thread_id); + tracing::info!("Starting on thread {:?}", thread_id); device.create_command_pool( self.queue_family, hal::pool::CommandPoolCreateFlags::RESET_INDIVIDUAL, @@ -125,7 +125,7 @@ impl CommandAllocator { impl CommandAllocator { pub fn new(queue_family: hal::queue::QueueFamilyId, device: &B::Device) -> Self { let internal_thread_id = thread::current().id(); - log::info!("Starting on (internal) thread {:?}", internal_thread_id); + tracing::info!("Starting on (internal) thread {:?}", internal_thread_id); let mut pools = FastHashMap::default(); pools.insert( internal_thread_id, @@ -213,7 +213,7 @@ impl CommandAllocator { } } for thread_id in remove_threads { - log::info!("Removing from thread {:?}", thread_id); + tracing::info!("Removing from thread {:?}", thread_id); let mut pool = inner.pools.remove(&thread_id).unwrap(); unsafe { pool.raw.free(pool.available); @@ -229,7 +229,7 @@ impl CommandAllocator { pool.recycle(raw); } if pool.total != pool.available.len() { - log::error!( + tracing::error!( "Some command buffers are still recorded, only tracking {} / {}", pool.available.len(), pool.total diff --git a/wgpu-core/src/command/bind.rs b/wgpu-core/src/command/bind.rs index e53bae67c2..272c644b01 100644 --- a/wgpu-core/src/command/bind.rs +++ b/wgpu-core/src/command/bind.rs @@ -187,7 +187,7 @@ impl Binder { bind_group: &BindGroup, offsets: &[DynamicOffset], ) -> Option<(PipelineLayoutId, FollowUpIter<'a>)> { - log::trace!("\tBinding [{}] = group {:?}", index, bind_group_id); + tracing::trace!("\tBinding [{}] = group {:?}", index, bind_group_id); debug_assert_eq!(B::VARIANT, bind_group_id.backend()); match self.entries[index].provide(bind_group_id, bind_group, offsets) { @@ -200,7 +200,7 @@ impl Binder { } else { self.entries.len() }); - log::trace!("\t\tbinding up to {}", end); + tracing::trace!("\t\tbinding up to {}", end); Some(( self.pipeline_layout_id?, FollowUpIter { @@ -208,7 +208,7 @@ impl Binder { }, )) } else { - log::trace!("\t\tskipping above compatible {}", compatible_count); + tracing::trace!("\t\tskipping above compatible {}", compatible_count); None } } diff --git a/wgpu-core/src/command/bundle.rs b/wgpu-core/src/command/bundle.rs index 1d7fbb63dd..e23f7252ee 100644 --- a/wgpu-core/src/command/bundle.rs +++ b/wgpu-core/src/command/bundle.rs @@ -891,7 +891,7 @@ impl Global { } } - log::debug!("Render bundle {:?} = {:#?}", id_in, state.trackers); + tracing::debug!("Render bundle {:?} = {:#?}", id_in, state.trackers); let _ = desc.label; //TODO: actually use //TODO: check if the device is still alive RenderBundle { diff --git a/wgpu-core/src/command/compute.rs b/wgpu-core/src/command/compute.rs index 9c56c70686..f9985c7b5d 100644 --- a/wgpu-core/src/command/compute.rs +++ b/wgpu-core/src/command/compute.rs @@ -199,7 +199,7 @@ impl Global { .unwrap(); bind_group.validate_dynamic_bindings(offsets)?; - log::trace!( + tracing::trace!( "Encoding barriers on binding of {:?} to {:?}", bind_group_id, encoder_id diff --git a/wgpu-core/src/command/mod.rs b/wgpu-core/src/command/mod.rs index b650f639bd..c2f7c3e3e2 100644 --- a/wgpu-core/src/command/mod.rs +++ b/wgpu-core/src/command/mod.rs @@ -174,7 +174,7 @@ impl Global { .expect("Used swap chain frame has already presented"); comb.trackers.views.remove(view_id.value); } - log::trace!("Command buffer {:?} {:#?}", encoder_id, comb.trackers); + tracing::trace!("Command buffer {:?} {:#?}", encoder_id, comb.trackers); Ok(encoder_id) } diff --git a/wgpu-core/src/command/render.rs b/wgpu-core/src/command/render.rs index e184a06247..b28516a7e4 100644 --- a/wgpu-core/src/command/render.rs +++ b/wgpu-core/src/command/render.rs @@ -573,7 +573,7 @@ impl Global { return Err(RenderPassError::InvalidSampleCount(sample_count)); } - log::trace!( + tracing::trace!( "Encoding render pass begin in command buffer {:?}", encoder_id ); @@ -1584,7 +1584,7 @@ impl Global { } } - log::trace!("Merging {:?} with the render pass", encoder_id); + tracing::trace!("Merging {:?} with the render pass", encoder_id); unsafe { raw.end_render_pass(); } diff --git a/wgpu-core/src/command/transfer.rs b/wgpu-core/src/command/transfer.rs index a0c31edcf9..1c83bca9cc 100644 --- a/wgpu-core/src/command/transfer.rs +++ b/wgpu-core/src/command/transfer.rs @@ -245,7 +245,7 @@ impl Global { } if size == 0 { - log::trace!("Ignoring copy_buffer_to_buffer of size 0"); + tracing::trace!("Ignoring copy_buffer_to_buffer of size 0"); return Ok(()); } @@ -332,7 +332,7 @@ impl Global { } if copy_size.width == 0 || copy_size.height == 0 || copy_size.width == 0 { - log::trace!("Ignoring copy_buffer_to_texture of size 0"); + tracing::trace!("Ignoring copy_buffer_to_texture of size 0"); return Ok(()); } @@ -432,7 +432,7 @@ impl Global { } if copy_size.width == 0 || copy_size.height == 0 || copy_size.width == 0 { - log::trace!("Ignoring copy_texture_to_buffer of size 0"); + tracing::trace!("Ignoring copy_texture_to_buffer of size 0"); return Ok(()); } @@ -541,7 +541,7 @@ impl Global { } if copy_size.width == 0 || copy_size.height == 0 || copy_size.width == 0 { - log::trace!("Ignoring copy_texture_to_texture of size 0"); + tracing::trace!("Ignoring copy_texture_to_texture of size 0"); return Ok(()); } diff --git a/wgpu-core/src/device/life.rs b/wgpu-core/src/device/life.rs index 58654a7691..ce166181aa 100644 --- a/wgpu-core/src/device/life.rs +++ b/wgpu-core/src/device/life.rs @@ -135,12 +135,12 @@ impl NonReferencedResources { if !self.buffers.is_empty() || !self.images.is_empty() { let mut heaps = heaps_mutex.lock(); for (raw, memory) in self.buffers.drain(..) { - log::trace!("Buffer {:?} is destroyed with memory {:?}", raw, memory); + tracing::trace!("Buffer {:?} is destroyed with memory {:?}", raw, memory); device.destroy_buffer(raw); heaps.free(device, memory); } for (raw, memory) in self.images.drain(..) { - log::trace!("Image {:?} is destroyed with memory {:?}", raw, memory); + tracing::trace!("Image {:?} is destroyed with memory {:?}", raw, memory); device.destroy_image(raw); heaps.free(device, memory); } @@ -272,7 +272,7 @@ impl LifetimeTracker { fn wait_idle(&self, device: &B::Device) -> Result<(), WaitIdleError> { if !self.active.is_empty() { - log::debug!("Waiting for IDLE..."); + tracing::debug!("Waiting for IDLE..."); let status = unsafe { device.wait_for_fences( self.active.iter().map(|a| &a.fence), @@ -280,7 +280,7 @@ impl LifetimeTracker { CLEANUP_WAIT_MS * 1_000_000, )? }; - log::debug!("...Done"); + tracing::debug!("...Done"); if status == false { // We timed out while waiting for the fences @@ -313,7 +313,7 @@ impl LifetimeTracker { }; for a in self.active.drain(..done_count) { - log::trace!("Active submission {} is done", a.index); + tracing::trace!("Active submission {} is done", a.index); self.free_resources.extend(a.last_resources); self.ready_to_map.extend(a.mapped); unsafe { @@ -469,7 +469,7 @@ impl LifetimeTracker { trace.map(|t| t.lock().add(trace::Action::DestroyBuffer(id))); hub.buffers.free_id(id); let res = guard.remove(id).unwrap(); - log::debug!("Buffer {:?} is detached", id); + tracing::debug!("Buffer {:?} is detached", id); let submit_index = res.life_guard.submission_index.load(Ordering::Acquire); self.active @@ -583,7 +583,7 @@ impl LifetimeTracker { let buf = &buffer_guard[resource_id]; let submit_index = buf.life_guard.submission_index.load(Ordering::Acquire); - log::trace!( + tracing::trace!( "Mapping of {:?} at submission {:?} gets assigned to active {:?}", resource_id, submit_index, @@ -653,7 +653,7 @@ impl LifetimeTracker { .collect::>(); if !remove_list.is_empty() { - log::debug!("Free framebuffers {:?}", remove_list); + tracing::debug!("Free framebuffers {:?}", remove_list); for (ref key, submit_index) in remove_list { let framebuffer = framebuffers.remove(key).unwrap(); self.active @@ -685,7 +685,7 @@ impl LifetimeTracker { if buffer.life_guard.ref_count.is_none() && trackers.buffers.remove_abandoned(buffer_id) { buffer.map_state = resource::BufferMapState::Idle; - log::debug!("Mapping request is dropped because the buffer is destroyed."); + tracing::debug!("Mapping request is dropped because the buffer is destroyed."); hub.buffers.free_id(buffer_id); let buffer = buffer_guard.remove(buffer_id).unwrap(); self.free_resources @@ -700,7 +700,7 @@ impl LifetimeTracker { _ => panic!("No pending mapping."), }; let status = if mapping.sub_range.size.map_or(true, |x| x != 0) { - log::debug!("Buffer {:?} map state -> Active", buffer_id); + tracing::debug!("Buffer {:?} map state -> Active", buffer_id); let host = mapping.op.host; match super::map_buffer(raw, buffer, mapping.sub_range.clone(), host) { Ok(ptr) => { @@ -712,7 +712,7 @@ impl LifetimeTracker { resource::BufferMapAsyncStatus::Success } Err(e) => { - log::error!("Mapping failed {:?}", e); + tracing::error!("Mapping failed {:?}", e); resource::BufferMapAsyncStatus::Error } } diff --git a/wgpu-core/src/device/mod.rs b/wgpu-core/src/device/mod.rs index c185b22cc8..2f4d9db0c3 100644 --- a/wgpu-core/src/device/mod.rs +++ b/wgpu-core/src/device/mod.rs @@ -236,7 +236,7 @@ impl Device { let descriptors = unsafe { DescriptorAllocator::new() }; #[cfg(not(feature = "trace"))] match trace_path { - Some(_) => log::error!("Feature 'trace' is not enabled"), + Some(_) => tracing::error!("Feature 'trace' is not enabled"), None => (), } @@ -264,7 +264,7 @@ impl Device { Some(Mutex::new(trace)) } Err(e) => { - log::error!("Unable to start a trace in '{:?}': {:?}", path, e); + tracing::error!("Unable to start a trace in '{:?}': {:?}", path, e); None } }), @@ -594,9 +594,13 @@ impl Device { unsafe { self.raw.create_render_pass(all, iter::once(subpass), &[]) } } - fn wait_for_submit(&self, submission_index: SubmissionIndex, token: &mut Token) -> Result<(), WaitIdleError> { + fn wait_for_submit( + &self, + submission_index: SubmissionIndex, + token: &mut Token, + ) -> Result<(), WaitIdleError> { if self.last_completed_submission_index() <= submission_index { - log::info!("Waiting for submission {:?}", submission_index); + tracing::info!("Waiting for submission {:?}", submission_index); self.lock_life(token) .triage_submissions(&self.raw, true) .map(|_| ()) @@ -631,7 +635,7 @@ impl Device { pub(crate) fn prepare_to_die(&mut self) { let mut life_tracker = self.life_tracker.lock(); if let Err(error) = life_tracker.triage_submissions(&self.raw, true) { - log::error!("failed to triage submissions: {}", error); + tracing::error!("failed to triage submissions: {}", error); } life_tracker.cleanup(&self.raw, &self.mem_allocator, &self.desc_allocator); } @@ -689,7 +693,7 @@ impl Global { let hub = B::hub(self); let mut token = Token::root(); - log::info!("Create buffer {:?} with ID {:?}", desc, id_in); + tracing::info!("Create buffer {:?} with ID {:?}", desc, id_in); if desc.mapped_at_creation && desc.size % wgt::COPY_BUFFER_ALIGNMENT != 0 { return Err(CreateBufferError::UnalignedSize); @@ -744,7 +748,7 @@ impl Global { }; let id = hub.buffers.register_identity(id_in, buffer, &mut token); - log::info!("Created buffer {:?} with {:?}", id, desc); + tracing::info!("Created buffer {:?} with {:?}", id, desc); #[cfg(feature = "trace")] match device.trace { Some(ref trace) => { @@ -784,8 +788,7 @@ impl Global { .load(Ordering::Acquire) }; - device_guard[device_id] - .wait_for_submit(last_submission, &mut token) + device_guard[device_id].wait_for_submit(last_submission, &mut token) } pub fn device_set_buffer_sub_data( @@ -885,15 +888,12 @@ impl Global { let hub = B::hub(self); let mut token = Token::root(); - log::info!("Buffer {:?} is dropped", buffer_id); + tracing::info!("Buffer {:?} is dropped", buffer_id); let (ref_count, last_submit_index, device_id) = { let (mut buffer_guard, _) = hub.buffers.write(&mut token); let buffer = &mut buffer_guard[buffer_id]; let ref_count = buffer.life_guard.ref_count.take().unwrap(); - let last_submit_index = buffer - .life_guard - .submission_index - .load(Ordering::Acquire); + let last_submit_index = buffer.life_guard.submission_index.load(Ordering::Acquire); (ref_count, last_submit_index, buffer.device_id.value) }; @@ -908,7 +908,7 @@ impl Global { .push(buffer_id); match device.wait_for_submit(last_submit_index, &mut token) { Ok(()) => (), - Err(e) => log::error!("Failed to wait for buffer {:?}: {:?}", buffer_id, e), + Err(e) => tracing::error!("Failed to wait for buffer {:?}: {:?}", buffer_id, e), } } else { device @@ -1850,7 +1850,7 @@ impl Global { let id = hub .bind_groups .register_identity(id_in, bind_group, &mut token); - log::debug!( + tracing::debug!( "Bind group {:?} {:#?}", id, hub.bind_groups.read(&mut token).0[id].used @@ -1930,8 +1930,8 @@ impl Global { .map_err(|err| { // TODO: eventually, when Naga gets support for all features, // we want to convert these to a hard error, - log::warn!("Failed to parse shader SPIR-V code: {:?}", err); - log::warn!("Shader module will not be validated"); + tracing::warn!("Failed to parse shader SPIR-V code: {:?}", err); + tracing::warn!("Shader module will not be validated"); }) .ok() } else { @@ -2356,7 +2356,7 @@ impl Global { for (i, state) in color_states.iter().enumerate() { let output = &interface[&(i as wgt::ShaderLocation)]; if !validation::check_texture_format(state.format, output) { - log::warn!( + tracing::warn!( "Incompatible fragment output[{}]. Shader: {:?}. Expected: {:?}", i, state.format, @@ -2640,7 +2640,7 @@ impl Global { || height < caps.extents.start().height || height > caps.extents.end().height { - log::warn!( + tracing::warn!( "Requested size {}x{} is outside of the supported range: {:?}", width, height, @@ -2648,7 +2648,7 @@ impl Global { ); } if !caps.present_modes.contains(config.present_mode) { - log::warn!( + tracing::warn!( "Surface does not support present mode: {:?}, falling back to {:?}", config.present_mode, hal::window::PresentMode::FIFO @@ -2657,7 +2657,7 @@ impl Global { } } - log::info!("creating swap chain {:?}", desc); + tracing::info!("creating swap chain {:?}", desc); let hub = B::hub(self); let mut token = Token::root(); @@ -2882,7 +2882,7 @@ impl Global { }) } }; - log::debug!("Buffer {:?} map state -> Waiting", buffer_id); + tracing::debug!("Buffer {:?} map state -> Waiting", buffer_id); (buffer.device_id.value, buffer.life_guard.add_ref()) }; @@ -2937,7 +2937,7 @@ impl Global { let buffer = &mut buffer_guard[buffer_id]; let device = &mut device_guard[buffer.device_id.value]; - log::debug!("Buffer {:?} map state -> Idle", buffer_id); + tracing::debug!("Buffer {:?} map state -> Idle", buffer_id); match mem::replace(&mut buffer.map_state, resource::BufferMapState::Idle) { resource::BufferMapState::Init { ptr, diff --git a/wgpu-core/src/device/queue.rs b/wgpu-core/src/device/queue.rs index 4170ab9084..4b6f6a929d 100644 --- a/wgpu-core/src/device/queue.rs +++ b/wgpu-core/src/device/queue.rs @@ -158,7 +158,7 @@ impl Global { let data_size = data.len() as wgt::BufferAddress; if data_size == 0 { - log::trace!("Ignoring write_buffer of size 0"); + tracing::trace!("Ignoring write_buffer of size 0"); return; } @@ -269,7 +269,7 @@ impl Global { } if size.width == 0 || size.height == 0 || size.width == 0 { - log::trace!("Ignoring write_texture of size 0"); + tracing::trace!("Ignoring write_texture of size 0"); return; } @@ -447,7 +447,7 @@ impl Global { let buffer = &mut buffer_guard[id]; if !buffer.life_guard.use_at(submit_index) { if let BufferMapState::Active { .. } = buffer.map_state { - log::warn!("Dropped buffer has a pending mapping."); + tracing::warn!("Dropped buffer has a pending mapping."); super::unmap_buffer(&device.raw, buffer).unwrap(); } device.temp_suspected.buffers.push(id); @@ -497,7 +497,7 @@ impl Global { transit .begin_primary(hal::command::CommandBufferFlags::ONE_TIME_SUBMIT); } - log::trace!("Stitching command buffer {:?} before submission", cmb_id); + tracing::trace!("Stitching command buffer {:?} before submission", cmb_id); CommandBuffer::insert_barriers( &mut transit, &mut *trackers, @@ -511,7 +511,7 @@ impl Global { comb.raw.insert(0, transit); } - log::trace!("Device after submission {}: {:#?}", submit_index, trackers); + tracing::trace!("Device after submission {}: {:#?}", submit_index, trackers); } // now prepare the GPU submission diff --git a/wgpu-core/src/device/trace.rs b/wgpu-core/src/device/trace.rs index fb9a4ed1a2..9d80e7ad71 100644 --- a/wgpu-core/src/device/trace.rs +++ b/wgpu-core/src/device/trace.rs @@ -159,7 +159,7 @@ pub struct Trace { #[cfg(feature = "trace")] impl Trace { pub fn new(path: &std::path::Path) -> Result { - log::info!("Tracing into '{:?}'", path); + tracing::info!("Tracing into '{:?}'", path); let mut file = std::fs::File::create(path.join(FILE_NAME))?; file.write_all(b"[\n")?; Ok(Trace { @@ -183,7 +183,7 @@ impl Trace { let _ = writeln!(self.file, "{},", string); } Err(e) => { - log::warn!("RON serialization failure: {:?}", e); + tracing::warn!("RON serialization failure: {:?}", e); } } } diff --git a/wgpu-core/src/hub.rs b/wgpu-core/src/hub.rs index adb98ae5f3..6e15ff24f8 100644 --- a/wgpu-core/src/hub.rs +++ b/wgpu-core/src/hub.rs @@ -661,7 +661,7 @@ impl Global { impl Drop for Global { fn drop(&mut self) { if !thread::panicking() { - log::info!("Dropping Global"); + tracing::info!("Dropping Global"); let mut surface_guard = self.surfaces.data.write(); // destroy hubs diff --git a/wgpu-core/src/instance.rs b/wgpu-core/src/instance.rs index 3f840c2208..f4200b3319 100644 --- a/wgpu-core/src/instance.rs +++ b/wgpu-core/src/instance.rs @@ -355,7 +355,7 @@ impl Global { if let Some(id_backend) = inputs.find(backend) { for raw in inst.enumerate_adapters() { let adapter = Adapter::new(raw); - log::info!("Adapter {} {:?}", backend_info, adapter.raw.info); + tracing::info!("Adapter {} {:?}", backend_info, adapter.raw.info); adapters.push(backend_hub(self).adapters.register_identity( id_backend.clone(), adapter, @@ -450,7 +450,7 @@ impl Global { } if device_types.is_empty() { - log::warn!("No adapters are available!"); + tracing::warn!("No adapters are available!"); return None; } @@ -478,7 +478,7 @@ impl Global { Ok(false) => discrete.or(integrated).or(other).or(virt), Ok(true) => integrated.or(discrete).or(other).or(virt), Err(err) => { - log::debug!( + tracing::debug!( "Power info unavailable, preferring integrated gpu ({})", err ); @@ -495,7 +495,7 @@ impl Global { let map = |(info_adapter, id_backend, mut adapters_backend, backend_hub)| { if selected < adapters_backend.len() { let adapter = Adapter::new(adapters_backend.swap_remove(selected)); - log::info!("Adapter {} {:?}", info_adapter, adapter.raw.info); + tracing::info!("Adapter {} {:?}", info_adapter, adapter.raw.info); let id = backend_hub(self).adapters.register_identity( id_backend.take().unwrap(), adapter, @@ -523,7 +523,7 @@ impl Global { id_dx12.take(), id_dx11.take(), ); - log::warn!("Some adapters are present, but enumerating them failed!"); + tracing::warn!("Some adapters are present, but enumerating them failed!"); None } @@ -610,7 +610,7 @@ impl Global { .contains(wgt::Features::MAPPABLE_PRIMARY_BUFFERS) && adapter.raw.info.device_type == hal::adapter::DeviceType::DiscreteGpu { - log::warn!("Feature MAPPABLE_PRIMARY_BUFFERS enabled on a discrete gpu. This is a massive performance footgun and likely not what you wanted"); + tracing::warn!("Feature MAPPABLE_PRIMARY_BUFFERS enabled on a discrete gpu. This is a massive performance footgun and likely not what you wanted"); } let available_features = adapter.raw.physical_device.features(); @@ -623,7 +623,7 @@ impl Global { | hal::Features::SAMPLER_ANISOTROPY; let mut enabled_features = available_features & wishful_features; if enabled_features != wishful_features { - log::warn!( + tracing::warn!( "Missing features: {:?}", wishful_features - enabled_features ); @@ -698,7 +698,7 @@ impl Global { let mem_props = phd.memory_properties(); if !desc.shader_validation { - log::warn!("Shader validation is disabled"); + tracing::warn!("Shader validation is disabled"); } let private_features = PrivateFeatures { shader_validation: desc.shader_validation, diff --git a/wgpu-core/src/logging/subscriber.rs b/wgpu-core/src/logging/subscriber.rs index c7817eecd0..6ee63414c8 100644 --- a/wgpu-core/src/logging/subscriber.rs +++ b/wgpu-core/src/logging/subscriber.rs @@ -1,31 +1,24 @@ -use std::{ - borrow::Cow, - fmt, io, - io::Write, - path::Path, - sync::{Arc, Mutex}, - time::Instant, -}; -use tracing::{ - field::{Field, Visit}, - span, Event, Metadata, Subscriber, -}; -use tracing_subscriber::{ - layer::{Context, SubscriberExt}, - registry::LookupSpan, - EnvFilter, Layer, -}; +pub use chrome::*; +pub use fmt_layer::*; +use std::path::Path; +use tracing_subscriber::{layer::SubscriberExt as _, EnvFilter}; + +mod chrome; +mod fmt_layer; /// Set up the "standard" logger. /// /// This is fairly inflexible, but a good default to start with. If you need more customization, /// take what this function does and implement it however you need. /// +/// If this function is called, you should **not** set up a log-based logger like env_logger +/// or fern. This will result in duplicate messages. +/// /// # Args /// /// - `chrome_tracing_path` if set to `Some`, will create a trace compatible with chrome://tracing -/// at that location. -pub fn initialize_default_subscriber(chrome_trace_path: Option>) { +/// at that location. +pub fn initialize_default_subscriber(chrome_trace_path: Option<&Path>) { let chrome_tracing_layer_opt = chrome_trace_path.map(|path| ChromeTracingLayer::with_file(path).unwrap()); @@ -34,178 +27,22 @@ pub fn initialize_default_subscriber(chrome_trace_path: Option> tracing::subscriber::set_global_default( tracing_subscriber::Registry::default() .with(chrome_tracing_layer) - .with(tracing_subscriber::fmt::Layer::new()) + .with(FmtLayer::new()) .with(EnvFilter::from_default_env()), ) .unwrap(); } else { tracing::subscriber::set_global_default( tracing_subscriber::Registry::default() - .with(tracing_subscriber::fmt::Layer::new()) + .with(FmtLayer::new()) .with(EnvFilter::from_default_env()), ) .unwrap(); } + + tracing_log::LogTracer::init().unwrap(); } thread_local! { static CURRENT_THREAD_ID: usize = thread_id::get(); } - -#[derive(Debug, Copy, Clone, Eq, PartialEq)] -enum EventType { - Begin, - Event, - End, -} - -/// A layer to add to a [`tracing_subscriber::Registry`] to output to a chrome -/// trace. -/// -/// If you want an easy "set and forget" method of installing this and normal -/// tracing logging, call [`initialize_default_subscriber`]. -#[derive(Debug, Clone)] -pub struct ChromeTracingLayer { - file: Arc>, - start_time: Instant, - process_id: u32, -} - -impl ChromeTracingLayer { - /// Create a trace which outputs to the given file. The file will be cleared if it exits. - pub fn with_file(file: impl AsRef) -> io::Result { - std::fs::File::create(file).map(|mut file| { - writeln!(file, "[").unwrap(); - ChromeTracingLayer { - file: Arc::new(Mutex::new(file)), - start_time: Instant::now(), - process_id: std::process::id(), - } - }) - } - - fn write_event( - &self, - mut fields: Option, - metadata: &'static Metadata<'static>, - event_type: EventType, - ) { - if let Some(EventVisitor { trace: false, .. }) = fields { - return; - } - - let current_time = Instant::now(); - - let diff = current_time - self.start_time; - let diff_in_us = diff.as_micros(); - - let event_type_str = match event_type { - EventType::Begin => "B", - EventType::Event => "i", - EventType::End => "E", - }; - - let instant_scope = if event_type == EventType::Event { - r#","s": "p""# - } else { - "" - }; - - let name = match event_type { - EventType::Event => fields - .as_mut() - .and_then(|fields| fields.message.take()) - .map_or_else( - || { - let name = metadata.name(); - // The default name for events has a path in it, filter paths only on windows - if cfg!(target_os = "windows") { - Cow::Owned(name.replace("\\", "\\\\")) - } else { - Cow::Borrowed(name) - } - }, - Cow::from, - ), - EventType::Begin | EventType::End => Cow::Borrowed(metadata.name()), - }; - - let category = fields - .as_mut() - .and_then(|fields| fields.category.take()) - .map_or_else(|| Cow::Borrowed("trace"), Cow::from); - - let mut file = self.file.lock().unwrap(); - writeln!( - file, - r#"{{ "name": "{}", "cat": "{}", "ph": "{}", "ts": {}, "pid": {}, "tid": {} {} }},"#, - name, - category, - event_type_str, - diff_in_us, - self.process_id, - CURRENT_THREAD_ID.with(|v| *v), - instant_scope, - ) - .unwrap(); - } -} - -impl Drop for ChromeTracingLayer { - fn drop(&mut self) { - println!("drop"); - let mut file = self.file.lock().unwrap(); - writeln!(file, "]").unwrap(); - file.flush().unwrap(); - } -} - -#[derive(Debug, Default)] -struct EventVisitor { - message: Option, - category: Option, - trace: bool, -} - -impl Visit for EventVisitor { - fn record_bool(&mut self, field: &Field, value: bool) { - match field.name() { - "trace" => self.trace = value, - _ => {} - } - } - - fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { - match field.name() { - "message" => self.message = Some(format!("{:?}", value)), - "category" => self.category = Some(format!("{:?}", value)), - _ => {} - } - } -} - -impl Layer for ChromeTracingLayer -where - S: Subscriber + for<'span> LookupSpan<'span>, -{ - fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { - let mut event_visitor = EventVisitor::default(); - event.record(&mut event_visitor); - - self.write_event(Some(event_visitor), event.metadata(), EventType::Event); - } - - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - let span = ctx.span(id).unwrap(); - self.write_event(None, span.metadata(), EventType::Begin); - } - - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - if std::thread::panicking() { - return; - } - - let span = ctx.span(id).unwrap(); - self.write_event(None, span.metadata(), EventType::End); - } -} diff --git a/wgpu-core/src/logging/subscriber/chrome.rs b/wgpu-core/src/logging/subscriber/chrome.rs new file mode 100644 index 0000000000..27cbeb6773 --- /dev/null +++ b/wgpu-core/src/logging/subscriber/chrome.rs @@ -0,0 +1,170 @@ +use crate::logging::subscriber::CURRENT_THREAD_ID; +use parking_lot::Mutex; +use std::{ + borrow::Cow, + fmt, + io::{self, Write as _}, + path::Path, + sync::Arc, + time::Instant, +}; +use tracing::field::{Field, Visit}; +use tracing::{span, Event, Metadata, Subscriber}; +use tracing_subscriber::{layer::Context, registry::LookupSpan, Layer}; + +#[derive(Debug, Copy, Clone, Eq, PartialEq)] +enum EventType { + Begin, + Event, + End, +} + +/// A layer to add to a [`tracing_subscriber::Registry`] to output to a chrome +/// trace. +/// +/// If you want an easy "set and forget" method of installing this and normal +/// tracing logging, call [`initialize_default_subscriber`]. +#[derive(Debug, Clone)] +pub struct ChromeTracingLayer { + file: Arc>, + start_time: Instant, + process_id: u32, +} + +impl ChromeTracingLayer { + /// Create a trace which outputs to the given file. The file will be cleared if it exits. + pub fn with_file(file: impl AsRef) -> io::Result { + std::fs::File::create(file).map(|mut file| { + writeln!(file, "[").unwrap(); + ChromeTracingLayer { + file: Arc::new(Mutex::new(file)), + start_time: Instant::now(), + process_id: std::process::id(), + } + }) + } + + fn write_event( + &self, + mut fields: Option, + metadata: &'static Metadata<'static>, + event_type: EventType, + ) { + if let Some(EventVisitor { trace: false, .. }) = fields { + return; + } + + let current_time = Instant::now(); + + let diff = current_time - self.start_time; + let diff_in_us = diff.as_micros(); + + let event_type_str = match event_type { + EventType::Begin => "B", + EventType::Event => "i", + EventType::End => "E", + }; + + let instant_scope = if event_type == EventType::Event { + r#","s": "p""# + } else { + "" + }; + + let name = match event_type { + EventType::Event => fields + .as_mut() + .and_then(|fields| fields.message.take()) + .map_or_else( + || { + let name = metadata.name(); + // The default name for events has a path in it, filter paths only on windows + if cfg!(target_os = "windows") { + Cow::Owned(name.replace("\\", "\\\\")) + } else { + Cow::Borrowed(name) + } + }, + Cow::from, + ), + EventType::Begin | EventType::End => Cow::Borrowed(metadata.name()), + }; + + let category = fields + .as_mut() + .and_then(|fields| fields.category.take()) + .map_or_else(|| Cow::Borrowed("trace"), Cow::from); + + let mut file = self.file.lock(); + writeln!( + file, + r#"{{ "name": "{}", "cat": "{}", "ph": "{}", "ts": {}, "pid": {}, "tid": {} {} }},"#, + name, + category, + event_type_str, + diff_in_us, + self.process_id, + CURRENT_THREAD_ID.with(|v| *v), + instant_scope, + ) + .unwrap(); + } +} + +impl Drop for ChromeTracingLayer { + fn drop(&mut self) { + let mut file = self.file.lock(); + writeln!(file, "]").unwrap(); + file.flush().unwrap(); + } +} + +#[derive(Debug, Default)] +struct EventVisitor { + message: Option, + category: Option, + trace: bool, +} + +impl Visit for EventVisitor { + fn record_bool(&mut self, field: &Field, value: bool) { + match field.name() { + "trace" => self.trace = value, + _ => {} + } + } + + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + match field.name() { + "message" => self.message = Some(format!("{:?}", value)), + "category" => self.category = Some(format!("{:?}", value)), + _ => {} + } + } +} + +impl Layer for ChromeTracingLayer +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { + let mut event_visitor = EventVisitor::default(); + event.record(&mut event_visitor); + + self.write_event(Some(event_visitor), event.metadata(), EventType::Event); + } + + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + let span = ctx.span(id).unwrap(); + self.write_event(None, span.metadata(), EventType::Begin); + } + + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + if std::thread::panicking() { + return; + } + + let span = ctx.span(id).unwrap(); + self.write_event(None, span.metadata(), EventType::End); + } +} diff --git a/wgpu-core/src/logging/subscriber/fmt_layer.rs b/wgpu-core/src/logging/subscriber/fmt_layer.rs new file mode 100644 index 0000000000..e5ceb74197 --- /dev/null +++ b/wgpu-core/src/logging/subscriber/fmt_layer.rs @@ -0,0 +1,100 @@ +use smallvec::SmallVec; +use std::{ + fmt, + io::{self, Stderr, Stdout}, + time::Instant, +}; +use tracing::field::{Field, Visit}; +use tracing::{Event, Level, Subscriber}; +use tracing_subscriber::{layer::Context, registry::LookupSpan, Layer}; + +#[derive(Debug, Default)] +struct FmtEventVisitor { + message: String, +} + +impl Visit for FmtEventVisitor { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + match field.name() { + "message" => self.message = format!("{:?}", value), + _ => {} + } + } +} + +enum StandardOutput { + Out(Stdout), + Err(Stderr), +} + +impl StandardOutput { + fn new(level: &Level) -> Self { + match *level { + Level::ERROR | Level::WARN => Self::Err(io::stderr()), + _ => Self::Out(io::stdout()), + } + } + + fn get_dyn_ref(&mut self) -> &mut dyn io::Write { + match self { + Self::Out(out) => out, + Self::Err(err) => err, + } + } +} + +pub struct FmtLayer { + start: Instant, +} + +impl FmtLayer { + pub fn new() -> Self { + FmtLayer { + start: Instant::now(), + } + } +} + +impl Layer for FmtLayer +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + let now = Instant::now(); + let time = now - self.start; + + let mut visitor = FmtEventVisitor::default(); + event.record(&mut visitor); + + let mut spans: SmallVec<[&str; 8]> = SmallVec::new(); + for span in ctx.scope() { + spans.push(span.name()); + } + let span_string = spans.join(" | "); + + let metadata = event.metadata(); + let level = match *metadata.level() { + Level::ERROR => "ERROR", + Level::WARN => "WARN", + Level::INFO => "INFO", + Level::DEBUG => "DEBUG", + Level::TRACE => "TRACE", + }; + + let module = metadata.module_path().unwrap_or("no module"); + + let mut output = StandardOutput::new(metadata.level()); + let output_ref = output.get_dyn_ref(); + + writeln!( + output_ref, + "[{:.6} {}]({})({}): {}", + time.as_secs_f64(), + level, + span_string, + module, + visitor.message, + ) + .unwrap(); + } +} diff --git a/wgpu-core/src/resource.rs b/wgpu-core/src/resource.rs index 1711e770e6..a022e88d36 100644 --- a/wgpu-core/src/resource.rs +++ b/wgpu-core/src/resource.rs @@ -110,7 +110,7 @@ unsafe impl Sync for BufferMapOperation {} impl BufferMapOperation { pub(crate) fn call_error(self) { - log::error!("wgpu_buffer_map_async failed: buffer mapping is pending"); + tracing::error!("wgpu_buffer_map_async failed: buffer mapping is pending"); unsafe { (self.callback)(BufferMapAsyncStatus::Error, self.user_data); } diff --git a/wgpu-core/src/track/mod.rs b/wgpu-core/src/track/mod.rs index eada8af4b4..59a6628566 100644 --- a/wgpu-core/src/track/mod.rs +++ b/wgpu-core/src/track/mod.rs @@ -132,7 +132,7 @@ impl PendingTransition { self, buf: &'a resource::Buffer, ) -> hal::memory::Barrier<'a, B> { - log::trace!("\tbuffer -> {:?}", self); + tracing::trace!("\tbuffer -> {:?}", self); hal::memory::Barrier::Buffer { states: conv::map_buffer_state(self.usage.start) ..conv::map_buffer_state(self.usage.end), @@ -149,7 +149,7 @@ impl PendingTransition { self, tex: &'a resource::Texture, ) -> hal::memory::Barrier<'a, B> { - log::trace!("\ttexture -> {:?}", self); + tracing::trace!("\ttexture -> {:?}", self); let aspects = tex.full_range.aspects; hal::memory::Barrier::Image { states: conv::map_texture_state(self.usage.start, aspects) diff --git a/wgpu-core/src/validation.rs b/wgpu-core/src/validation.rs index faa9f5082f..7566499e2b 100644 --- a/wgpu-core/src/validation.rs +++ b/wgpu-core/src/validation.rs @@ -147,7 +147,7 @@ fn get_aligned_type_size( Ti::Struct { ref members } => members.last().map_or(0, |member| { let offset = match member.origin { naga::MemberOrigin::BuiltIn(_) => { - log::error!("Missing offset on a struct member"); + tracing::error!("Missing offset on a struct member"); 0 // TODO: make it a proper error } naga::MemberOrigin::Offset(offset) => offset as wgt::BufferAddress,