github/wgpu
1
1
Fork 0
mirror of https://github.com/gfx-rs/wgpu.git synced 2026-04-22 03:02:01 -04:00
Code Issues Packages Projects Releases Wiki Activity

Merge #835

Browse Source 
835: Convert all logging to tracing and add fmt logger r=kvark a=cwfitzgerald

**Connections**

#289 ish.

**Description**

This converts us fully to tracing, allowing traces to show up in logs.

https://github.com/gfx-rs/wgpu-rs/pull/476 should be considered at the same time as this PR.

**Testing**

Ran examples in wgpu-rs.

Co-authored-by: Connor Fitzgerald <connorwadefitzgerald@gmail.com>
This commit is contained in:
bors[bot]
2020-07-26 04:00:54 +00:00
committed by GitHub
parent 6182495102 cb485f3798
commit 11b3a95671
23 changed files with 368 additions and 256 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
Cargo.lock generated
View File

@@ -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",
]

2
player/Cargo.toml
View File

@@ -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"] }

7
player/src/bin/play.rs
View File

@@ -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))]

4
wgpu-core/Cargo.toml
View File

@@ -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"

10
wgpu-core/src/command/allocator.rs
View File

@@ -28,7 +28,7 @@ impl<B: hal::Backend> CommandPool<B> {
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<B: GfxBackend> CommandAllocator<B> {
.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<B: GfxBackend> CommandAllocator<B> {
impl<B: hal::Backend> CommandAllocator<B> {
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<B: hal::Backend> CommandAllocator<B> {
}
}
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<B: hal::Backend> CommandAllocator<B> {
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

6
wgpu-core/src/command/bind.rs
View File

@@ -187,7 +187,7 @@ impl Binder {
bind_group: &BindGroup<B>,
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
}
}

2
wgpu-core/src/command/bundle.rs
View File

@@ -891,7 +891,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
}
}
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 {

2
wgpu-core/src/command/compute.rs
View File

@@ -199,7 +199,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
.unwrap();
bind_group.validate_dynamic_bindings(offsets)?;
log::trace!(
tracing::trace!(
"Encoding barriers on binding of {:?} to {:?}",
bind_group_id,
encoder_id

2
wgpu-core/src/command/mod.rs
View File

@@ -174,7 +174,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
.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)
}

4
wgpu-core/src/command/render.rs
View File

@@ -573,7 +573,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
return Err(RenderPassError::InvalidSampleCount(sample_count));
}
log::trace!(
tracing::trace!(
"Encoding render pass begin in command buffer {:?}",
encoder_id
);
@@ -1584,7 +1584,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
}
}
log::trace!("Merging {:?} with the render pass", encoder_id);
tracing::trace!("Merging {:?} with the render pass", encoder_id);
unsafe {
raw.end_render_pass();
}

8
wgpu-core/src/command/transfer.rs
View File

@@ -245,7 +245,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
}
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<G: GlobalIdentityHandlerFactory> Global<G> {
}
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<G: GlobalIdentityHandlerFactory> Global<G> {
}
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<G: GlobalIdentityHandlerFactory> Global<G> {
}
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(());
}

22
wgpu-core/src/device/life.rs
View File

@@ -135,12 +135,12 @@ impl<B: hal::Backend> NonReferencedResources<B> {
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<B: hal::Backend> LifetimeTracker<B> {
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<B: hal::Backend> LifetimeTracker<B> {
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<B: hal::Backend> LifetimeTracker<B> {
};
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<B: GfxBackend> LifetimeTracker<B> {
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<B: GfxBackend> LifetimeTracker<B> {
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<B: GfxBackend> LifetimeTracker<B> {
.collect::<FastHashMap<_, _>>();
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<B: GfxBackend> LifetimeTracker<B> {
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<B: GfxBackend> LifetimeTracker<B> {
_ => 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<B: GfxBackend> LifetimeTracker<B> {
resource::BufferMapAsyncStatus::Success
}
Err(e) => {
log::error!("Mapping failed {:?}", e);
tracing::error!("Mapping failed {:?}", e);
resource::BufferMapAsyncStatus::Error
}
}

48
wgpu-core/src/device/mod.rs
View File

@@ -236,7 +236,7 @@ impl<B: GfxBackend> Device<B> {
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<B: GfxBackend> Device<B> {
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<B: GfxBackend> Device<B> {
unsafe { self.raw.create_render_pass(all, iter::once(subpass), &[]) }
}
fn wait_for_submit(&self, submission_index: SubmissionIndex, token: &mut Token<Self>) -> Result<(), WaitIdleError> {
fn wait_for_submit(
&self,
submission_index: SubmissionIndex,
token: &mut Token<Self>,
) -> 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<B: hal::Backend> Device<B> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
};
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<G: GlobalIdentityHandlerFactory> Global<G> {
.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<B: GfxBackend>(
@@ -885,15 +888,12 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
.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<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
.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<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
|| 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<G: GlobalIdentityHandlerFactory> Global<G> {
);
}
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<G: GlobalIdentityHandlerFactory> Global<G> {
}
}
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<G: GlobalIdentityHandlerFactory> Global<G> {
})
}
};
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<G: GlobalIdentityHandlerFactory> Global<G> {
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,

10
wgpu-core/src/device/queue.rs
View File

@@ -158,7 +158,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
}
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<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
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

4
wgpu-core/src/device/trace.rs
View File

@@ -159,7 +159,7 @@ pub struct Trace {
#[cfg(feature = "trace")]
impl Trace {
pub fn new(path: &std::path::Path) -> Result<Self, std::io::Error> {
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);
}
}
}

2
wgpu-core/src/hub.rs
View File

@@ -661,7 +661,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
impl<G: GlobalIdentityHandlerFactory> Drop for Global<G> {
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

16
wgpu-core/src/instance.rs
View File

@@ -355,7 +355,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
}
if device_types.is_empty() {
log::warn!("No adapters are available!");
tracing::warn!("No adapters are available!");
return None;
}
@@ -478,7 +478,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
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<G: GlobalIdentityHandlerFactory> Global<G> {
.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<G: GlobalIdentityHandlerFactory> Global<G> {
| 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<G: GlobalIdentityHandlerFactory> Global<G> {
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,

195
wgpu-core/src/logging/subscriber.rs
View File

@@ -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<impl AsRef<Path>>) {
/// 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<impl AsRef<Path>>
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<Mutex<std::fs::File>>,
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<Path>) -> io::Result<Self> {
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<EventVisitor>,
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<String>,
category: Option<String>,
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<S> Layer<S> 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);
}
}

170
wgpu-core/src/logging/subscriber/chrome.rs Normal file
View File

@@ -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<Mutex<std::fs::File>>,
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<Path>) -> io::Result<Self> {
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<EventVisitor>,
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<String>,
category: Option<String>,
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<S> Layer<S> 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);
}
}

100
wgpu-core/src/logging/subscriber/fmt_layer.rs Normal file
View File

@@ -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<S> Layer<S> 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();
}
}

2
wgpu-core/src/resource.rs
View File

@@ -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);
}

4
wgpu-core/src/track/mod.rs
View File

@@ -132,7 +132,7 @@ impl PendingTransition<BufferState> {
self,
buf: &'a resource::Buffer<B>,
) -> 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<TextureState> {
self,
tex: &'a resource::Texture<B>,
) -> 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)

2
wgpu-core/src/validation.rs
View File

@@ -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,