Add debugging to surface bottlenecks and performance issues

Signed-off-by: Matt Butcher <matt.butcher@fermyon.com>

src/handlers.rs

@@ -104,6 +104,7 @@ impl WasmRouteHandler {
     }
 
     fn prepare_wasm_instance(&self, global_context: &RequestGlobalContext, ctx: WasiCtx) -> Result<(Store<WasiCtx>, Instance), Error> {
+        debug!("Preparing Wasm instance.");
         let link_options = WasmLinkOptions::default()
             .with_http(self.allowed_hosts.clone(), self.http_max_concurrency);
         prepare_wasm_instance(global_context, ctx, &self.wasm_module_source, link_options)
@@ -119,7 +120,7 @@ pub fn compose_response(stdout_mutex: Arc<RwLock<Vec<u8>>>) -> Result<Response<B
     // looking for the double-newline that distinguishes the headers from the body.
     // The headers can then be parsed separately, while the body can be sent back
     // to the client.
-
+    debug!("composing response");
     let out = stdout_mutex.read().unwrap();
     let mut last = 0;
     let mut scan_headers = true;
@@ -192,5 +193,6 @@ pub fn compose_response(stdout_mutex: Arc<RwLock<Vec<u8>>>) -> Result<Response<B
             "Exactly one of 'location' or 'content-type' must be specified",
         ));
     }
+    debug!("Response successfully sent");
     Ok(res)
 }

src/wasm_runner.rs

@@ -5,6 +5,8 @@ use wasi_common::pipe::{ReadPipe, WritePipe};
 use wasmtime::*;
 use wasmtime_wasi::*;
 
+use tracing::debug;
+
 use crate::request::RequestGlobalContext;
 use crate::wasm_module::WasmModuleSource;
 
@@ -102,13 +104,16 @@ pub fn prepare_wasm_instance(
     wasm_module_source: &WasmModuleSource,
     link_options: WasmLinkOptions,
 ) -> Result<(Store<WasiCtx>, Instance), Error> {
+    debug!("Creating store, engine, and linker.");
     let (mut store, engine) = new_store_and_engine(&global_context.cache_config_path, ctx)?;
     let mut linker = Linker::new(&engine);
     wasmtime_wasi::add_to_linker(&mut linker, |cx| cx)?;
 
     link_options.apply_to(&mut linker)?;
 
+    debug!("loading module from store");
     let module = wasm_module_source.load_module(&store)?;
+    debug!("instantiating module in linker");
     let instance = linker.instantiate(&mut store, &module)?;
     Ok((store, instance))
 }
@@ -124,6 +129,7 @@ pub fn run_prepared_wasm_instance(
     })?;
     tracing::trace!("Calling Wasm entry point");
     start.call(&mut store, &[], &mut vec![])?;
+    tracing::trace!("Module execution complete");
     Ok(())
 }