chore: Small tracing log improvements for wasix

Add some additional trace logs and information in journal restore and
thread spawning.

lib/wasix/src/journal/effector/save_event.rs

@@ -10,6 +10,8 @@ impl JournalEffector {
             return Ok(());
         }
 
+        tracing::trace!(?event, "saving journal event");
+
         ctx.data()
             .active_journal()?
             .write(event)

lib/wasix/src/os/task/thread.rs

@@ -107,6 +107,10 @@ pub struct WasiThread {
 }
 
 impl WasiThread {
+    pub fn id(&self) -> WasiThreadId {
+        self.state.id
+    }
+
     /// Sets that a rewind will take place
     pub(crate) fn set_rewind(&mut self, rewind: RewindResult) {
         self.rewind.replace(rewind);

lib/wasix/src/state/func_env.rs

@@ -290,10 +290,13 @@ impl WasiFunctionEnv {
     ///
     #[allow(clippy::result_large_err)]
     #[allow(unused_variables, unused_mut)]
+    #[tracing::instrument(skip_all)]
     pub unsafe fn bootstrap(
         &self,
         mut store: &'_ mut impl AsStoreMut,
     ) -> Result<RewindStateOption, WasiRuntimeError> {
+        tracing::debug!("bootstrap start");
+
         #[allow(unused_mut)]
         let mut rewind_state = None;
 
@@ -357,6 +360,8 @@ impl WasiFunctionEnv {
             }
         }
 
+        tracing::debug!("bootstrap complete");
+
         Ok(rewind_state)
     }
 }

lib/wasix/src/syscalls/journal/restore_snapshot.rs

@@ -3,8 +3,9 @@ use super::*;
 /// Safety: This function manipulates the memory of the process and thus must
 /// be executed by the WASM process thread itself.
 ///
-#[allow(clippy::result_large_err)]
 #[cfg(feature = "journal")]
+#[allow(clippy::result_large_err)]
+#[tracing::instrument(skip_all)]
 pub unsafe fn restore_snapshot(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     journal: Arc<DynJournal>,
@@ -20,15 +21,17 @@ pub unsafe fn restore_snapshot(
     // We read all the logs from the journal into the state machine
     let mut ethereal_events = Vec::new();
     while let Some(next) = journal.read().map_err(anyhow_err_to_runtime_err)? {
+        tracing::trace!(event=?next, "restoring event");
         runner.play_event(next.into_inner(), Some(&mut ethereal_events));
     }
 
     // Check for events that are orphaned
     for evt in ethereal_events {
-        tracing::debug!("Orphaned ethereal events - {:?}", evt);
+        tracing::trace!("Orphaned ethereal events - {:?}", evt);
     }
 
     // Now output the stdout and stderr
+    tracing::trace!("replaying stdout");
     for (offset, data, is_64bit) in runner.stdout {
         if is_64bit {
             JournalEffector::apply_fd_write::<Memory64>(&runner.ctx, 1, offset, data)
@@ -38,6 +41,7 @@ pub unsafe fn restore_snapshot(
         .map_err(anyhow_err_to_runtime_err)?;
     }
 
+    tracing::trace!("replaying stdout");
     for (offset, data, is_64bit) in runner.stderr {
         if is_64bit {
             JournalEffector::apply_fd_write::<Memory64>(&runner.ctx, 2, offset, data)
@@ -59,7 +63,11 @@ pub unsafe fn restore_snapshot(
     }
 
     // Spawn all the threads
-    for (thread_id, thread_state) in runner.spawn_threads {
+    let thread_count = runner.spawn_threads.len();
+    tracing::trace!(thread_count, "restoring threads");
+    for (index, (thread_id, thread_state)) in runner.spawn_threads.into_iter().enumerate() {
+        tracing::trace!("restoring thread {}/{}", index + 1, thread_count);
+
         if thread_state.is_64bit {
             JournalEffector::apply_thread_state::<Memory64>(
                 &mut runner.ctx,
@@ -84,6 +92,7 @@ pub unsafe fn restore_snapshot(
             .map_err(anyhow_err_to_runtime_err)?;
         }
     }
+    tracing::debug!(thread_count, "snapshot restore complete");
 
     Ok(runner.rewind)
 }

lib/wasix/src/syscalls/wasix/thread_exit.rs

@@ -12,6 +12,6 @@ use crate::syscalls::*;
 /// * `rval` - The exit code returned by the process.
 #[instrument(level = "debug", skip_all, fields(%exitcode), ret)]
 pub fn thread_exit(ctx: FunctionEnvMut<'_, WasiEnv>, exitcode: ExitCode) -> Result<(), WasiError> {
-    tracing::debug!(%exitcode);
+    tracing::debug!(tid=%ctx.data().thread.id(), %exitcode);
     Err(WasiError::Exit(exitcode))
 }

lib/wasix/src/syscalls/wasix/thread_spawn.rs

@@ -30,7 +30,7 @@ use wasmer_wasix_types::wasi::ThreadStart;
 ///
 /// Returns the thread index of the newly created thread
 /// (indices always start from the same value as `pid` and increments in steps)
-//#[instrument(level = "debug", skip_all, ret)]
+#[instrument(level = "debug", skip_all, ret)]
 pub fn thread_spawn_v2<M: MemorySize>(
     mut ctx: FunctionEnvMut<'_, WasiEnv>,
     start_ptr: WasmPtr<ThreadStart<M>, M>,
@@ -42,6 +42,13 @@ pub fn thread_spawn_v2<M: MemorySize>(
     // Success
     let memory = unsafe { ctx.data().memory_view(&ctx) };
     wasi_try_mem!(ret_tid.write(&memory, tid));
+
+    tracing::debug!(
+        tid,
+        from_tid = ctx.data().thread.id().raw(),
+        "spawned new thread"
+    );
+
     Errno::Success
 }
 
@@ -72,7 +79,11 @@ pub fn thread_spawn_internal_from_wasi<M: MemorySize>(
             stack_size,
         }
     };
-    tracing::trace!("spawn with layout {:?}", layout);
+    tracing::trace!(
+        from_tid = env.thread.id().raw(),
+        "thread_spawn with layout {:?}",
+        layout
+    );
 
     // Create the handle that represents this thread
     let thread_start = ThreadStartType::ThreadSpawn {