INFO-level logging is too verbose

[ErichDonGubler]

Description

While @emilk was investigating a (separate) crashing issue with wgpu, they reported that wgpu-hal and wgpu-core's logging at the INFO level were so verbose as to hinder debugging.

Repro steps

See this comment.

Expected vs observed behavior

In @emilk's words:

I think INFO should be used sparingly to inform users of important and rare events. Currently I cannot even resize my window without four log lines for each resize event:

2022-11-11T13:18:11.813326Z  INFO wgpu_core::device: configuring surface with SurfaceConfiguration { usage: RENDER_ATTACHMENT, format: Bgra8Unorm, width: 1889, height: 2135, present_mode: AutoVsync, alpha_mode: Auto }    
2022-11-11T13:18:11.813387Z  INFO wgpu_core::device: Automatically choosing presentation mode by rule AutoVsync. Chose Fifo    
2022-11-11T13:18:11.813391Z  INFO wgpu_core::device: Automatically choosing alpha mode by rule Auto. Chose Opaque    
2022-11-11T13:18:11.813397Z  INFO wgpu_hal::metal::surface: build swapchain SurfaceConfiguration { swap_chain_size: 3, present_mode: Fifo, composite_alpha_mode: Opaque, format: Bgra8Unorm, extent: Extent3d { width: 1889, height: 2135, depth_or_array_layers: 1 }, usage: COLOR_TARGET }

This is not interesting to me. This should be at the TRACE or DEBUG level imho.

Out of the box, we'd like INFO-level and higher severities of logging to have a high ratio of useful information.

Extra materials

-

Platform

-

Remaining action items

• Determine log levels going forward; reconcile the following opinions:

  • @cwfitzgerald's opinion(s): 1 (consensus from @kvark)

  • @kpreid's opinion(s): 1

  • @emilk's opinion(s): 1

  • @ErichDonGubler's opinion(s): 1

  • Current apparent consensus, with open questions noted in bold:

    Term	Definition
    Recoverability	@emilk: Whether an issue can be resolved automatically. A “recoverable” issue has good automatic fallback within wgpu, but should still be resolved. An “unrecoverable” issue requires end-user or developer intervention to resolve.
    Severity	The significance of a consequence associated with an issue. High severity (or "more severe") potentially thwarts wgpu's usage. Low severity ("less severe") may result in degraded performance or scope of functionality, but is not likely to threaten overall usage.

    Level	Description
    ERROR	High-severity unrecoverable issues. @emilk: Ideally, we avoid these in favor of returning Errors to user code.
    WARN	Issues that are one of (@emilk) recoverable (viz., has “good” automatic fallback), (@cwfitzgerald) unrecoverable, but of low severity, or (@ErichDonGubler) conditions that are unexpected and whose consequence is (1) potentially severe but (2) require further information to triage.
    INFO	@emilk, @kpreid: High-level summary of infrequent wgpu operations. Currently unclear whether there are any non-problematic per-frame events that are acceptable to report here.
    DEBUG	High-level indications of wgpu's inner workings. Intended only to contextualize other logs or span elements.
    TRACE	Fine-grained reporting of execution that is only expected to be interesting when wgpu itself is being scrutinized heavily for bugs.

• Move log statements that “only” acknowledge API calls to DEBUG level.
  • Move per-frame tracing to DEBUG or lower, in general.
    • TODO: Concrete things to move?

[kpreid]

I approve of this proposed change. It was an unpleasant surprise that my application logs were flooded with per-frame events when I added wgpu as a dependency, and I had to write a custom log filter for my wasm target (since console_log does not have a source filter, only a level filter).

I would like to suggest the rule that INFO or higher level should only be used if:

• it pertains to device/surface initialization or resource creation (things hopefully not done per-frame), or
• the message is almost certainly indicating a bug worth noting

