From 8acd62a0c3edcf89e2041f0264607102dbca0a22 Mon Sep 17 00:00:00 2001
From: Michael-F-Bryan <michael@wasmer.io>
Date: Thu, 22 Jun 2023 21:12:13 +0800
Subject: [PATCH 1/3] Add "Cache hit!" log messages to each of the module cache
 implementations

---
 lib/wasix/src/runtime/module_cache/filesystem.rs  |  7 ++++++-
 lib/wasix/src/runtime/module_cache/shared.rs      | 15 +++++++++++----
 .../src/runtime/module_cache/thread_local.rs      | 11 +++++++++--
 3 files changed, 26 insertions(+), 7 deletions(-)

diff --git a/lib/wasix/src/runtime/module_cache/filesystem.rs b/lib/wasix/src/runtime/module_cache/filesystem.rs
index 438c237ac9a..4fc685dd6e7 100644
--- a/lib/wasix/src/runtime/module_cache/filesystem.rs
+++ b/lib/wasix/src/runtime/module_cache/filesystem.rs
@@ -34,6 +34,7 @@ impl FileSystemCache {
 
 #[async_trait::async_trait]
 impl ModuleCache for FileSystemCache {
+    #[tracing::instrument(level = "debug", skip_all, fields(%key))]
     async fn load(&self, key: ModuleHash, engine: &Engine) -> Result<Module, CacheError> {
         let path = self.path(key, engine.deterministic_id());
 
@@ -46,7 +47,10 @@ impl ModuleCache for FileSystemCache {
 
         let res = unsafe { Module::deserialize(&engine, uncompressed) };
         match res {
-            Ok(m) => Ok(m),
+            Ok(m) => {
+                tracing::debug!("Cache hit!");
+                Ok(m)
+            }
             Err(e) => {
                 tracing::debug!(
                     %key,
@@ -69,6 +73,7 @@ impl ModuleCache for FileSystemCache {
         }
     }
 
+    #[tracing::instrument(level = "debug", skip_all, fields(%key))]
     async fn save(
         &self,
         key: ModuleHash,
diff --git a/lib/wasix/src/runtime/module_cache/shared.rs b/lib/wasix/src/runtime/module_cache/shared.rs
index cec47cfde0b..012faf36983 100644
--- a/lib/wasix/src/runtime/module_cache/shared.rs
+++ b/lib/wasix/src/runtime/module_cache/shared.rs
@@ -17,14 +17,21 @@ impl SharedCache {
 
 #[async_trait::async_trait]
 impl ModuleCache for SharedCache {
+    #[tracing::instrument(level = "debug", skip_all, fields(%key))]
     async fn load(&self, key: ModuleHash, engine: &Engine) -> Result<Module, CacheError> {
         let key = (key, engine.deterministic_id().to_string());
-        self.modules
-            .get(&key)
-            .map(|m| m.value().clone())
-            .ok_or(CacheError::NotFound)
+
+        match self.modules.get(&key) {
+            Some(m) => {
+                tracing::debug!("Cache hit!");
+                Ok(m.value().clone())
+            }
+
+            None => Err(CacheError::NotFound),
+        }
     }
 
+    #[tracing::instrument(level = "debug", skip_all, fields(%key))]
     async fn save(
         &self,
         key: ModuleHash,
diff --git a/lib/wasix/src/runtime/module_cache/thread_local.rs b/lib/wasix/src/runtime/module_cache/thread_local.rs
index ca8abf3d430..e4ff8cf88b6 100644
--- a/lib/wasix/src/runtime/module_cache/thread_local.rs
+++ b/lib/wasix/src/runtime/module_cache/thread_local.rs
@@ -28,11 +28,18 @@ impl ThreadLocalCache {
 
 #[async_trait::async_trait]
 impl ModuleCache for ThreadLocalCache {
+    #[tracing::instrument(level = "debug", skip_all, fields(%key))]
     async fn load(&self, key: ModuleHash, engine: &Engine) -> Result<Module, CacheError> {
-        self.lookup(key, engine.deterministic_id())
-            .ok_or(CacheError::NotFound)
+        match self.lookup(key, engine.deterministic_id()) {
+            Some(m) => {
+                tracing::debug!("Cache hit!");
+                Ok(m)
+            }
+            None => Err(CacheError::NotFound),
+        }
     }
 
+    #[tracing::instrument(level = "debug", skip_all, fields(%key))]
     async fn save(
         &self,
         key: ModuleHash,

From 4b772eca42e0802376eff807bca0c1306edf4cc6 Mon Sep 17 00:00:00 2001
From: Michael-F-Bryan <michael@wasmer.io>
Date: Thu, 22 Jun 2023 21:12:36 +0800
Subject: [PATCH 2/3] Make sure we save a compiled *.wasm after compiling it

---
 lib/cli/src/commands/run.rs | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/lib/cli/src/commands/run.rs b/lib/cli/src/commands/run.rs
index c48f28cfe82..a0f7d37cb70 100644
--- a/lib/cli/src/commands/run.rs
+++ b/lib/cli/src/commands/run.rs
@@ -585,8 +585,12 @@ impl ExecutableTarget {
                             );
                         }
 
-                        Module::new(&engine, &wasm)
-                            .with_context(|| format!("Unable to compile \"{}\"", path.display()))?
+                        let module = Module::new(&engine, &wasm)
+                            .with_context(|| format!("Unable to compile \"{}\"", path.display()))?;
+
+                        tasks.block_on(module_cache.save(module_hash, &engine, &module))?;
+
+                        module
                     }
                 };
 

From ebe590ea2b49b2ad1cf36d5f40055023a4593232 Mon Sep 17 00:00:00 2001
From: Michael-F-Bryan <michael@wasmer.io>
Date: Thu, 22 Jun 2023 21:24:47 +0800
Subject: [PATCH 3/3] Wrapped the compilation step in its own span for timing
 purposes

---
 lib/cli/src/commands/run.rs | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/lib/cli/src/commands/run.rs b/lib/cli/src/commands/run.rs
index a0f7d37cb70..fc52814bc92 100644
--- a/lib/cli/src/commands/run.rs
+++ b/lib/cli/src/commands/run.rs
@@ -585,7 +585,8 @@ impl ExecutableTarget {
                             );
                         }
 
-                        let module = Module::new(&engine, &wasm)
+                        let module = tracing::debug_span!("compiling_wasm")
+                            .in_scope(|| Module::new(&engine, &wasm))
                             .with_context(|| format!("Unable to compile \"{}\"", path.display()))?;
 
                         tasks.block_on(module_cache.save(module_hash, &engine, &module))?;