From b9416b922ff58c8a730d1d13e0968be719a175c2 Mon Sep 17 00:00:00 2001 From: mars Date: Mon, 5 Dec 2022 20:59:52 -0700 Subject: [PATCH 1/5] Add env_logger to Magpie --- apps/magpie/Cargo.toml | 4 +++- apps/magpie/src/main.rs | 1 + 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/apps/magpie/Cargo.toml b/apps/magpie/Cargo.toml index 37e72e8..e8f45be 100644 --- a/apps/magpie/Cargo.toml +++ b/apps/magpie/Cargo.toml @@ -13,8 +13,10 @@ required-features = ["service"] anyhow = { version = "1", optional = true } byteorder = "1.4" canary = { path = "../..", optional = true } +env_logger = { version = "0.10", optional = true } futures-util = { version = "0.3", optional = true, features = ["io"] } glium = { version = "0.32", optional = true} +log = "0.4" mio = { version = "0.8", features = ["net", "os-poll"], optional = true } mio-signals = { version = "0.2", optional = true } parking_lot = { version = "0.12", optional = true} @@ -24,4 +26,4 @@ slab = { version = "0.4", optional = true} [features] async = ["dep:futures-util"] -service = ["dep:anyhow", "dep:canary", "dep:glium", "dep:mio", "dep:mio-signals", "dep:parking_lot", "dep:slab"] +service = ["dep:anyhow", "dep:canary", "dep:env_logger", "dep:glium", "dep:mio", "dep:mio-signals", "dep:parking_lot", "dep:slab"] diff --git a/apps/magpie/src/main.rs b/apps/magpie/src/main.rs index 372dd9c..cfbd810 100644 --- a/apps/magpie/src/main.rs +++ b/apps/magpie/src/main.rs @@ -8,6 +8,7 @@ use ipc::Ipc; use window::{WindowMessage, WindowStore}; fn main() -> std::io::Result<()> { + env_logger::init(); let event_loop = EventLoopBuilder::::with_user_event().build(); let window_sender = event_loop.create_proxy(); let (ipc, ipc_sender) = Ipc::new(window_sender)?; From 03e596b2191c872204194e141b24e881e230fb4d Mon Sep 17 00:00:00 2001 From: mars Date: Mon, 5 Dec 2022 21:17:19 -0700 Subject: [PATCH 2/5] Add logging to canary crate --- Cargo.toml | 1 + src/backend/mod.rs | 2 ++ src/backend/wasmtime.rs | 22 ++++++++++++++++++++++ src/lib.rs | 2 ++ src/text/mod.rs | 5 +++-- 5 files changed, 30 insertions(+), 2 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 354eb52..8472e7e 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -20,6 +20,7 @@ allsorts = "0.10" anyhow = "1" bytemuck = "1" canary-script = { path = "crates/script" } +log = "0.4" lyon = "1" ouroboros = "^0.15" parking_lot = "0.12" diff --git a/src/backend/mod.rs b/src/backend/mod.rs index aa2c1d1..40209ee 100644 --- a/src/backend/mod.rs +++ b/src/backend/mod.rs @@ -19,11 +19,13 @@ pub mod wasmtime; /// Currently, only ever creates [wasmtime::WasmtimeBackend]. pub fn make_default_backend() -> anyhow::Result> { let backend = wasmtime::WasmtimeBackend::new()?; + log::info!("Created default ({}) backend", backend.name()); Ok(Box::new(backend)) } /// A WebAssembly runtime backend. pub trait Backend { + fn name(&self) -> &'static str; fn load_module(&self, abi: Arc, module: &[u8]) -> anyhow::Result>; } diff --git a/src/backend/wasmtime.rs b/src/backend/wasmtime.rs index db4f831..225fa07 100644 --- a/src/backend/wasmtime.rs +++ b/src/backend/wasmtime.rs @@ -4,6 +4,7 @@ use std::collections::{hash_map::DefaultHasher, HashMap}; use std::hash::Hasher; use std::ops::DerefMut; +use std::time::Instant; use super::{Arc, Backend, Instance, PanelId, ScriptAbi}; use crate::DrawCommand; @@ -24,6 +25,8 @@ pub struct WasmtimeBackend { impl WasmtimeBackend { pub fn new() -> anyhow::Result { + log::info!("Creating wasmtime backend"); + let mut config = wasmtime::Config::new(); config.wasm_simd(true); config.wasm_bulk_memory(true); @@ -40,20 +43,33 @@ impl WasmtimeBackend { } impl Backend for WasmtimeBackend { + fn name(&self) -> &'static str { + "wasmtime" + } + fn load_module(&self, abi: Arc, module: &[u8]) -> anyhow::Result> { + let start = Instant::now(); + let mut hasher = DefaultHasher::new(); hasher.write(module); let hashed = hasher.finish(); + let fmt_hash = format!("{:x}", hashed); + + log::debug!("Loading module (hash: {})", fmt_hash); let prehasher = DefaultPrehasher::new(); let prehashed = prehasher.prehash(hashed); let mut cache = self.module_cache.lock(); let module = if let Some(module) = cache.get(&prehashed) { + log::debug!("Module load cache hit (hash: {})", fmt_hash); module } else { + log::debug!("Module load cache miss; building (hash: {})", fmt_hash); + let start = Instant::now(); let module = wasmtime::Module::new(&self.engine, module)?; cache.insert(prehashed, module); + log::debug!("Built module in {:?} (hash: {})", start.elapsed(), fmt_hash); cache.get(&prehashed).unwrap() }; @@ -80,6 +96,12 @@ impl Backend for WasmtimeBackend { let instance = Arc::new(instance); + log::debug!( + "Loaded module in {:?} (hash: {})", + start.elapsed(), + fmt_hash + ); + Ok(instance) } } diff --git a/src/lib.rs b/src/lib.rs index 02cea3f..29de67e 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -21,6 +21,8 @@ pub struct Runtime { impl Runtime { pub fn new(backend: Box) -> anyhow::Result { + log::info!("Initializing runtime with {} backend", backend.name()); + Ok(Self { backend, font_store: Arc::new(FontStore::new()), diff --git a/src/text/mod.rs b/src/text/mod.rs index b51366c..6bb0814 100644 --- a/src/text/mod.rs +++ b/src/text/mod.rs @@ -220,6 +220,7 @@ impl Default for FontStore { impl FontStore { pub fn new() -> Self { + log::info!("Initializing FontStore"); let source = font_kit::source::SystemSource::new(); let source = Box::new(source); @@ -241,14 +242,14 @@ impl FontStore { use font_kit::handle::Handle; use font_kit::properties::Properties; - println!("loading font family {}", title); + log::info!("Finding font by family: {}", title); let font_handle = self .source .select_best_match(&[FamilyName::Title(title.to_string())], &Properties::new()) .unwrap(); - println!("loading font file: {:?}", font_handle); + log::info!("Loading font file: {:?}", font_handle); let font_data = if let Handle::Path { path, From 4b46142f9043ce27adb77a34f364b5903bf35b3e Mon Sep 17 00:00:00 2001 From: mars Date: Mon, 5 Dec 2022 21:26:05 -0700 Subject: [PATCH 3/5] Fix use of prehash so that the RAM cache actually hits --- src/backend/wasmtime.rs | 19 ++++++++----------- 1 file changed, 8 insertions(+), 11 deletions(-) diff --git a/src/backend/wasmtime.rs b/src/backend/wasmtime.rs index 225fa07..a2bd075 100644 --- a/src/backend/wasmtime.rs +++ b/src/backend/wasmtime.rs @@ -2,7 +2,7 @@ // SPDX-License-Identifier: LGPL-3.0-or-later use std::collections::{hash_map::DefaultHasher, HashMap}; -use std::hash::Hasher; +use std::hash::{Hasher, BuildHasherDefault}; use std::ops::DerefMut; use std::time::Instant; @@ -11,12 +11,12 @@ use crate::DrawCommand; use canary_script::{Color, CursorEventKind, Rect, Vec2}; use parking_lot::Mutex; -use prehash::{DefaultPrehasher, Prehashed, Prehasher}; +use prehash::Passthru; type Caller<'a> = wasmtime::Caller<'a, Arc>; type Store = wasmtime::Store>; type Linker = wasmtime::Linker>; -type ModuleCache = Mutex, wasmtime::Module, DefaultPrehasher>>; +type ModuleCache = Mutex>>; pub struct WasmtimeBackend { engine: wasmtime::Engine, @@ -52,25 +52,22 @@ impl Backend for WasmtimeBackend { let mut hasher = DefaultHasher::new(); hasher.write(module); - let hashed = hasher.finish(); - let fmt_hash = format!("{:x}", hashed); + let hash = hasher.finish(); + let fmt_hash = format!("{:x}", hash); log::debug!("Loading module (hash: {})", fmt_hash); - - let prehasher = DefaultPrehasher::new(); - let prehashed = prehasher.prehash(hashed); let mut cache = self.module_cache.lock(); - let module = if let Some(module) = cache.get(&prehashed) { + let module = if let Some(module) = cache.get(&hash) { log::debug!("Module load cache hit (hash: {})", fmt_hash); module } else { log::debug!("Module load cache miss; building (hash: {})", fmt_hash); let start = Instant::now(); let module = wasmtime::Module::new(&self.engine, module)?; - cache.insert(prehashed, module); + cache.insert(hash, module); log::debug!("Built module in {:?} (hash: {})", start.elapsed(), fmt_hash); - cache.get(&prehashed).unwrap() + cache.get(&hash).unwrap() }; let mut store = wasmtime::Store::new(&self.engine, abi); From ae7271a479e6d44a1f02fdb6be12448f24dd2869 Mon Sep 17 00:00:00 2001 From: mars Date: Mon, 5 Dec 2022 21:53:38 -0700 Subject: [PATCH 4/5] Add logging macros to Magpie --- apps/magpie/src/main.rs | 1 + apps/magpie/src/protocol.rs | 2 -- apps/magpie/src/service/ipc.rs | 25 +++++++++++++------------ apps/magpie/src/service/window.rs | 8 ++++++-- 4 files changed, 20 insertions(+), 16 deletions(-) diff --git a/apps/magpie/src/main.rs b/apps/magpie/src/main.rs index cfbd810..f4af851 100644 --- a/apps/magpie/src/main.rs +++ b/apps/magpie/src/main.rs @@ -9,6 +9,7 @@ use window::{WindowMessage, WindowStore}; fn main() -> std::io::Result<()> { env_logger::init(); + log::info!("Initializing Magpie..."); let event_loop = EventLoopBuilder::::with_user_event().build(); let window_sender = event_loop.create_proxy(); let (ipc, ipc_sender) = Ipc::new(window_sender)?; diff --git a/apps/magpie/src/protocol.rs b/apps/magpie/src/protocol.rs index eacf451..5aedc03 100644 --- a/apps/magpie/src/protocol.rs +++ b/apps/magpie/src/protocol.rs @@ -63,7 +63,6 @@ pub type ClientMessenger = Messenger; impl ClientMessenger { pub fn send_panel_json(&mut self, id: PanelId, msg: &O) { let msg = serde_json::to_string(msg).unwrap(); - eprintln!("Sending message: {:?}", msg); let _ = self.send(&MagpieServerMsg::SendMessage(SendMessage { id, @@ -220,7 +219,6 @@ mod async_messages { impl ClientMessenger { pub async fn send_panel_json_async(&mut self, id: PanelId, msg: &O) { let msg = serde_json::to_string(msg).unwrap(); - eprintln!("Sending message: {:?}", msg); let _ = self .send_async(&MagpieServerMsg::SendMessage(SendMessage { diff --git a/apps/magpie/src/service/ipc.rs b/apps/magpie/src/service/ipc.rs index ad9dce2..0da73cb 100644 --- a/apps/magpie/src/service/ipc.rs +++ b/apps/magpie/src/service/ipc.rs @@ -47,7 +47,7 @@ impl Drop for Listener { fn drop(&mut self) { match std::fs::remove_file(&self.path) { Ok(_) => {} - Err(e) => eprintln!("Could not delete UnixListener {:?}", e), + Err(e) => log::error!("Could not delete UnixListener {:?}", e), } } } @@ -75,20 +75,20 @@ impl Listener { use std::io::{Error, ErrorKind}; match UnixStream::connect(&sock_path) { Ok(_) => { - eprintln!("Socket is already in use. Another instance of Magpie may be running."); + log::warn!("Socket is already in use. Another instance of Magpie may be running."); let kind = ErrorKind::AddrInUse; let error = Error::new(kind, "Socket is already in use."); return Err(error); } Err(ref err) if err.kind() == ErrorKind::ConnectionRefused => { - eprintln!("Found leftover socket; removing."); + log::warn!("Found leftover socket; removing."); std::fs::remove_file(&sock_path)?; } Err(ref err) if err.kind() == ErrorKind::NotFound => {} Err(err) => return Err(err), } - eprintln!("Making socket at: {:?}", sock_path); + log::info!("Making socket at: {:?}", sock_path); let uds = UnixListener::bind(&sock_path)?; let path = sock_path.to_path_buf(); Ok(Self { uds, path }) @@ -120,11 +120,11 @@ pub struct Client { impl Client { pub fn on_readable(&mut self) -> std::io::Result { if let Err(err) = self.messenger.flush_recv() { - eprintln!("flush_recv() error: {:?}", err); + log::error!("flush_recv() error: {:?}", err); } while let Some(msg) = self.messenger.try_recv() { - println!("Client #{}: {:?}", self.token.0, msg); + log::debug!("Client #{}: {:?}", self.token.0, msg); match msg { MagpieServerMsg::CreatePanel(CreatePanel { id, @@ -162,7 +162,7 @@ impl Client { } pub fn disconnect(mut self) { - println!("Client #{} disconnected", self.token.0); + log::info!("Client #{} disconnected", self.token.0); let mut transport = self.messenger.into_transport(); let mut data = self.data.write(); @@ -262,9 +262,10 @@ impl Ipc { match self.listener.accept() { Ok((mut connection, address)) => { let token = Token(self.clients.vacant_key()); - println!( + log::info!( "Accepting connection (Client #{}) from {:?}", - token.0, address + token.0, + address ); let interest = Interest::READABLE; @@ -288,7 +289,7 @@ impl Ipc { } } else if event.token() == self.signals_token { while let Some(received) = self.signals.receive()? { - eprintln!("Received {:?} signal; exiting...", received); + log::info!("Received {:?} signal; exiting...", received); let _ = self.window_sender.send_event(WindowMessage::Quit); self.quit = true; } @@ -302,7 +303,7 @@ impl Ipc { self.clients.remove(event.token().0).disconnect(); } } else { - eprintln!("Unrecognized event token: {:?}", event); + log::error!("Unrecognized event token: {:?}", event); } } @@ -316,7 +317,7 @@ impl Ipc { match self.poll(&mut events, Some(wait)) { Ok(_) => {} Err(e) => { - eprintln!("IPC poll error: {:?}", e); + log::error!("IPC poll error: {:?}", e); } } } diff --git a/apps/magpie/src/service/window.rs b/apps/magpie/src/service/window.rs index fd41d39..0e9229e 100644 --- a/apps/magpie/src/service/window.rs +++ b/apps/magpie/src/service/window.rs @@ -195,14 +195,18 @@ impl WindowStore { protocol, script, } => { - println!("Opening window {} with script {:?}", id, script); + log::debug!("Opening window {} with script {:?}...", id, script); + let start = std::time::Instant::now(); let module = std::fs::read(script)?; let mut script = self.runtime.load_module(&module)?; + log::debug!("Instantiated window {} script in {:?}", id, start.elapsed()); let panel = script.create_panel(&protocol, vec![])?; + log::debug!("Created window {} panel in {:?}", id, start.elapsed()); let window = Window::new(self.ipc_sender.to_owned(), id, panel, &event_loop)?; let window_id = window.get_id(); self.windows.insert(window_id, window); self.ipc_to_window.insert(id, window_id); + log::debug!("Opened window {} in {:?}", id, start.elapsed()); } WindowMessage::CloseWindow { id } => { if let Some(window_id) = self.ipc_to_window.remove(&id) { @@ -242,7 +246,7 @@ impl WindowStore { Ok(false) => {} Ok(true) => *control_flow = ControlFlow::Exit, Err(err) => { - eprintln!("Error while handling message {:?}:\n{}", event, err); + log::error!("Error while handling message {:?}:\n{}", event, err); } }, _ => {} From c58ca051f48bedf1bac94680bc0cedce6af91b0e Mon Sep 17 00:00:00 2001 From: mars Date: Tue, 6 Dec 2022 16:25:36 -0700 Subject: [PATCH 5/5] Magpie logs info and up by default --- apps/magpie/src/main.rs | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/apps/magpie/src/main.rs b/apps/magpie/src/main.rs index f4af851..a477324 100644 --- a/apps/magpie/src/main.rs +++ b/apps/magpie/src/main.rs @@ -8,7 +8,11 @@ use ipc::Ipc; use window::{WindowMessage, WindowStore}; fn main() -> std::io::Result<()> { - env_logger::init(); + env_logger::Builder::new() + .filter(None, log::LevelFilter::Info) // By default logs all info messages. + .parse_default_env() + .init(); + log::info!("Initializing Magpie..."); let event_loop = EventLoopBuilder::::with_user_event().build(); let window_sender = event_loop.create_proxy();