That will minimize the probability of every-frame log spam which could create problems like a game writing gigabytes of log file to disk while it sits idle. (Of course, capping log file size is a good idea anyway, but it's the sort of thing that can be easily overlooked, and it reduces the value of the log when actually looked at.)

[emilk]

Thanks for creating this issue and summarizing it so well!

Repro

git clone [email protected]:emilk/egui.git
git checkout ef931c406c47c64d71462886692787ebca4b7b04
cargo r -p egui_demo_app --features wgpu

This already prints:

2022-11-14T18:59:36.867108Z  INFO wgpu_core::instance: Adapter Metal AdapterInfo { name: "Apple M1 Pro", vendor: 0, device: 0, device_type: IntegratedGpu, driver: "", driver_info: "", backend: Metal }    
2022-11-14T18:59:36.869277Z  INFO wgpu_core::device: Created buffer Valid((0, 1, Metal)) with BufferDescriptor { label: Some("egui_uniform_buffer"), size: 16, usage: COPY_DST | UNIFORM, mapped_at_creation: true }    
2022-11-14T18:59:36.871209Z  INFO wgpu_core::device: Created render pipeline Valid((0, 1, Metal)) with RenderPipelineDescriptor { label: Some("egui_pipeline"), layout: Some((0, 1, Metal)), vertex: VertexState { stage: ProgrammableStageDescriptor { module: (0, 1, Metal), entry_point: "vs_main" }, buffers: [VertexBufferLayout { array_stride: 20, step_mode: Vertex, attributes: [VertexAttribute { format: Float32x2, offset: 0, shader_location: 0 }, VertexAttribute { format: Float32x2, offset: 8, shader_location: 1 }, VertexAttribute { format: Uint32, offset: 16, shader_location: 2 }] }] }, primitive: PrimitiveState { topology: TriangleList, strip_index_format: None, front_face: Ccw, cull_mode: None, unclipped_depth: false, polygon_mode: Fill, conservative: false }, depth_stencil: None, multisample: MultisampleState { count: 1, mask: 18446744073709551615, alpha_to_coverage_enabled: false }, fragment: Some(FragmentState { stage: ProgrammableStageDescriptor { module: (0, 1, Metal), entry_point: "fs_main_gamma_framebuffer" }, targets: [Some(ColorTargetState { format: Bgra8Unorm, blend: Some(BlendState { color: BlendComponent { src_factor: One, dst_factor: OneMinusSrcAlpha, operation: Add }, alpha: BlendComponent { src_factor: OneMinusDstAlpha, dst_factor: One, operation: Add } }), write_mask: RED | GREEN | BLUE | ALPHA | COLOR | ALL })] }), multiview: None }    
2022-11-14T18:59:36.871322Z  INFO wgpu_core::device: Created buffer Valid((1, 1, Metal)) with BufferDescriptor { label: Some("egui_vertex_buffer"), size: 20480, usage: COPY_DST | VERTEX, mapped_at_creation: false }    
2022-11-14T18:59:36.871372Z  INFO wgpu_core::device: Created buffer Valid((2, 1, Metal)) with BufferDescriptor { label: Some("egui_index_buffer"), size: 12288, usage: COPY_DST | INDEX, mapped_at_creation: false }    
2022-11-14T18:59:36.871469Z  INFO wgpu_core::device: configuring surface with SurfaceConfiguration { usage: RENDER_ATTACHMENT, format: Bgra8Unorm, width: 1327, height: 1059, present_mode: AutoVsync, alpha_mode: Auto }    
2022-11-14T18:59:36.871476Z  INFO wgpu_core::device: Automatically choosing presentation mode by rule AutoVsync. Chose Fifo    
2022-11-14T18:59:36.871478Z  INFO wgpu_core::device: Automatically choosing alpha mode by rule Auto. Chose Opaque    
2022-11-14T18:59:36.871480Z  INFO wgpu_hal::metal::surface: build swapchain SurfaceConfiguration { swap_chain_size: 3, present_mode: Fifo, composite_alpha_mode: Opaque, format: Bgra8Unorm, extent: Extent3d { width: 1327, height: 1059, depth_or_array_layers: 1 }, usage: COLOR_TARGET }    
2022-11-14T18:59:36.874348Z  INFO wgpu_core::device: Created render pipeline Valid((1, 1, Metal)) with RenderPipelineDescriptor { label: Some("custom3d"), layout: Some((1, 1, Metal)), vertex: VertexState { stage: ProgrammableStageDescriptor { module: (0, 2, Metal), entry_point: "vs_main" }, buffers: [] }, primitive: PrimitiveState { topology: TriangleList, strip_index_format: None, front_face: Ccw, cull_mode: None, unclipped_depth: false, polygon_mode: Fill, conservative: false }, depth_stencil: None, multisample: MultisampleState { count: 1, mask: 18446744073709551615, alpha_to_coverage_enabled: false }, fragment: Some(FragmentState { stage: ProgrammableStageDescriptor { module: (0, 2, Metal), entry_point: "fs_main" }, targets: [Some(ColorTargetState { format: Bgra8Unorm, blend: None, write_mask: RED | GREEN | BLUE | ALPHA | COLOR | ALL })] }), multiview: None }    
2022-11-14T18:59:36.874415Z  INFO wgpu_core::device: Created buffer Valid((3, 1, Metal)) with BufferDescriptor { label: Some("custom3d"), size: 16, usage: COPY_DST | UNIFORM, mapped_at_creation: true }    
2022-11-14T18:59:36.921052Z  INFO wgpu_core::device: Created texture Valid((1, 1, Metal)) with TextureDescriptor { label: Some("egui_texid_Managed(1)"), size: Extent3d { width: 128, height: 64, depth_or_array_layers: 1 }, mip_level_count: 1, sample_count: 1, dimension: D2, format: Rgba8UnormSrgb, usage: COPY_DST | TEXTURE_BINDING }    
2022-11-14T18:59:37.034451Z  INFO wgpu_core::device: Created texture Valid((2, 1, Metal)) with TextureDescriptor { label: Some("egui_texid_Managed(0)"), size: Extent3d { width: 8192, height: 256, depth_or_array_layers: 1 }, mip_level_count: 1, sample_count: 1, dimension: D2, format: Rgba8UnormSrgb, usage: COPY_DST | TEXTURE_BINDING }    
2022-11-14T18:59:37.036247Z  INFO wgpu_core::device: Created buffer Valid((4, 1, Metal)) with BufferDescriptor { label: Some("egui_index_buffer"), size: 69000, usage: COPY_DST | INDEX, mapped_at_creation: false }    
2022-11-14T18:59:37.036281Z  INFO wgpu_core::device: Created buffer Valid((5, 1, Metal)) with BufferDescriptor { label: Some("egui_vertex_buffer"), size: 150080, usage: COPY_DST | VERTEX, mapped_at_creation: false }    
2022-11-14T18:59:37.056029Z  INFO wgpu_core::device: configuring surface with SurfaceConfiguration { usage: RENDER_ATTACHMENT, format: Bgra8Unorm, width: 1327, height: 1059, present_mode: AutoVsync, alpha_mode: Auto }    
2022-11-14T18:59:37.056059Z  INFO wgpu_core::device: Automatically choosing presentation mode by rule AutoVsync. Chose Fifo    
2022-11-14T18:59:37.056061Z  INFO wgpu_core::device: Automatically choosing alpha mode by rule Auto. Chose Opaque    
2022-11-14T18:59:37.056063Z  INFO wgpu_hal::metal::surface: build swapchain SurfaceConfiguration { swap_chain_size: 3, present_mode: Fifo, composite_alpha_mode: Opaque, format: Bgra8Unorm, extent: Extent3d { width: 1327, height: 1059, depth_or_array_layers: 1 }, usage: COLOR_TARGET }    
2022-11-14T18:59:37.060206Z  INFO wgpu_core::device: Created buffer Valid((1, 2, Metal)) with BufferDescriptor { label: Some("egui_index_buffer"), size: 138000, usage: COPY_DST | INDEX, mapped_at_creation: false }    
2022-11-14T18:59:37.060234Z  INFO wgpu_core::device: Created buffer Valid((2, 2, Metal)) with BufferDescriptor { label: Some("egui_vertex_buffer"), size: 300160, usage: COPY_DST | VERTEX, mapped_at_creation: false }  

This is far more verbose than any other Rust crate I know of.

If I then resize the window, then each frame during the resize I get:

2022-11-14T19:01:01.568595Z  INFO wgpu_core::device: configuring surface with SurfaceConfiguration { usage: RENDER_ATTACHMENT, format: Bgra8Unorm, width: 1422, height: 1067, present_mode: AutoVsync, alpha_mode: Auto }    
2022-11-14T19:01:01.568620Z  INFO wgpu_core::device: Automatically choosing presentation mode by rule AutoVsync. Chose Fifo    
2022-11-14T19:01:01.568622Z  INFO wgpu_core::device: Automatically choosing alpha mode by rule Auto. Chose Opaque    
2022-11-14T19:01:01.568624Z  INFO wgpu_hal::metal::surface: build swapchain SurfaceConfiguration { swap_chain_size: 3, present_mode: Fifo, composite_alpha_mode: Opaque, format: Bgra8Unorm, extent: Extent3d { width: 1422, height: 1067, depth_or_array_layers: 1 }, usage: COLOR_TARGET }

The same is true in the browser.

Now, I'm no wgpu expert, and it is possible that the egui-wgpu renderer could/should be rewritten to do less wgpu allocations (@Wumpf knows it better than I do), but recreating the render surface on resize is unavoidable, and since it is something I as the user am doing explicitly, I don't need wgpu echoing it back to me, and definitely not at the INFO level.

[emilk]

My two cents on log levels

The log is for several distinct users:

• The application user
• The application programmer
• The library user
• The library programmer

We are all sharing the same log stream, so we must cooperate carefully.

This is my general philosophy:

ERROR

This is for unrecoverable problems. The application or library couldn't complete an operation.

Libraries should ideally not log ERROR, but instead return Err in a Result, but there are rare cases where returning a Result isn't possible (e.g. then doing an operation in a background task).

Application can "handle" Errors by logging them as ERROR (perhaps in addition to showing a popup, if this is a GUI app).

WARNING

This is for recoverable problems. The operation completed, but couldn't do exactly what it was instructed to do.

Sometimes an Err is handled by logging it as WARNING and then running some fallback code.

INFO

This is the default verbosity level. This should mostly be used only by application code to write interesting and rare things to the application user. For instance, you may perhaps log that a file was saved to specific path, or where the default configuration was read from. These things lets application users understand what the application is doing, and debug their use of the application.

DEBUG

This is a level you opt-in to to debug either an application or a library. These are logged when high-level operations are performed (e.g. texture creation).

TRACE

This is the last-resort log level, and mostly for debugging libraries or the use of libraries. Here any and all spam goes, logging low-level operations.

The distinction between DEBUG and TRACE is the least clear. My rule of thumb: if it generates a lot of continuous logging, it should go to TRACE.

[ErichDonGubler]

I'm noting where we seem to diverge or converge for each log level in the PR OP. I'm assuming that general consensus is what we're looking for, as opposed to consensus only among maintainers (CC @cwfitzgerald, @jimblandy, @i509VCB, @crowlKats, @teoxoy). LMK if any assumptions are invalid, this just doesn't sound useful, or I've missed somebody in my tagging. EDIT: Also inviting more informal chat in Matrix here.

In general, I agree with the thrust of @cwfitzgerald's and @emilk's opinions, and I think we all have mostly compatible opinions? I am hesitant to un-bold things (meaning, mark them as not controversial), without explicit confirmation, but even then, I think we can refine this quickly into consensus.

[ErichDonGubler]

I'd also add to the scope of WARN to include likely issues; that is, something that wgpu can't or doesn't conclusively classify as an issue, but with potentially severe consequences. I've added my opinion to the OP.

To that point: @kpreid suggested that a “message [that] is almost certainly indicating a bug worth noting” should be in INFO-level or above. The previous paragraph in this message would mean that “almost certainly [a] bug” should actually be WARN-level or higher, rather than INFO-level or higher.