Add logging to canary crate

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"

src/backend/mod.rs

@@ -19,11 +19,13 @@ pub mod wasmtime;
 /// Currently, only ever creates [wasmtime::WasmtimeBackend].
 pub fn make_default_backend() -> anyhow::Result<Box<dyn Backend>> {
     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<ScriptAbi>, module: &[u8]) -> anyhow::Result<Arc<dyn Instance>>;
 }
 

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<Self> {
+        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<ScriptAbi>, module: &[u8]) -> anyhow::Result<Arc<dyn Instance>> {
+        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)
     }
 }

src/lib.rs

@@ -21,6 +21,8 @@ pub struct Runtime {
 
 impl Runtime {
     pub fn new(backend: Box<dyn Backend>) -> anyhow::Result<Self> {
+        log::info!("Initializing runtime with {} backend", backend.name());
+
         Ok(Self {
             backend,
             font_store: Arc::new(FontStore::new()),

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,