diff --git a/lib/wasix/src/journal/effector/save_event.rs b/lib/wasix/src/journal/effector/save_event.rs index 415b61c434f..f1a3a1b9c6b 100644 --- a/lib/wasix/src/journal/effector/save_event.rs +++ b/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) diff --git a/lib/wasix/src/os/task/thread.rs b/lib/wasix/src/os/task/thread.rs index f9e4ec534db..6724634940a 100644 --- a/lib/wasix/src/os/task/thread.rs +++ b/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); diff --git a/lib/wasix/src/state/func_env.rs b/lib/wasix/src/state/func_env.rs index 29f1c6d5464..fb7dee2c6da 100644 --- a/lib/wasix/src/state/func_env.rs +++ b/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 { + 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) } } diff --git a/lib/wasix/src/syscalls/journal/restore_snapshot.rs b/lib/wasix/src/syscalls/journal/restore_snapshot.rs index 96457957b1b..d9bfc4efd56 100644 --- a/lib/wasix/src/syscalls/journal/restore_snapshot.rs +++ b/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, @@ -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::(&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::(&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::( &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) } diff --git a/lib/wasix/src/syscalls/wasix/thread_exit.rs b/lib/wasix/src/syscalls/wasix/thread_exit.rs index 77ff6d1f8c9..9282f440a29 100644 --- a/lib/wasix/src/syscalls/wasix/thread_exit.rs +++ b/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)) } diff --git a/lib/wasix/src/syscalls/wasix/thread_spawn.rs b/lib/wasix/src/syscalls/wasix/thread_spawn.rs index f30d2d772fa..d40b11afbca 100644 --- a/lib/wasix/src/syscalls/wasix/thread_spawn.rs +++ b/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( mut ctx: FunctionEnvMut<'_, WasiEnv>, start_ptr: WasmPtr, M>, @@ -42,6 +42,13 @@ pub fn thread_spawn_v2( // 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( 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 {