diff --git a/Cargo.toml b/Cargo.toml index 6081ce91f..96c86b3ce 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -45,6 +45,7 @@ bytemuck = { workspace = true } skrifa = { workspace = true } peniko = { workspace = true } wgpu = { workspace = true, optional = true } +log = { workspace = true } raw-window-handle = "0.5" futures-intrusive = "0.5.0" vello_encoding = { path = "crates/encoding" } @@ -57,7 +58,7 @@ peniko = "0.1.0" # NOTE: Make sure to keep this in sync with the version badge in README.md wgpu = { version = "0.18" } - +log = "0.4.20" # Used for examples clap = "4.1.0" diff --git a/examples/with_winit/Cargo.toml b/examples/with_winit/Cargo.toml index 4d3d2e72c..be220c264 100644 --- a/examples/with_winit/Cargo.toml +++ b/examples/with_winit/Cargo.toml @@ -31,7 +31,7 @@ wgpu-profiler = { workspace = true } wgpu = { workspace = true } winit = "0.28.1" env_logger = "0.10.0" -log = "0.4.17" +log = { workspace = true } [target.'cfg(not(any(target_arch = "wasm32", target_os = "android")))'.dependencies] vello = { path = "../../", features = ["hot_reload"] } @@ -48,5 +48,9 @@ console_log = "1" wasm-bindgen-futures = "0.4.33" # Note: pinning the exact dep here because 0.3.65 broke semver. Update this # when revving wgpu. -web-sys = { version = "=0.3.64", features = [ "HtmlCollection", "Text" ] } +web-sys = { version = "=0.3.64", features = ["HtmlCollection", "Text"] } getrandom = { version = "0.2.10", features = ["js"] } + +[package.metadata.android.signing.release] +path = "/home/djmcnab/.android/debug.keystore" +keystore_password = "android" diff --git a/examples/with_winit/src/lib.rs b/examples/with_winit/src/lib.rs index 88fd6849a..91923fd63 100644 --- a/examples/with_winit/src/lib.rs +++ b/examples/with_winit/src/lib.rs @@ -17,7 +17,6 @@ use instant::{Duration, Instant}; use std::collections::HashSet; -use anyhow::Result; use clap::{CommandFactory, Parser}; use scenes::{ImageCache, SceneParams, SceneSet, SimpleText}; use vello::peniko::Color; @@ -112,7 +111,7 @@ fn run( let mut complexity_shown = false; let mut vsync_on = true; - const AA_CONFIGS: [AaConfig; 3] = [AaConfig::Area, AaConfig::Msaa8, AaConfig::Msaa16]; + const AA_CONFIGS: [AaConfig; 1] = [AaConfig::Area]; // We allow cycling through AA configs in either direction, so use a signed index let mut aa_config_ix: i32 = 0; @@ -201,10 +200,8 @@ fn run( path, profile_result, ) { - Ok(()) => { - println!("Wrote trace to path {path:?}"); - } - Err(e) => eprintln!("Failed to write trace {e}"), + Ok(()) => println!("Wrote trace to path {path:?}"), + Err(e) => log::warn!("Failed to write trace: {e}"), } } } @@ -292,7 +289,7 @@ fn run( * Affine::translate(-prior_position) * transform; } else { - eprintln!("Scrolling without mouse in window; this shouldn't be possible"); + log::warn!("Scrolling without mouse in window; this shouldn't be possible"); } } WindowEvent::CursorLeft { .. } => { @@ -469,7 +466,7 @@ fn run( return; }; let device_handle = &render_cx.devices[render_state.surface.dev_id]; - eprintln!("==============\nReloading shaders"); + log::info!("==============\nReloading shaders"); let start = Instant::now(); let result = renderers[render_state.surface.dev_id] .as_mut() @@ -477,13 +474,13 @@ fn run( .reload_shaders(&device_handle.device); // We know that the only async here (`pop_error_scope`) is actually sync, so blocking is fine match pollster::block_on(result) { - Ok(_) => eprintln!("Reloading took {:?}", start.elapsed()), - Err(e) => eprintln!("Failed to reload shaders because of {e}"), + Ok(_) => log::info!("Shaders reloaded. Took {:?}", start.elapsed()), + Err(e) => log::error!("Failed to reload shaders because of {e}"), } } }, Event::Suspended => { - eprintln!("Suspending"); + log::info!("Suspending"); #[cfg(not(target_arch = "wasm32"))] // When we suspend, we need to remove the `wgpu` Surface if let Some(render_state) = render_state.take() { @@ -501,7 +498,9 @@ fn run( .take() .unwrap_or_else(|| create_window(_event_loop)); let size = window.inner_size(); + log::debug!("Creating surface"); let surface_future = render_cx.create_surface(&window, size.width, size.height); + log::debug!("Created surface"); // We need to block here, in case a Suspended event appeared let surface = pollster::block_on(surface_future).expect("Error creating surface"); render_state = { @@ -509,17 +508,20 @@ fn run( renderers.resize_with(render_cx.devices.len(), || None); let id = render_state.surface.dev_id; renderers[id].get_or_insert_with(|| { - eprintln!("Creating renderer {id}"); - Renderer::new( + log::debug!("Creating renderer {id}"); + let renderer = Renderer::new( &render_cx.devices[id].device, RendererOptions { surface_format: Some(render_state.surface.format), use_cpu, - antialiasing_support: vello::AaSupport::all(), + antialiasing_support: vello::AaSupport::area_only(), }, ) - .expect("Could create renderer") + .expect("Could create renderer"); + log::debug!("Created renderer {id}"); + renderer }); + Some(render_state) }; *control_flow = ControlFlow::Poll; @@ -566,11 +568,14 @@ fn display_error_message() -> Option<()> { Some(()) } -pub fn main() -> Result<()> { +#[cfg(not(target_os = "android"))] +pub fn main() -> anyhow::Result<()> { // TODO: initializing both env_logger and console_logger fails on wasm. // Figure out a more principled approach. #[cfg(not(target_arch = "wasm32"))] - env_logger::init(); + env_logger::builder() + .format_timestamp(Some(env_logger::TimestampPrecision::Millis)) + .init(); let args = Args::parse(); let scenes = args.args.select_scene_set(Args::command)?; if let Some(scenes) = scenes { @@ -579,9 +584,7 @@ pub fn main() -> Result<()> { let mut render_cx = RenderContext::new().unwrap(); #[cfg(not(target_arch = "wasm32"))] { - #[cfg(not(target_os = "android"))] let proxy = event_loop.create_proxy(); - #[cfg(not(target_os = "android"))] let _keep = hot_reload::hot_reload(move || { proxy.send_event(UserEvent::HotReload).ok().map(drop) }); @@ -631,14 +634,31 @@ use winit::platform::android::activity::AndroidApp; fn android_main(app: AndroidApp) { use winit::platform::android::EventLoopBuilderExtAndroid; - android_logger::init_once( - android_logger::Config::default().with_max_level(log::LevelFilter::Warn), - ); + let config = android_logger::Config::default(); + // We allow configuring the Android logging with an environment variable at build time + let config = if let Some(logging_config) = option_env!("VELLO_STATIC_LOG") { + let mut filter = env_logger::filter::Builder::new(); + filter.filter_level(log::LevelFilter::Warn); + filter.parse(logging_config); + let filter = filter.build(); + // This shouldn't be needed in theory, but without this the max + // level is set to 0 (i.e. Off) + let config = config.with_max_level(filter.filter()); + config.with_filter(filter) + } else { + config.with_max_level(log::LevelFilter::Warn) + }; + android_logger::init_once(config); let event_loop = EventLoopBuilder::with_user_event() .with_android_app(app) .build(); - let args = Args::parse(); + let args = if let Some(args) = option_env!("VELLO_STATIC_ARGS") { + // We split by whitespace here to allow + Args::parse_from(args.split_ascii_whitespace()) + } else { + Args::parse() + }; let scenes = args .args .select_scene_set(|| Args::command()) diff --git a/src/shaders.rs b/src/shaders.rs index 90d55cd9a..183751b4f 100644 --- a/src/shaders.rs +++ b/src/shaders.rs @@ -92,6 +92,8 @@ pub fn full_shaders( engine: &mut WgpuEngine, options: &RendererOptions, ) -> Result { + use std::time::Instant; + use crate::wgpu_engine::CpuShaderType; use BindType::*; let imports = SHARED_SHADERS @@ -108,6 +110,7 @@ pub fn full_shaders( let mut force_gpu = false; let force_gpu_from: Option<&str> = None; + let mut previous_done = Instant::now(); // Uncomment this to force use of GPU shaders from the specified shader and later even // if `engine.use_cpu` is specified. @@ -118,17 +121,29 @@ pub fn full_shaders( if force_gpu_from == Some(stringify!($name)) { force_gpu = true; } - engine.add_shader( + let processed = + preprocess::preprocess(shader!(stringify!($name)), &$defines, &imports).into(); + // Preprocessing is very quick, so we don't need to take this time into account + // log::debug!( + // "Pre-processing {} took {:?}", + // $label, + // previous_done.elapsed() + // ); + let shader = engine.add_shader( device, $label, - preprocess::preprocess(shader!(stringify!($name)), &$defines, &imports).into(), + processed, &$bindings, if force_gpu { CpuShaderType::Missing } else { $cpu }, - )? + )?; + let now = Instant::now(); + log::debug!("Processing {} took {:?}", $label, now - previous_done); + previous_done = now; + shader }}; ($name:ident, $bindings:expr, $defines:expr, $cpu:expr) => {{ add_shader!($name, stringify!($name), $bindings, &$defines, $cpu) diff --git a/src/wgpu_engine.rs b/src/wgpu_engine.rs index 3ae8a3fba..f8f032f4b 100644 --- a/src/wgpu_engine.rs +++ b/src/wgpu_engine.rs @@ -5,6 +5,7 @@ use std::{ borrow::Cow, cell::RefCell, collections::{hash_map::Entry, HashMap, HashSet}, + time::Instant, }; use wgpu::{ @@ -172,11 +173,18 @@ impl WgpuEngine { CpuShaderType::Missing => {} } } - + log::debug!("Compiling shader {label}"); + let mut previous_done = Instant::now(); let shader_module = device.create_shader_module(wgpu::ShaderModuleDescriptor { label: Some(label), source: wgpu::ShaderSource::Wgsl(wgsl), }); + let now = Instant::now(); + log::debug!( + "Shader finished compiling in {:?} ({label})", + now - previous_done + ); + previous_done = now; let entries = layout .iter() .enumerate() @@ -229,18 +237,30 @@ impl WgpuEngine { label: None, entries: &entries, }); + log::debug!( + "Bind group layout created in {:?} ({label})", + now - previous_done + ); let compute_pipeline_layout = device.create_pipeline_layout(&wgpu::PipelineLayoutDescriptor { label: None, bind_group_layouts: &[&bind_group_layout], push_constant_ranges: &[], }); + let now = Instant::now(); + log::debug!( + "Pipeline layout created in {:?} ({label})", + now - previous_done + ); + previous_done = now; let pipeline = device.create_compute_pipeline(&wgpu::ComputePipelineDescriptor { label: Some(label), layout: Some(&compute_pipeline_layout), module: &shader_module, entry_point: "main", }); + let now = Instant::now(); + log::debug!("Pipeline created in {:?} ({label})", now - previous_done); add(Shader { wgpu: Some(WgpuShader { pipeline,