Downgrade resource lifetime management log level to trace. (#4772)

* Downgrade resource lifetime management log level to trace. Allow promoting it back to info via an feature flag. * Don't filter out info and warning log in the examples. * Changelog entry.
2024-11-25 00:03:29 +00:00 · 2023-11-25 17:33:02 +01:00 · 2023-11-25 17:33:02 +01:00 · ebcfd25b58
commit ebcfd25b58
parent f4c6faf773
14 changed files with 53 additions and 31 deletions
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@ -82,6 +82,7 @@ By @gents83 in [#3626](https://github.com/gfx-rs/wgpu/pull/3626) and tnx also to
 - `TextureFormat::block_size` is deprecated, use `TextureFormat::block_copy_size` instead: By @wumpf in [#4647](https://github.com/gfx-rs/wgpu/pull/4647)
 - Rename of `DispatchIndirect`, `DrawIndexedIndirect`, and `DrawIndirect` types in the `wgpu::util` module to `DispatchIndirectArgs`, `DrawIndexedIndirectArgs`, and `DrawIndirectArgs`. By @cwfitzgerald in [#4723](https://github.com/gfx-rs/wgpu/pull/4723).
 - Make the size parameter of `encoder.clear_buffer` an `Option<u64>` instead of `Option<NonZero<u64>>`. By @nical in [#4737](https://github.com/gfx-rs/wgpu/pull/4737)
+- Reduce the `info` log level noise. By @nical in [#4769](https://github.com/gfx-rs/wgpu/pull/4769), [#4711](https://github.com/gfx-rs/wgpu/pull/4711) and [#4772](https://github.com/gfx-rs/wgpu/pull/4772)

 #### Safe `Surface` creation

--- a/examples/src/framework.rs
+++ b/examples/src/framework.rs
@ -80,7 +80,7 @@ fn init_logger() {
            env_logger::builder()
                .filter_level(log::LevelFilter::Info)
                // We keep wgpu at Error level, as it's very noisy.
-                .filter_module("wgpu_core", log::LevelFilter::Error)
+                .filter_module("wgpu_core", log::LevelFilter::Info)
                .filter_module("wgpu_hal", log::LevelFilter::Error)
                .filter_module("naga", log::LevelFilter::Error)
                .parse_default_env()
--- a/wgpu-core/Cargo.toml
+++ b/wgpu-core/Cargo.toml
@ -31,6 +31,8 @@ targets = [
 default = ["link"]
 # Log all API entry points at info instead of trace level.
 api_log_info = []
+# Log resource lifecycle management at info instead of trace level.
+resource_log_info = []

 # Backends, passed through to wgpu-hal
 metal = ["hal/metal"]
--- a/wgpu-core/src/binding_model.rs
+++ b/wgpu-core/src/binding_model.rs
@ -8,6 +8,7 @@ use crate::{
    },
    init_tracker::{BufferInitTrackerAction, TextureInitTrackerAction},
    resource::{Resource, ResourceInfo, ResourceType},
+    resource_log,
    track::{BindGroupStates, UsageConflict},
    validation::{MissingBufferUsageError, MissingTextureUsageError},
    FastHashMap, Label,
@ -465,8 +466,8 @@ pub struct BindGroupLayout<A: HalApi> {

 impl<A: HalApi> Drop for BindGroupLayout<A> {
    fn drop(&mut self) {
-        log::info!("Destroying BindGroupLayout {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw BindGroupLayout {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_bind_group_layout(raw);
@ -606,8 +607,8 @@ pub struct PipelineLayout<A: HalApi> {

 impl<A: HalApi> Drop for PipelineLayout<A> {
    fn drop(&mut self) {
-        log::info!("Destroying PipelineLayout {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw PipelineLayout {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_pipeline_layout(raw);
@ -827,8 +828,8 @@ pub struct BindGroup<A: HalApi> {

 impl<A: HalApi> Drop for BindGroup<A> {
    fn drop(&mut self) {
-        log::info!("Destroying BindGroup {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw BindGroup {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_bind_group(raw);
--- a/wgpu-core/src/command/mod.rs
+++ b/wgpu-core/src/command/mod.rs
@ -27,7 +27,8 @@ use crate::init_tracker::BufferInitTrackerAction;
 use crate::resource::{Resource, ResourceInfo, ResourceType};
 use crate::track::{Tracker, UsageScope};
 use crate::{
-    api_log, global::Global, hal_api::HalApi, id, identity::GlobalIdentityHandlerFactory, Label,
+    api_log, global::Global, hal_api::HalApi, id, identity::GlobalIdentityHandlerFactory,
+    resource_log, Label,
 };

 use hal::CommandEncoder as _;
@ -137,7 +138,7 @@ impl<A: HalApi> Drop for CommandBuffer<A> {
        if self.data.lock().is_none() {
            return;
        }
-        log::info!("Destroying CommandBuffer {:?}", self.info.label());
+        resource_log!("resource::CommandBuffer::drop {}", self.info.label());
        let mut baked = self.extract_baked_commands();
        unsafe {
            baked.encoder.reset_all(baked.list.into_iter());
--- a/wgpu-core/src/device/mod.rs
+++ b/wgpu-core/src/device/mod.rs
@ -6,7 +6,7 @@ use crate::{
    identity::{GlobalIdentityHandlerFactory, Input},
    resource::{Buffer, BufferAccessResult},
    resource::{BufferAccessError, BufferMapOperation},
-    Label, DOWNLEVEL_ERROR_MESSAGE,
+    resource_log, Label, DOWNLEVEL_ERROR_MESSAGE,
 };

 use arrayvec::ArrayVec;
@ -372,7 +372,10 @@ impl<A: HalApi> CommandAllocator<A> {
    }

    fn dispose(self, device: &A::Device) {
-        log::info!("Destroying {} command encoders", self.free_encoders.len());
+        resource_log!(
+            "CommandAllocator::dispose encoders {}",
+            self.free_encoders.len()
+        );
        for cmd_encoder in self.free_encoders {
            unsafe {
                device.destroy_command_encoder(cmd_encoder);
--- a/wgpu-core/src/device/queue.rs
+++ b/wgpu-core/src/device/queue.rs
@ -19,7 +19,7 @@ use crate::{
        Buffer, BufferAccessError, BufferMapState, Resource, ResourceInfo, ResourceType,
        StagingBuffer, Texture, TextureInner,
    },
-    track, FastHashMap, SubmissionIndex,
+    resource_log, track, FastHashMap, SubmissionIndex,
 };

 use hal::{CommandEncoder as _, Device as _, Queue as _};
@ -468,7 +468,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {

        let fid = hub.staging_buffers.prepare::<G>(id_in);
        let (id, _) = fid.assign(staging_buffer);
-        log::info!("Created StagingBuffer {:?}", id);
+        resource_log!("Queue::create_staging_buffer {id:?}");

        Ok((id, staging_buffer_ptr))
    }
--- a/wgpu-core/src/device/resource.rs
+++ b/wgpu-core/src/device/resource.rs
@ -25,6 +25,7 @@ use crate::{
        self, Buffer, QuerySet, Resource, ResourceType, Sampler, Texture, TextureView,
        TextureViewNotRenderableReason,
    },
+    resource_log,
    storage::Storage,
    track::{BindGroupStates, TextureSelector, Tracker},
    validation::{self, check_buffer_usage, check_texture_usage},
@ -140,7 +141,7 @@ impl<A: HalApi> std::fmt::Debug for Device<A> {

 impl<A: HalApi> Drop for Device<A> {
    fn drop(&mut self) {
-        log::info!("Destroying Device {:?}", self.info.label());
+        resource_log!("Destroy raw Device {}", self.info.label());
        let raw = self.raw.take().unwrap();
        let pending_writes = self.pending_writes.lock().take().unwrap();
        pending_writes.dispose(&raw);
--- a/wgpu-core/src/global.rs
+++ b/wgpu-core/src/global.rs
@ -9,6 +9,7 @@ use crate::{
    identity::GlobalIdentityHandlerFactory,
    instance::{Instance, Surface},
    registry::{Registry, RegistryReport},
+    resource_log,
    storage::Element,
 };

@ -150,7 +151,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
 impl<G: GlobalIdentityHandlerFactory> Drop for Global<G> {
    fn drop(&mut self) {
        profiling::scope!("Global::drop");
-        log::info!("Destroying Global");
+        resource_log!("Global::drop");
        let mut surfaces_locked = self.surfaces.write();

        // destroy hubs before the instance gets dropped
--- a/wgpu-core/src/instance.rs
+++ b/wgpu-core/src/instance.rs
@ -10,7 +10,7 @@ use crate::{
    identity::{GlobalIdentityHandlerFactory, Input},
    present::Presentation,
    resource::{Resource, ResourceInfo, ResourceType},
-    LabelHelpers, DOWNLEVEL_WARNING_MESSAGE,
+    resource_log, LabelHelpers, DOWNLEVEL_WARNING_MESSAGE,
 };

 use parking_lot::Mutex;
@ -1082,7 +1082,7 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
                Backend::Gl => fid.assign(Adapter::new(hal_adapter)),
                _ => unreachable!(),
            };
-        log::info!("Created Adapter {:?}", id);
+        resource_log!("Created Adapter {:?}", id);
        id
    }

@ -1203,13 +1203,13 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
                    Err(e) => break e,
                };
            let (device_id, _) = device_fid.assign(device);
-            log::info!("Created Device {:?}", device_id);
+            resource_log!("Created Device {:?}", device_id);

            let device = hub.devices.get(device_id).unwrap();
            queue.device = Some(device.clone());

            let (queue_id, _) = queue_fid.assign(queue);
-            log::info!("Created Queue {:?}", queue_id);
+            resource_log!("Created Queue {:?}", queue_id);

            device.queue_id.write().replace(queue_id);

@ -1255,13 +1255,13 @@ impl<G: GlobalIdentityHandlerFactory> Global<G> {
                Err(e) => break e,
            };
            let (device_id, _) = devices_fid.assign(device);
-            log::info!("Created Device {:?}", device_id);
+            resource_log!("Created Device {:?}", device_id);

            let device = hub.devices.get(device_id).unwrap();
            queue.device = Some(device.clone());

            let (queue_id, _) = queues_fid.assign(queue);
-            log::info!("Created Queue {:?}", queue_id);
+            resource_log!("Created Queue {:?}", queue_id);

            device.queue_id.write().replace(queue_id);

--- a/wgpu-core/src/lib.rs
+++ b/wgpu-core/src/lib.rs
@ -289,6 +289,16 @@ macro_rules! api_log {
 }
 pub(crate) use api_log;

+#[cfg(feature = "resource_log_info")]
+macro_rules! resource_log {
+    ($($arg:tt)+) => (log::info!($($arg)+))
+}
+#[cfg(not(feature = "resource_log_info"))]
+macro_rules! resource_log {
+    ($($arg:tt)+) => (log::trace!($($arg)+))
+}
+pub(crate) use resource_log;
+
 /// Fast hash map used internally.
 type FastHashMap<K, V> =
    std::collections::HashMap<K, V, std::hash::BuildHasherDefault<rustc_hash::FxHasher>>;
--- a/wgpu-core/src/pipeline.rs
+++ b/wgpu-core/src/pipeline.rs
@ -7,7 +7,7 @@ use crate::{
    hal_api::HalApi,
    id::{ComputePipelineId, PipelineLayoutId, RenderPipelineId, ShaderModuleId},
    resource::{Resource, ResourceInfo, ResourceType},
-    validation, Label,
+    resource_log, validation, Label,
 };
 use arrayvec::ArrayVec;
 use std::{borrow::Cow, error::Error, fmt, marker::PhantomData, num::NonZeroU32, sync::Arc};
@ -54,8 +54,8 @@ pub struct ShaderModule<A: HalApi> {

 impl<A: HalApi> Drop for ShaderModule<A> {
    fn drop(&mut self) {
-        log::info!("Destroying ShaderModule {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw ShaderModule {}", self.info.label());
            #[cfg(feature = "trace")]
            if let Some(ref mut trace) = *self.device.trace.lock() {
                trace.add(trace::Action::DestroyShaderModule(self.info.id()));
@ -253,8 +253,8 @@ pub struct ComputePipeline<A: HalApi> {

 impl<A: HalApi> Drop for ComputePipeline<A> {
    fn drop(&mut self) {
-        log::info!("Destroying ComputePipeline {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw ComputePipeline {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_compute_pipeline(raw);
@ -494,8 +494,8 @@ pub struct RenderPipeline<A: HalApi> {

 impl<A: HalApi> Drop for RenderPipeline<A> {
    fn drop(&mut self) {
-        log::info!("Destroying RenderPipeline {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw RenderPipeline {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_render_pipeline(raw);
--- a/wgpu-core/src/resource.rs
+++ b/wgpu-core/src/resource.rs
@ -13,7 +13,7 @@ use crate::{
    },
    identity::{GlobalIdentityHandlerFactory, IdentityManager},
    init_tracker::{BufferInitTracker, TextureInitTracker},
-    resource,
+    resource, resource_log,
    track::TextureSelector,
    validation::MissingBufferUsageError,
    Label, SubmissionIndex,
@ -79,7 +79,6 @@ impl<Id: TypedId> Drop for ResourceInfo<Id> {
        if let Some(identity) = self.identity.as_ref() {
            let id = self.id.as_ref().unwrap();
            identity.free(*id);
-            log::info!("Freeing {:?}", self.label());
        }
    }
 }
@ -418,8 +417,8 @@ pub struct Buffer<A: HalApi> {

 impl<A: HalApi> Drop for Buffer<A> {
    fn drop(&mut self) {
-        log::info!("Destroying Buffer {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw Buffer {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_buffer(raw);
@ -639,8 +638,8 @@ pub struct StagingBuffer<A: HalApi> {

 impl<A: HalApi> Drop for StagingBuffer<A> {
    fn drop(&mut self) {
-        log::info!("Destroying StagingBuffer {:?}", self.info.label());
        if let Some(raw) = self.raw.lock().take() {
+            resource_log!("Destroy raw StagingBuffer {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_buffer(raw);
@ -722,7 +721,7 @@ pub struct Texture<A: HalApi> {

 impl<A: HalApi> Drop for Texture<A> {
    fn drop(&mut self) {
-        log::info!("Destroying Texture {:?}", self.info.label());
+        resource_log!("Destroy raw Texture {}", self.info.label());
        use hal::Device;
        let mut clear_mode = self.clear_mode.write();
        let clear_mode = &mut *clear_mode;
@ -1038,8 +1037,8 @@ pub struct TextureView<A: HalApi> {

 impl<A: HalApi> Drop for TextureView<A> {
    fn drop(&mut self) {
-        log::info!("Destroying TextureView {:?}", self.info.label());
        if let Some(raw) = self.raw.take() {
+            resource_log!("Destroy raw TextureView {}", self.info.label());
            unsafe {
                use hal::Device;
                self.device.raw().destroy_texture_view(raw);
@ -1160,7 +1159,7 @@ pub struct Sampler<A: HalApi> {

 impl<A: HalApi> Drop for Sampler<A> {
    fn drop(&mut self) {
-        log::info!("Destroying Sampler {:?}", self.info.label());
+        resource_log!("Destroy raw Sampler {}", self.info.label());
        if let Some(raw) = self.raw.take() {
            unsafe {
                use hal::Device;
@ -1257,7 +1256,7 @@ pub struct QuerySet<A: HalApi> {

 impl<A: HalApi> Drop for QuerySet<A> {
    fn drop(&mut self) {
-        log::info!("Destroying QuerySet {:?}", self.info.label());
+        resource_log!("Destroy raw QuerySet {}", self.info.label());
        if let Some(raw) = self.raw.take() {
            unsafe {
                use hal::Device;
--- a/wgpu-core/src/track/stateless.rs
+++ b/wgpu-core/src/track/stateless.rs
@ -9,7 +9,8 @@ use std::{marker::PhantomData, sync::Arc};
 use parking_lot::Mutex;

 use crate::{
-    hal_api::HalApi, id::TypedId, resource::Resource, storage::Storage, track::ResourceMetadata,
+    hal_api::HalApi, id::TypedId, resource::Resource, resource_log, storage::Storage,
+    track::ResourceMetadata,
 };

 use super::ResourceTracker;
@ -91,6 +92,8 @@ impl<A: HalApi, Id: TypedId, T: Resource<Id>> ResourceTracker<Id, T>
            return false;
        }

+        resource_log!("StatelessTracker::remove_abandoned {id:?}");
+
        self.tracker_assert_in_bounds(index);

        unsafe {