diff --git a/Cargo.lock b/Cargo.lock index 964b697198f..e34a0dff789 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1369,18 +1369,18 @@ dependencies = [ [[package]] name = "enum-map" -version = "2.6.1" +version = "2.6.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9705d8de4776df900a4a0b2384f8b0ab42f775e93b083b42f8ce71bdc32a47e3" +checksum = "c188012f8542dee7b3996e44dd89461d64aa471b0a7c71a1ae2f595d259e96e5" dependencies = [ "enum-map-derive", ] [[package]] name = "enum-map-derive" -version = "0.13.0" +version = "0.14.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ccb14d927583dd5c2eac0f2cf264fc4762aefe1ae14c47a8a20fc1939d3a5fc0" +checksum = "04d0b288e3bb1d861c4403c1774a6f7a798781dfc519b3647df2a3dd4ae95f25" dependencies = [ "proc-macro2", "quote", @@ -4266,6 +4266,7 @@ dependencies = [ "derive_more", "dirs", "email_address", + "enum-map", "flate2", "fs2", "futures", diff --git a/Cargo.toml b/Cargo.toml index fff3265697b..358e9868642 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -91,6 +91,7 @@ dirs = "5.0.1" duct = "0.13.5" email_address = "0.2.4" enum-as-inner = "0.6" +enum-map = "2.6.3" env_logger = "0.10" flate2 = "1.0.24" fs2 = "0.4.3" diff --git a/crates/core/Cargo.toml b/crates/core/Cargo.toml index 7abf70c654f..92cb5ac0526 100644 --- a/crates/core/Cargo.toml +++ b/crates/core/Cargo.toml @@ -34,6 +34,7 @@ crossbeam-channel.workspace = true derive_more.workspace = true dirs.workspace = true email_address.workspace = true +enum-map.workspace = true flate2.workspace = true fs2.workspace = true futures.workspace = true diff --git a/crates/core/src/host/wasm_common.rs b/crates/core/src/host/wasm_common.rs index 0069f010ca6..5aef3ae8c6b 100644 --- a/crates/core/src/host/wasm_common.rs +++ b/crates/core/src/host/wasm_common.rs @@ -1,4 +1,5 @@ pub mod abi; +pub mod instrumentation; pub mod module_host_actor; use std::time::Instant; diff --git a/crates/core/src/host/wasm_common/instrumentation.rs b/crates/core/src/host/wasm_common/instrumentation.rs new file mode 100644 index 00000000000..62acdbcb5cd --- /dev/null +++ b/crates/core/src/host/wasm_common/instrumentation.rs @@ -0,0 +1,127 @@ +//! This file defines `CallSpan` and `CallSpanStart`, +//! which describe the time that a module spends executing "host calls," +//! the WASM analog to syscalls. +//! +//! We can collect `CallSpan` timing data for various parts of host-call execution: +//! - `WasmInstanceEnv`, responsible for direct communication between WASM and the host. +//! - `InstanceEnv`, responsible for calls into the relational DB. +//! - Others? +//! +//! The instrumentation has non-negligible overhead, +//! so we enable it on a per-component basis with `cfg` attributes. +//! This is accomplished by defining two interchangeable modules, +//! `noop` and `op`, both of which implement the call-span interface. +//! `noop` does nothing. +//! `op` uses `std::time::Instant` and `std::time::Duration` to capture timings. +//! Components which use the time-span interface will conditionally import one of the two modules, like: +//! ```no-run +//! #[cfg(feature = "spacetimedb-wasm-instance-times)] +//! use instrumentation::op as span; +//! #[cfg(not(feature = "spacetimedb-wasm-instance-times)] +//! use instrumentation::noop as span; +//! ``` + +use std::time::{Duration, Instant}; + +use enum_map::{enum_map, Enum, EnumMap}; + +#[allow(unused)] +pub mod noop { + use super::*; + + pub struct CallSpanStart; + + impl CallSpanStart { + pub fn new(_call: Call) -> Self { + Self + } + + pub fn end(self) -> CallSpan { + CallSpan + } + } + + pub struct CallSpan; + + pub fn record_span(_call_times: &mut CallTimes, _span: CallSpan) {} +} + +#[allow(unused)] +pub mod op { + use super::*; + + pub struct CallSpanStart { + call: Call, + start: Instant, + } + + impl CallSpanStart { + pub fn new(call: Call) -> Self { + let start = Instant::now(); + Self { call, start } + } + + pub fn end(self) -> CallSpan { + let call = self.call; + let duration = self.start.elapsed(); + CallSpan { call, duration } + } + } + + #[derive(Debug)] + pub struct CallSpan { + pub(super) call: Call, + pub(super) duration: Duration, + } + + pub fn record_span(times: &mut CallTimes, span: CallSpan) { + times.span(span) + } +} + +/// Tags for each call that a `WasmInstanceEnv` can make. +#[derive(Debug, Enum)] +pub enum Call { + CancelReducer, + ConsoleLog, + CreateIndex, + DeleteByColEq, + GetTableId, + Insert, + IterByColEq, + IterDrop, + IterNext, + IterStart, + IterStartFiltered, + ScheduleReducer, +} + +#[derive(Debug)] +/// Associates each `Call` tag with a cumulative total `Duration` spent within that call. +pub struct CallTimes { + times: EnumMap, +} + +impl CallTimes { + /// Create a new timing structure, with times for all calls set to zero. + pub fn new() -> Self { + let times = enum_map! { _ => Duration::ZERO }; + Self { times } + } + + /// Track a particular `CallSpan` by adding its duration to the + /// associated `Call`'s timing information. + pub fn span(&mut self, span: op::CallSpan) { + self.times[span.call] += span.duration; + } + + /// Taking the record of call times gives a copy of the + /// current values and resets the values to zero. + /// + /// WasmInstanceEnv::finish_reducer (and other future per-reducer-call metrics) + /// will `take`` the CallTimes after running a reducer and report the taken times, + /// leaving a fresh zeroed CallTimes for the next reducer invocation. + pub fn take(&mut self) -> CallTimes { + std::mem::replace(self, Self::new()) + } +} diff --git a/crates/core/src/host/wasm_common/module_host_actor.rs b/crates/core/src/host/wasm_common/module_host_actor.rs index df95c998934..bef2fed38af 100644 --- a/crates/core/src/host/wasm_common/module_host_actor.rs +++ b/crates/core/src/host/wasm_common/module_host_actor.rs @@ -31,6 +31,7 @@ use crate::identity::Identity; use crate::subscription::module_subscription_actor::{ModuleSubscriptionManager, SubscriptionEventSender}; use crate::worker_metrics::{REDUCER_COMPUTE_TIME, REDUCER_COUNT, REDUCER_WRITE_SIZE}; +use super::instrumentation::CallTimes; use super::*; pub trait WasmModule: Send + 'static { @@ -74,9 +75,14 @@ pub struct EnergyStats { pub remaining: EnergyQuanta, } +pub struct ExecutionTimings { + pub total_duration: Duration, + pub wasm_instance_env_call_times: CallTimes, +} + pub struct ExecuteResult { pub energy: EnergyStats, - pub execution_duration: Duration, + pub timings: ExecutionTimings, pub call_result: Result>, E>, } @@ -602,28 +608,39 @@ impl WasmModuleInstance { let ExecuteResult { energy, - execution_duration, + timings, call_result, } = result; self.energy_monitor - .record(&energy_fingerprint, energy.used, execution_duration); + .record(&energy_fingerprint, energy.used, timings.total_duration); const FRAME_LEN_60FPS: Duration = match Duration::from_secs(1).checked_div(60) { Some(d) => d, None => unreachable!(), }; - if execution_duration > FRAME_LEN_60FPS { + if timings.total_duration > FRAME_LEN_60FPS { // If we can't get your reducer done in a single frame - // we should debug it. - log::debug!("Long running reducer {func_ident:?} took {execution_duration:?} to execute"); + // we should debug it. To that end, this logging includes a detailed + // breakdown of where time is spent in the reducer call. + // + // TODO(george) only print the per-call timings if they are actually collected. + log::debug!( + "Long running reducer {func_ident:?} took {:?} to execute, with the following wasm_instance_env call times: {:?}", + timings.total_duration, + timings.wasm_instance_env_call_times + ); } else { - log::trace!("Reducer {func_ident:?} ran: {execution_duration:?}, {:?}", energy.used); + log::trace!( + "Reducer {func_ident:?} ran: {:?}, {:?}", + timings.total_duration, + energy.used + ); } REDUCER_COMPUTE_TIME .with_label_values(&[address, func_ident]) - .observe(execution_duration.as_secs_f64()); + .observe(timings.total_duration.as_secs_f64()); // If you can afford to take 500 ms for a transaction // you can afford to generate a flamegraph. Fix your stuff. diff --git a/crates/core/src/host/wasmer/wasm_instance_env.rs b/crates/core/src/host/wasmer/wasm_instance_env.rs index b6d3ac794e1..2ccefc45537 100644 --- a/crates/core/src/host/wasmer/wasm_instance_env.rs +++ b/crates/core/src/host/wasmer/wasm_instance_env.rs @@ -1,11 +1,16 @@ #![allow(clippy::too_many_arguments)] +use std::time::Instant; + use crate::database_logger::{BacktraceFrame, BacktraceProvider, ModuleBacktrace, Record}; use crate::host::scheduler::{ScheduleError, ScheduledReducerId}; use crate::host::timestamp::Timestamp; +use crate::host::wasm_common::instrumentation; +use crate::host::wasm_common::module_host_actor::ExecutionTimings; use crate::host::wasm_common::{ - err_to_errno, AbiRuntimeError, BufferIdx, BufferIterIdx, BufferIters, Buffers, TimingSpan, TimingSpanIdx, - TimingSpanSet, + err_to_errno, + instrumentation::{Call, CallTimes}, + AbiRuntimeError, BufferIdx, BufferIterIdx, BufferIters, Buffers, TimingSpan, TimingSpanIdx, TimingSpanSet, }; use wasmer::{FunctionEnvMut, MemoryAccessError, RuntimeError, ValueType, WasmPtr}; @@ -13,6 +18,11 @@ use crate::host::instance_env::InstanceEnv; use super::{Mem, WasmError}; +#[cfg(not(feature = "spacetimedb-wasm-instance-env-times"))] +use instrumentation::noop as span; +#[cfg(feature = "spacetimedb-wasm-instance-env-times")] +use instrumentation::op as span; + /// A `WasmInstanceEnv` provides the connection between a module /// and the database. /// @@ -45,6 +55,15 @@ pub(super) struct WasmInstanceEnv { /// Track time spent in module-defined spans. timing_spans: TimingSpanSet, + + /// The point in time the last reducer call started at. + reducer_start: Instant, + + /// Track time spent in all wasm instance env calls (aka syscall time). + /// + /// Each function, like `insert`, will add the `Duration` spent in it + /// to this tracker. + call_times: CallTimes, } type WasmResult = Result; @@ -64,12 +83,15 @@ fn mem_err(err: MemoryAccessError) -> RuntimeError { impl WasmInstanceEnv { /// Create a new `WasmEnstanceEnv` from the given `InstanceEnv`. pub fn new(instance_env: InstanceEnv) -> Self { + let reducer_start = Instant::now(); Self { instance_env, mem: None, buffers: Default::default(), iters: Default::default(), timing_spans: Default::default(), + reducer_start, + call_times: CallTimes::new(), } } @@ -101,27 +123,57 @@ impl WasmInstanceEnv { self.buffers.insert(data) } - /// Reset all of the state associated to a single reducer call. - pub fn clear_reducer_state(&mut self) { - // For the moment, we only explicitly clear the set of buffers. + /// Signal to this `WasmInstanceEnv` that a reducer call is beginning. + pub fn start_reducer(&mut self) { + self.reducer_start = Instant::now(); + } + + /// Signal to this `WasmInstanceEnv` that a reducer call is over. + /// This resets all of the state associated to a single reducer call, + /// and returns instrumentation records. + pub fn finish_reducer(&mut self) -> ExecutionTimings { + // For the moment, we only explicitly clear the set of buffers and the + // "syscall" times. // TODO: should we be clearing `iters` and/or `timing_spans`? self.buffers.clear(); + + let total_duration = self.reducer_start.elapsed(); + + // Taking the call times record also resets timings to 0s for the next call. + let wasm_instance_env_call_times = self.call_times.take(); + + ExecutionTimings { + total_duration, + wasm_instance_env_call_times, + } } /// Call the function `f` with the name `func`. /// The function `f` is provided with the callers environment and the host's memory. /// + /// One of `cvt`, `cvt_ret`, or `cvt_noret` should be used in the implementation of any + /// host call, to provide consistent error handling and instrumentation. + /// /// Some database errors are logged but are otherwise regarded as `Ok(_)`. /// See `err_to_errno` for a list. fn cvt( mut caller: FunctionEnvMut<'_, Self>, func: &'static str, + call: Call, f: impl FnOnce(FunctionEnvMut<'_, Self>, &Mem) -> WasmResult<()>, ) -> RtResult { + let span_start = span::CallSpanStart::new(call); + // Call `f` with the caller and a handle to the memory. - // Bail if there were no errors. let mem = caller.data().mem(); - let Err(err) = f(caller.as_mut(), &mem) else { + let result = f(caller.as_mut(), &mem); + + // Track the span of this call. + let span = span_start.end(); + span::record_span(&mut caller.data_mut().call_times, span); + + // Bail if there were no errors. + let Err(err) = result else { return Ok(0); }; @@ -143,6 +195,9 @@ impl WasmInstanceEnv { /// /// Otherwise, `cvt_ret` (this function) behaves as `cvt`. /// + /// One of `cvt`, `cvt_ret`, or `cvt_noret` should be used in the implementation of any + /// host call, to provide consistent error handling and instrumentation. + /// /// This method should be used as opposed to a manual implementation, /// as it helps with upholding the safety invariants of [`bindings_sys::call`]. /// @@ -150,14 +205,31 @@ impl WasmInstanceEnv { fn cvt_ret( caller: FunctionEnvMut<'_, Self>, func: &'static str, + call: Call, out: WasmPtr, f: impl FnOnce(FunctionEnvMut<'_, Self>, &Mem) -> WasmResult, ) -> RtResult { - Self::cvt(caller, func, |mut caller, mem| { + Self::cvt(caller, func, call, |mut caller, mem| { f(caller.as_mut(), mem).and_then(|ret| out.write(&mem.view(&caller), ret).map_err(Into::into)) }) } + /// Call the function `f`. + /// + /// This is the version of `cvt` or `cvt_ret` for functions with no return value. + /// One of `cvt`, `cvt_ret`, or `cvt_noret` should be used in the implementation of any + /// host call, to provide consistent error handling and instrumentation. + fn cvt_noret(mut caller: FunctionEnvMut<'_, Self>, call: Call, f: impl FnOnce(FunctionEnvMut<'_, Self>, &Mem)) { + let span_start = span::CallSpanStart::new(call); + + // Call `f` with the caller and a handle to the memory. + let mem = caller.data().mem(); + f(caller.as_mut(), &mem); + + let span = span_start.end(); + span::record_span(&mut caller.data_mut().call_times, span); + } + /// Reads a string from WASM memory starting at `ptr` and lasting `len` bytes. /// /// Returns an error if: @@ -191,7 +263,7 @@ impl WasmInstanceEnv { time: u64, out: WasmPtr, ) -> RtResult<()> { - Self::cvt_ret(caller, "schedule_reducer", out, |caller, mem| { + Self::cvt_ret(caller, "schedule_reducer", Call::ScheduleReducer, out, |caller, mem| { // Read the index name as a string from `(name, name_len)`. let name = Self::read_string(&caller, mem, name, name_len)?; @@ -223,7 +295,9 @@ impl WasmInstanceEnv { /// This assumes that the reducer hasn't already been executed. #[tracing::instrument(skip_all)] pub fn cancel_reducer(caller: FunctionEnvMut<'_, Self>, id: u64) { - caller.data().instance_env.cancel_reducer(ScheduledReducerId(id)) + Self::cvt_noret(caller, Call::CancelReducer, |caller, _mem| { + caller.data().instance_env.cancel_reducer(ScheduledReducerId(id)) + }) } /// Log at `level` a `message` message occuring in `filename:line_number` @@ -252,40 +326,40 @@ impl WasmInstanceEnv { message: WasmPtr, message_len: u32, ) { - let mem = caller.data().mem(); - - // Reads a string lossily from the slice `(ptr, len)` in WASM memory. - let read_str = |ptr, len| { - mem.read_bytes(&caller, ptr, len) - .map(crate::util::string_from_utf8_lossy_owned) - }; - - // Reads as string optionally, unless `ptr.is_null()`. - let read_opt_str = |ptr: WasmPtr<_>, len| (!ptr.is_null()).then(|| read_str(ptr, len)).transpose(); - - let _ = (|| -> Result<_, MemoryAccessError> { - // Read the `target`, `filename`, and `message` strings from WASM memory. - let target = read_opt_str(target, target_len)?; - let filename = read_opt_str(filename, filename_len)?; - let message = read_str(message, message_len)?; - - // The line number cannot be `u32::MAX` as this represents `Option::None`. - let line_number = (line_number != u32::MAX).then_some(line_number); - - let record = Record { - target: target.as_deref(), - filename: filename.as_deref(), - line_number, - message: &message, + Self::cvt_noret(caller, Call::ConsoleLog, |caller, mem| { + // Reads a string lossily from the slice `(ptr, len)` in WASM memory. + let read_str = |ptr, len| { + mem.read_bytes(&caller, ptr, len) + .map(crate::util::string_from_utf8_lossy_owned) }; - // Write the log record to the `DatabaseLogger` in the database instance context (dbic). - caller - .data() - .instance_env - .console_log(level.into(), &record, &WasmerBacktraceProvider); - Ok(()) - })(); + // Reads as string optionally, unless `ptr.is_null()`. + let read_opt_str = |ptr: WasmPtr<_>, len| (!ptr.is_null()).then(|| read_str(ptr, len)).transpose(); + + let _ = (|| -> Result<_, MemoryAccessError> { + // Read the `target`, `filename`, and `message` strings from WASM memory. + let target = read_opt_str(target, target_len)?; + let filename = read_opt_str(filename, filename_len)?; + let message = read_str(message, message_len)?; + + // The line number cannot be `u32::MAX` as this represents `Option::None`. + let line_number = (line_number != u32::MAX).then_some(line_number); + + let record = Record { + target: target.as_deref(), + filename: filename.as_deref(), + line_number, + message: &message, + }; + + // Write the log record to the `DatabaseLogger` in the database instance context (dbic). + caller + .data() + .instance_env + .console_log(level.into(), &record, &WasmerBacktraceProvider); + Ok(()) + })(); + }) } /// Inserts a row into the table identified by `table_id`, @@ -305,7 +379,7 @@ impl WasmInstanceEnv { /// according to the `ProductType` that the table's schema specifies. #[tracing::instrument(skip_all)] pub fn insert(caller: FunctionEnvMut<'_, Self>, table_id: u32, row: WasmPtr, row_len: u32) -> RtResult { - Self::cvt(caller, "insert", |caller, mem| { + Self::cvt(caller, "insert", Call::Insert, |caller, mem| { // Read the row from WASM memory into a buffer. let mut row_buffer = mem.read_bytes(&caller, row, row_len)?; @@ -351,7 +425,7 @@ impl WasmInstanceEnv { value_len: u32, out: WasmPtr, ) -> RtResult { - Self::cvt_ret(caller, "delete_by_col_eq", out, |caller, mem| { + Self::cvt_ret(caller, "delete_by_col_eq", Call::DeleteByColEq, out, |caller, mem| { let value = mem.read_bytes(&caller, value, value_len)?; Ok(caller.data().instance_env.delete_by_col_eq(table_id, col_id, &value)?) }) @@ -452,7 +526,7 @@ impl WasmInstanceEnv { name_len: u32, out: WasmPtr, ) -> RtResult { - Self::cvt_ret(caller, "get_table_id", out, |caller, mem| { + Self::cvt_ret(caller, "get_table_id", Call::GetTableId, out, |caller, mem| { // Read the table name from WASM memory. let name = Self::read_string(&caller, mem, name, name_len)?; @@ -488,7 +562,7 @@ impl WasmInstanceEnv { col_ids: WasmPtr, col_len: u32, ) -> RtResult { - Self::cvt(caller, "create_index", |caller, mem| { + Self::cvt(caller, "create_index", Call::CreateIndex, |caller, mem| { // Read the index name from WASM memory. let index_name = Self::read_string(&caller, mem, index_name, index_name_len)?; @@ -530,7 +604,7 @@ impl WasmInstanceEnv { val_len: u32, out: WasmPtr, ) -> RtResult { - Self::cvt_ret(caller, "iter_by_col_eq", out, |mut caller, mem| { + Self::cvt_ret(caller, "iter_by_col_eq", Call::IterByColEq, out, |mut caller, mem| { // Read the test value from WASM memory. let value = mem.read_bytes(&caller, val, val_len)?; @@ -551,7 +625,7 @@ impl WasmInstanceEnv { /// - a table with the provided `table_id` doesn't exist // #[tracing::instrument(skip_all)] pub fn iter_start(caller: FunctionEnvMut<'_, Self>, table_id: u32, out: WasmPtr) -> RtResult { - Self::cvt_ret(caller, "iter_start", out, |mut caller, _mem| { + Self::cvt_ret(caller, "iter_start", Call::IterStart, out, |mut caller, _mem| { // Collect the iterator chunks. let chunks = caller.data().instance_env.iter_chunks(table_id)?; @@ -582,17 +656,23 @@ impl WasmInstanceEnv { filter_len: u32, out: WasmPtr, ) -> RtResult { - Self::cvt_ret(caller, "iter_start_filtered", out, |mut caller, _mem| { - // Read the slice `(filter, filter_len)`. - let filter = caller.data().mem().read_bytes(&caller, filter, filter_len)?; - - // Construct the iterator. - let chunks = caller.data().instance_env.iter_filtered_chunks(table_id, &filter)?; - - // Register the iterator and get back the index to write to `out`. - // Calls to the iterator are done through dynamic dispatch. - Ok(caller.data_mut().iters.insert(chunks.into_iter())) - }) + Self::cvt_ret( + caller, + "iter_start_filtered", + Call::IterStartFiltered, + out, + |mut caller, _mem| { + // Read the slice `(filter, filter_len)`. + let filter = caller.data().mem().read_bytes(&caller, filter, filter_len)?; + + // Construct the iterator. + let chunks = caller.data().instance_env.iter_filtered_chunks(table_id, &filter)?; + + // Register the iterator and get back the index to write to `out`. + // Calls to the iterator are done through dynamic dispatch. + Ok(caller.data_mut().iters.insert(chunks.into_iter())) + }, + ) } /// Advances the registered iterator with the index given by `iter_key`. @@ -608,7 +688,7 @@ impl WasmInstanceEnv { /// - advancing the iterator resulted in an error // #[tracing::instrument(skip_all)] pub fn iter_next(caller: FunctionEnvMut<'_, Self>, iter_key: u32, out: WasmPtr) -> RtResult { - Self::cvt_ret(caller, "iter_next", out, |mut caller, _mem| { + Self::cvt_ret(caller, "iter_next", Call::IterNext, out, |mut caller, _mem| { let data_mut = caller.data_mut(); // Retrieve the iterator by `iter_key`. @@ -630,7 +710,7 @@ impl WasmInstanceEnv { /// Returns an error if the iterator does not exist. // #[tracing::instrument(skip_all)] pub fn iter_drop(caller: FunctionEnvMut<'_, Self>, iter_key: u32) -> RtResult { - Self::cvt(caller, "iter_drop", |mut caller, _mem| { + Self::cvt(caller, "iter_drop", Call::IterDrop, |mut caller, _mem| { caller .data_mut() .iters diff --git a/crates/core/src/host/wasmer/wasmer_module.rs b/crates/core/src/host/wasmer/wasmer_module.rs index f3bd083b512..15589eb972f 100644 --- a/crates/core/src/host/wasmer/wasmer_module.rs +++ b/crates/core/src/host/wasmer/wasmer_module.rs @@ -243,7 +243,7 @@ impl WasmerInstance { .ok_or(DescribeError::BadBuffer)?; // Clear all of the instance state associated to this describer call. - self.env.as_mut(store).clear_reducer_state(); + self.env.as_mut(store).finish_reducer(); Ok(bytes) } @@ -320,8 +320,8 @@ impl WasmerInstance { // let guard = pprof::ProfilerGuardBuilder::default().frequency(2500).build().unwrap(); - let start = std::time::Instant::now(); - log::trace!("Start reducer \"{}\"...", reducer_symbol); + self.env.as_mut(store).start_reducer(); + // pass ownership of the `ptr` allocation into the reducer let result = call(reduce, store, bufs).and_then(|errbuf| { let errbuf = BufferIdx(errbuf); @@ -337,20 +337,20 @@ impl WasmerInstance { }) }); - // Clear all of the instance state associated to this single reducer call. - self.env.as_mut(store).clear_reducer_state(); + // Signal that this reducer call is finished. This gets us the timings + // associated to our reducer call, and clears all of the instance state + // associated to the call. + let timings = self.env.as_mut(store).finish_reducer(); - // .call(store, sender_buf.ptr.cast(), timestamp, args_buf.ptr, args_buf.len) - // .and_then(|_| {}); - let duration = start.elapsed(); let remaining = get_remaining_points(store, instance); let energy = module_host_actor::EnergyStats { used: EnergyQuanta::from_points(budget) - EnergyQuanta::from_points(remaining), remaining: EnergyQuanta::from_points(remaining), }; + module_host_actor::ExecuteResult { energy, - execution_duration: duration, + timings, call_result: result, } }