From d1e24a2d35220e9d3f7dcd8ba880f95f7ac6bdd7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Wed, 16 Feb 2022 15:42:47 -0800 Subject: [PATCH 01/17] feat: measure fuel usage and timing stats Signed-off-by: Jakub Sztandera feat: expose machine from executor via deref Signed-off-by: Jakub Sztandera fvm: more stats Signed-off-by: Jakub Sztandera feat: track "real" compute gas feat: time module compile/link/instantiate time detailed gas and fuel tracing: initial implementation. Introduces a new Cargo feature `tracing` that enables detailed gas tracing. Traces are accumulated in the GasTracer, owned by the CallManager. Gas traces specify the context, point of tracing, consumption stats, and timing stats. We currently support these tracing points: - {Pre,Post}Syscall - {Pre,Post}Extern - {Enter,Exit}Call - Start (of the call stack) - Finish (of the call stack) Traces are currently serialized to JSON and printed directly on stdout. There's a bit of duplication the syscall binding macros that I'm not happy about, and perhaps we could make the tracepoints in the CallManager a bit DRYer. fix build. Trace to file Signed-off-by: Jakub Sztandera --- fvm/Cargo.toml | 2 + fvm/src/call_manager/default.rs | 139 +++++++++++++- fvm/src/call_manager/mod.rs | 27 ++- fvm/src/executor/default.rs | 29 ++- fvm/src/executor/mod.rs | 40 ++-- fvm/src/gas/mod.rs | 13 ++ fvm/src/gas/tracer.rs | 172 ++++++++++++++++++ fvm/src/kernel/default.rs | 99 +++++++++- fvm/src/kernel/mod.rs | 7 + fvm/src/machine/engine.rs | 54 +++++- fvm/src/syscalls/bind.rs | 84 ++++++++- fvm/src/syscalls/mod.rs | 12 ++ testing/conformance/Cargo.toml | 1 + .../conformance/src/bin/perf-conformance.rs | 1 + testing/conformance/src/vm.rs | 23 ++- 15 files changed, 650 insertions(+), 53 deletions(-) create mode 100644 fvm/src/gas/tracer.rs diff --git a/fvm/Cargo.toml b/fvm/Cargo.toml index 029685d7a..043bdd4d1 100644 --- a/fvm/Cargo.toml +++ b/fvm/Cargo.toml @@ -27,6 +27,7 @@ fvm_ipld_blockstore = { version = "0.1.0", path = "../ipld/blockstore" } fvm_ipld_encoding = { version = "0.1.0", path = "../ipld/encoding" } serde = { version = "1.0", features = ["derive"] } serde_tuple = "0.5" +serde_json = { version = "1.0.79", optional = true } serde_repr = "0.1" lazy_static = "1.4.0" derive-getters = "0.2.0" @@ -49,3 +50,4 @@ features = ["cranelift", "pooling-allocator", "parallel-compilation"] default = ["opencl"] opencl = ["filecoin-proofs-api/opencl"] cuda = ["filecoin-proofs-api/cuda"] +tracing = ["serde_json"] diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 45c83827a..2ebc2e2f0 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -1,3 +1,8 @@ +use std::io::Write; +use std::ops::DerefMut; +use std::sync::Mutex; +use std::time::{Duration, Instant}; + use anyhow::Context as _; use derive_more::{Deref, DerefMut}; use fvm_ipld_encoding::{RawBytes, DAG_CBOR}; @@ -8,7 +13,7 @@ use fvm_shared::error::ExitCode; use fvm_shared::{ActorID, MethodNum, METHOD_SEND}; use num_traits::Zero; -use super::{Backtrace, CallManager, InvocationResult, NO_DATA_BLOCK_ID}; +use super::{Backtrace, CallManager, CallStats, InvocationResult, NO_DATA_BLOCK_ID}; use crate::call_manager::backtrace::Frame; use crate::gas::GasTracker; use crate::kernel::{ClassifyResult, ExecutionError, Kernel, Result}; @@ -39,6 +44,12 @@ pub struct InnerDefaultCallManager { call_stack_depth: u32, /// The current chain of errors, if any. backtrace: Backtrace, + + /// Stats related to the message execution. + call_stats: CallStats, + + #[cfg(feature = "tracing")] + gas_tracer: Option>, } #[doc(hidden)] @@ -57,6 +68,13 @@ impl std::ops::DerefMut for DefaultCallManager { } } +lazy_static::lazy_static! { + static ref TRACE_FILE : Mutex> = { + let f = std::fs::File::options().create(true).write(true).append(true).open("fuel_tqrace.json").unwrap(); + Mutex::new(std::io::BufWriter::new(f)) + }; +} + impl CallManager for DefaultCallManager where M: Machine, @@ -72,6 +90,22 @@ where num_actors_created: 0, call_stack_depth: 0, backtrace: Backtrace::default(), + call_stats: CallStats::default(), + + #[cfg(feature = "tracing")] + gas_tracer: { + use crate::gas::tracer::Point; + let mut tracer = crate::gas::tracer::GasTracer::new(); + tracer.record( + Default::default(), + Point { + event: crate::gas::tracer::Event::Started, + label: Default::default(), + }, + Default::default(), + ); + Some(std::cell::RefCell::new(tracer)) + }, })) } @@ -123,12 +157,52 @@ where res } - fn finish(mut self) -> (i64, Backtrace, Self::Machine) { - let gas_used = self.gas_tracker.gas_used().max(0); + fn finish(mut self) -> (i64, Backtrace, CallStats, Self::Machine) { + #[cfg(feature = "tracing")] + { + use crate::gas::tracer::{Consumption, Point}; + let tracer = self.gas_tracer.take().unwrap(); + let traces = { + let mut tracer = tracer.into_inner(); + tracer.record( + Default::default(), + Point { + event: crate::gas::tracer::Event::Finished, + label: Default::default(), + }, + Consumption { + fuel_consumed: None, + gas_consumed: Some(self.gas_tracker.gas_used()), + }, + ); + tracer.finish() + }; + let mut tf = TRACE_FILE.lock().unwrap(); + serde_json::to_writer(tf.deref_mut(), &traces).unwrap(); + tf.flush().unwrap(); + } let inner = self.0.take().expect("call manager is poisoned"); + let gas_used = inner.gas_tracker.gas_used().max(0); + let mut stats = inner.call_stats; + stats.compute_gas = inner.gas_tracker.compute_gas_real().max(0) as u64; + // TODO: Having to check against zero here is fishy, but this is what lotus does. - (gas_used, inner.backtrace, inner.machine) + (gas_used, inner.backtrace, stats, inner.machine) + } + + #[cfg(feature = "tracing")] + fn record_trace( + &self, + context: crate::gas::tracer::Context, + point: crate::gas::tracer::Point, + consumption: crate::gas::tracer::Consumption, + ) { + self.gas_tracer + .as_ref() + .unwrap() + .borrow_mut() + .record(context, point, consumption) } // Accessor methods so the trait can implement some common methods by default. @@ -272,6 +346,27 @@ where log::trace!("sent {} -> {}: {}", from, to, &value); return Ok(InvocationResult::Return(Default::default())); } + let call_start = Instant::now(); + + #[cfg(feature = "tracing")] + { + use crate::gas::tracer::{Consumption, Context, Point}; + let gas_used = self.gas_tracker.gas_used(); + self.gas_tracer.as_mut().unwrap().get_mut().record( + Context { + code_cid: state.code.clone(), + method_num: method, + }, + Point { + event: crate::gas::tracer::Event::EnterCall, + label: Default::default(), + }, + Consumption { + fuel_consumed: None, + gas_consumed: Some(gas_used), + }, + ); + } // This is a cheap operation as it doesn't actually clone the struct, // it returns a referenced copy. @@ -295,6 +390,7 @@ where // Make a store. let mut store = engine.new_store(kernel); + store.add_fuel(u64::MAX).expect("failed to add fuel"); // Instantiate the module. let instance = match engine @@ -314,7 +410,7 @@ where // All actors will have an invoke method. .map_err(Abort::Fatal)?; - // Invoke it. + // Invoke (and time) it. let return_block_id = invoke.call(&mut store, (param_id,))?; // Extract the return value, if there is one. @@ -333,10 +429,43 @@ where Ok(return_value) })(); + let fuel_used = store.fuel_consumed().expect("fuel not enabled?"); let invocation_data = store.into_data(); let last_error = invocation_data.last_error; let mut cm = invocation_data.kernel.take(); + #[cfg(feature = "tracing")] + { + use crate::gas::tracer::{Consumption, Context, Point}; + let gas_used = cm.gas_tracker.gas_used(); + cm.gas_tracer.as_mut().unwrap().get_mut().record( + Context { + code_cid: state.code.clone(), + method_num: method, + }, + Point { + event: crate::gas::tracer::Event::ExitCall, + label: Default::default(), + }, + Consumption { + fuel_consumed: Some(fuel_used), + gas_consumed: Some(gas_used), + }, + ); + } + + // We're ignoring the backtrace collection time, because that will be disabled on + // mainnet unless explicitly enabled. + let call_duration = call_start.elapsed(); + + cm.call_stats.fuel_used += fuel_used; + cm.call_stats.call_count += 1; + cm.call_stats.call_overhead += + (call_duration - invocation_data.actor_time).max(Default::default()); + cm.call_stats.wasm_duration += (invocation_data.actor_time + - invocation_data.syscall_time) + .max(Duration::default()); + // Process the result, updating the backtrace if necessary. let ret = match result { Ok(value) => Ok(InvocationResult::Return(value)), diff --git a/fvm/src/call_manager/mod.rs b/fvm/src/call_manager/mod.rs index f87c564c8..14c74448c 100644 --- a/fvm/src/call_manager/mod.rs +++ b/fvm/src/call_manager/mod.rs @@ -1,3 +1,5 @@ +use std::time::Duration; + use fvm_ipld_encoding::RawBytes; use fvm_shared::address::Address; use fvm_shared::econ::TokenAmount; @@ -58,7 +60,7 @@ pub trait CallManager: 'static { ) -> Result; /// Finishes execution, returning the gas used and the machine. - fn finish(self) -> (i64, backtrace::Backtrace, Self::Machine); + fn finish(self) -> (i64, backtrace::Backtrace, CallStats, Self::Machine); /// Returns a reference to the machine. fn machine(&self) -> &Self::Machine; @@ -114,6 +116,15 @@ pub trait CallManager: 'static { self.gas_tracker_mut().charge_gas(charge)?; Ok(()) } + + /// Record a gas trace. + #[cfg(feature = "tracing")] + fn record_trace( + &self, + context: crate::gas::tracer::Context, + point: crate::gas::tracer::Point, + consumption: crate::gas::tracer::Consumption, + ); } /// The result of a method invocation. @@ -140,3 +151,17 @@ impl InvocationResult { } } } + +#[derive(Default, Clone, Debug)] +pub struct CallStats { + /// Wasm fuel used over the course of the message execution. + pub fuel_used: u64, + /// Time spent inside wasm code. + pub wasm_duration: Duration, + /// Time spent setting up and tearing down wasm calls. + pub call_overhead: Duration, + /// Total number of actor calls (that invoke wasm). + pub call_count: u64, + /// Compute gas actually used. + pub compute_gas: u64, +} diff --git a/fvm/src/executor/default.rs b/fvm/src/executor/default.rs index 50192e342..2cbb83f83 100644 --- a/fvm/src/executor/default.rs +++ b/fvm/src/executor/default.rs @@ -59,12 +59,12 @@ where }; // Apply the message. - let (res, gas_used, mut backtrace) = self.map_machine(|machine| { + let (res, gas_used, stats, mut backtrace) = self.map_machine(|machine| { let mut cm = K::CallManager::new(machine, msg.gas_limit, msg.from, msg.sequence); // This error is fatal because it should have already been acounted for inside // preflight_message. if let Err(e) = cm.charge_gas(inclusion_cost) { - return (Err(e), cm.finish().2); + return (Err(e), cm.finish().3); } let result = cm.with_transaction(|cm| { @@ -79,8 +79,8 @@ where Ok(ret) }); - let (gas_used, backtrace, machine) = cm.finish(); - (Ok((result, gas_used, backtrace)), machine) + let (gas_used, backtrace, stats, machine) = cm.finish(); + (Ok((result, gas_used, stats, backtrace)), machine) })?; // Extract the exit code and build the result of the message application. @@ -152,15 +152,14 @@ where Some(ApplyFailure::MessageBacktrace(backtrace)) }; - match apply_kind { - ApplyKind::Explicit => self.finish_message(msg, receipt, failure_info, gas_cost), - ApplyKind::Implicit => Ok(ApplyRet { - msg_receipt: receipt, - failure_info, - penalty: TokenAmount::zero(), - miner_tip: TokenAmount::zero(), - }), - } + let mut ret = match apply_kind { + ApplyKind::Explicit => self.finish_message(msg, receipt, gas_cost)?, + ApplyKind::Implicit => ApplyRet::from(receipt), + }; + + ret.failure_info = failure_info; + ret.wasm_stats = Some(stats); + Ok(ret) } } @@ -311,7 +310,6 @@ where &mut self, msg: Message, receipt: Receipt, - failure_info: Option, gas_cost: BigInt, ) -> anyhow::Result { // NOTE: we don't support old network versions in the FVM, so we always burn. @@ -362,7 +360,8 @@ where } Ok(ApplyRet { msg_receipt: receipt, - failure_info, + failure_info: None, + wasm_stats: None, penalty: miner_penalty, miner_tip, }) diff --git a/fvm/src/executor/mod.rs b/fvm/src/executor/mod.rs index cf7029f0f..bea305174 100644 --- a/fvm/src/executor/mod.rs +++ b/fvm/src/executor/mod.rs @@ -1,6 +1,7 @@ mod default; use std::fmt::Display; +use std::ops::{Deref, DerefMut}; pub use default::DefaultExecutor; use fvm_ipld_encoding::RawBytes; @@ -10,7 +11,7 @@ use fvm_shared::message::Message; use fvm_shared::receipt::Receipt; use num_traits::Zero; -use crate::call_manager::Backtrace; +use crate::call_manager::{Backtrace, CallManager, CallStats}; use crate::Kernel; /// An executor executes messages on the underlying machine/kernel. It's responsible for: @@ -18,7 +19,10 @@ use crate::Kernel; /// 1. Validating messages (nonce, sender, etc). /// 2. Creating message receipts. /// 3. Charging message inclusion gas, overestimation gas, miner tip, etc. -pub trait Executor { +pub trait Executor: DerefMut +where + Self: Deref::CallManager as CallManager>::Machine>, +{ /// The [`Kernel`] on which messages will be applied. We specify a [`Kernel`] here, not a /// [`Machine`](crate::machine::Machine), because the [`Kernel`] implies the /// [`Machine`](crate::machine::Machine). @@ -71,6 +75,20 @@ pub struct ApplyRet { pub miner_tip: BigInt, /// Additional failure information for debugging, if any. pub failure_info: Option, + /// Wasm execution stats. + pub wasm_stats: Option, +} + +impl From for ApplyRet { + fn from(receipt: Receipt) -> Self { + ApplyRet { + msg_receipt: receipt, + penalty: BigInt::zero(), + miner_tip: BigInt::zero(), + failure_info: None, + wasm_stats: None, + } + } } impl ApplyRet { @@ -80,16 +98,14 @@ impl ApplyRet { message: impl Into, miner_penalty: BigInt, ) -> ApplyRet { - ApplyRet { - msg_receipt: Receipt { - exit_code: code, - return_data: RawBytes::default(), - gas_used: 0, - }, - penalty: miner_penalty, - failure_info: Some(ApplyFailure::PreValidation(message.into())), - miner_tip: BigInt::zero(), - } + let mut ret = ApplyRet::from(Receipt { + exit_code: code, + return_data: RawBytes::default(), + gas_used: 0, + }); + ret.penalty = miner_penalty; + ret.failure_info = Some(ApplyFailure::PreValidation(message.into())); + ret } pub fn assign_from_slice(&mut self, sign: Sign, slice: &[u32]) { diff --git a/fvm/src/gas/mod.rs b/fvm/src/gas/mod.rs index b140fa2aa..b006cd8f7 100644 --- a/fvm/src/gas/mod.rs +++ b/fvm/src/gas/mod.rs @@ -10,9 +10,13 @@ mod charge; mod outputs; mod price_list; +#[cfg(feature = "tracing")] +pub mod tracer; + pub struct GasTracker { gas_available: i64, gas_used: i64, + compute_gas_real: i64, } impl GasTracker { @@ -20,6 +24,7 @@ impl GasTracker { Self { gas_available, gas_used, + compute_gas_real: 0, } } @@ -41,6 +46,8 @@ impl GasTracker { Err(ExecutionError::OutOfGas) } else { self.gas_used = used; + // can't overflow if the sum doesn't overflow. + self.compute_gas_real += charge.compute_gas; Ok(()) } } @@ -56,6 +63,12 @@ impl GasTracker { pub fn gas_used(&self) -> i64 { self.gas_used } + + /// Getter for the "real" compute gas. That is, the compute gas that was actually _used_, not + /// including the storage gas and gas charged when we run out of gas. + pub fn compute_gas_real(&self) -> i64 { + self.compute_gas_real + } } #[cfg(test)] diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs new file mode 100644 index 000000000..e759b0f5d --- /dev/null +++ b/fvm/src/gas/tracer.rs @@ -0,0 +1,172 @@ +use std::time::{Duration, Instant}; + +use cid::Cid; +use fvm_shared::MethodNum; +use serde::Serialize; + +#[derive(Debug, Serialize)] +pub struct GasTracer { + #[serde(skip_serializing)] + started: Instant, + #[serde(skip_serializing)] + previous: Instant, + /// Accumulated traces. + traces: Vec, +} + +impl GasTracer { + pub fn new() -> GasTracer { + let now = Instant::now(); + GasTracer { + started: now, + previous: now, + traces: Default::default(), + } + } + + pub fn record(&mut self, context: Context, point: Point, consumption: Consumption) { + let trace = GasTrace { + context, + point, + consumption, + timing: { + let now = Instant::now(); + let prev = self.previous; + self.previous = now; + Timing { + elapsed_cum: now.duration_since(self.started), + elapsed_rel: now.duration_since(prev), + } + }, + }; + self.traces.push(trace) + } + + pub fn finish(self) -> Vec { + self.traces + } +} + +#[derive(Debug, Serialize)] +pub struct GasTrace { + /// Context annotates the trace with the source context. + pub context: Context, + /// Point represents the location from where the trace was emitted. + pub point: Point, + /// The consumption at the moment of trace. + pub consumption: Consumption, + /// Timing information. + pub timing: Timing, +} + +#[derive(Debug, Serialize, Default)] +pub struct Consumption { + /// Wasmtime fuel consumed reports how much fuel has been consumed at this point. + /// May be optional if the point had no access to this information, or if non applicable. + pub fuel_consumed: Option, + /// Gas consumed reports how much gas has been consumed at this point. + /// May be optional if the point had no access to this information, or if non applicable. + pub gas_consumed: Option, +} + +#[derive(Debug, Serialize)] +pub struct Timing { + /// Total time elapsed since the GasTracer was created. + #[serde( + serialize_with = "ser::serialize_duration_as_nanos", + rename = "elapsed_cum_ns" + )] + pub elapsed_cum: Duration, + /// Relative time elapsed since the previous trace was recorded. + #[serde( + serialize_with = "ser::serialize_duration_as_nanos", + rename = "elapsed_rel_ns" + )] + pub elapsed_rel: Duration, +} + +#[derive(Debug, Serialize, Default)] +pub struct Context { + #[serde(serialize_with = "ser::serialize_cid")] + pub code_cid: Cid, + pub method_num: MethodNum, +} + +#[derive(Debug, Serialize)] +pub struct Point { + pub event: Event, + pub label: String, +} + +#[derive(Debug, Serialize)] +pub enum Event { + Started, + EnterCall, + PreSyscall, + PostSyscall, + PreExtern, + PostExtern, + ExitCall, + Finished, +} + +#[test] +fn test_tracer() { + let mut tracer = GasTracer::new(); + tracer.record( + Context { + code_cid: Default::default(), + method_num: 0, + }, + Point { + event: Event::Started, + label: "".to_string(), + }, + Consumption { + fuel_consumed: None, + gas_consumed: None, + }, + ); + + std::thread::sleep(Duration::from_millis(1000)); + tracer.record( + Context { + code_cid: Default::default(), + method_num: 0, + }, + Point { + event: Event::Started, + label: "".to_string(), + }, + Consumption { + fuel_consumed: None, + gas_consumed: None, + }, + ); + let traces = tracer.finish(); + println!("{:?}", traces); + + let str = serde_json::to_string(&traces).unwrap(); + println!("{}", str); +} + +mod ser { + use std::time::Duration; + + use cid::Cid; + use serde::{Serialize, Serializer}; + + pub fn serialize_cid(c: &Cid, serializer: S) -> Result + where + S: Serializer, + { + c.to_string().serialize(serializer) + } + + pub fn serialize_duration_as_nanos(d: &Duration, serializer: S) -> Result + where + S: Serializer, + { + d.as_nanos().serialize(serializer) + } +} diff --git a/fvm/src/kernel/default.rs b/fvm/src/kernel/default.rs index 0b8d261b9..42d86a496 100644 --- a/fvm/src/kernel/default.rs +++ b/fvm/src/kernel/default.rs @@ -47,15 +47,36 @@ lazy_static! { static ref INITIAL_RESERVE_BALANCE: BigInt = BigInt::from(300_000_000) * FILECOIN_PRECISION; } +macro_rules! record_trace { + ($self:ident, $event:ident, $name:literal) => { + #[cfg(feature = "tracing")] + $self.record_trace( + crate::gas::tracer::Point { + event: crate::gas::tracer::Event::$event, + label: $name.to_string(), + }, + crate::gas::tracer::Consumption { + fuel_consumed: None, + gas_consumed: Some($self.call_manager.gas_tracker().gas_used()), + }, + ); + }; +} + /// Tracks data accessed and modified during the execution of a message. /// /// TODO writes probably ought to be scoped by invocation container. pub struct DefaultKernel { // Fields extracted from the message, except parameters, which have been // preloaded into the block registry. + /// The actor ID of the caller. caller: ActorID, + /// The actor ID of the executing actor (aka receiver). actor_id: ActorID, + /// The method number that was invoked. This is part of the legacy + /// calling convention. method: MethodNum, + /// The value received in filecoin tokens. value_received: TokenAmount, /// The call manager for this call stack. If this kernel calls another actor, it will @@ -66,6 +87,16 @@ pub struct DefaultKernel { /// /// This does not yet reason about reachability. blocks: BlockRegistry, + + /// Tracing information. + #[cfg(feature = "tracing")] + debug: DebugInfo, +} + +#[cfg(feature = "tracing")] +#[derive(Default)] +struct DebugInfo { + code_cid: Cid, } // Even though all children traits are implemented, Rust needs to know that the @@ -90,14 +121,39 @@ where method: MethodNum, value_received: TokenAmount, ) -> Self { - DefaultKernel { + #[allow(unused_mut)] + let mut ret = DefaultKernel { call_manager: mgr, blocks: BlockRegistry::new(), caller, actor_id, method, value_received, - } + + #[cfg(feature = "tracing")] + debug: Default::default(), + }; + + #[cfg(feature = "tracing")] + ret.prepare_tracing(); + + ret + } + + #[cfg(feature = "tracing")] + fn record_trace( + &self, + point: crate::gas::tracer::Point, + mut consumption: crate::gas::tracer::Consumption, + ) { + // Create the context from our debug info. + let context = crate::gas::tracer::Context { + code_cid: self.debug.code_cid, + method_num: self.method, + }; + // Stamp with gas consumed. + consumption.gas_consumed = Some(self.call_manager.gas_tracker().gas_used()); + self.call_manager.record_trace(context, point, consumption) } } @@ -105,6 +161,18 @@ impl DefaultKernel where C: CallManager, { + #[cfg(feature = "tracing")] + fn prepare_tracing(&mut self) { + self.debug.code_cid = self + .call_manager + .state_tree() + .get_actor_id(self.actor_id) + .context("tracing: failed to lookup actor to get code CID") + .unwrap() + .map(|act| act.code) + .unwrap(); + } + fn resolve_to_key_addr(&mut self, addr: &Address, charge_gas: bool) -> Result
{ if addr.protocol() == Protocol::BLS || addr.protocol() == Protocol::Secp256k1 { return Ok(*addr); @@ -561,6 +629,8 @@ where self.call_manager .charge_gas(self.call_manager.price_list().on_verify_consensus_fault())?; + record_trace!(self, PreExtern, "verify_consensus_fault"); + // This syscall cannot be resolved inside the FVM, so we need to traverse // the node boundary through an extern. let (fault, gas) = self @@ -568,6 +638,9 @@ where .externs() .verify_consensus_fault(h1, h2, extra) .or_illegal_argument()?; + + record_trace!(self, PostExtern, "verify_consensus_fault"); + self.call_manager .charge_gas(GasCharge::new("verify_consensus_fault_accesses", gas, 0))?; Ok(fault) @@ -748,11 +821,18 @@ where rand_epoch: ChainEpoch, entropy: &[u8], ) -> Result<[u8; RANDOMNESS_LENGTH]> { + record_trace!(self, PreExtern, "get_chain_randomness"); + // TODO: Check error code - self.call_manager + let ret = self + .call_manager .externs() .get_chain_randomness(personalization, rand_epoch, entropy) - .or_illegal_argument() + .or_illegal_argument(); + + record_trace!(self, PostExtern, "get_chain_randomness"); + + ret } #[allow(unused)] @@ -762,12 +842,19 @@ where rand_epoch: ChainEpoch, entropy: &[u8], ) -> Result<[u8; RANDOMNESS_LENGTH]> { + record_trace!(self, PreExtern, "get_beacon_randomness"); + // TODO: Check error code // Hyperdrive and above only. - self.call_manager + let ret = self + .call_manager .externs() .get_beacon_randomness(personalization, rand_epoch, entropy) - .or_illegal_argument() + .or_illegal_argument(); + + record_trace!(self, PostExtern, "get_beacon_randomness"); + + ret } } diff --git a/fvm/src/kernel/mod.rs b/fvm/src/kernel/mod.rs index 2279ac330..bb424f199 100644 --- a/fvm/src/kernel/mod.rs +++ b/fvm/src/kernel/mod.rs @@ -64,6 +64,13 @@ pub trait Kernel: ) -> Self where Self: Sized; + + #[cfg(feature = "tracing")] + fn record_trace( + &self, + point: crate::gas::tracer::Point, + consumption: crate::gas::tracer::Consumption, + ); } /// Network-related operations. diff --git a/fvm/src/machine/engine.rs b/fvm/src/machine/engine.rs index 5f6b7c510..0c33eca03 100644 --- a/fvm/src/machine/engine.rs +++ b/fvm/src/machine/engine.rs @@ -2,11 +2,12 @@ use std::collections::hash_map::Entry; use std::collections::HashMap; use std::ops::Deref; use std::sync::{Arc, Mutex}; +use std::time::Instant; use anyhow::anyhow; use cid::Cid; use fvm_ipld_blockstore::Blockstore; -use wasmtime::{Linker, Module}; +use wasmtime::{Linker, Module, Trap}; use crate::syscalls::{bind_syscalls, InvocationData}; use crate::Kernel; @@ -79,7 +80,7 @@ impl Deref for Engine { impl Engine { /// Create a new Engine from a wasmtime config. pub fn new(c: &wasmtime::Config) -> anyhow::Result { - Ok(wasmtime::Engine::new(c)?.into()) + Ok(wasmtime::Engine::new(c.clone().consume_fuel(true))?.into()) } } @@ -119,7 +120,12 @@ impl Engine { &cid.to_string() ) })?; + let start = Instant::now(); let module = Module::from_binary(&self.0.engine, wasm.as_slice())?; + log::info!( + "compiled {cid} in {}", + duration = start.elapsed().as_nanos() + ); cache.insert(*cid, module); } Ok(()) @@ -131,7 +137,9 @@ impl Engine { let module = match cache.get(k) { Some(module) => module.clone(), None => { + let start = Instant::now(); let module = Module::from_binary(&self.0.engine, wasm)?; + log::info!("compiled {k} in {}", duration = start.elapsed().as_nanos()); cache.insert(*k, module.clone()); module } @@ -179,8 +187,14 @@ impl Engine { let cache = match instance_cache.entry() { anymap::Entry::Occupied(e) => e.into_mut(), anymap::Entry::Vacant(e) => e.insert({ + let start = Instant::now(); let mut linker = Linker::new(&self.0.engine); bind_syscalls(&mut linker)?; + log::info!( + "created linker for {kernel} in {duration}", + kernel = std::any::type_name::(), + duration = start.elapsed().as_nanos(), + ); Cache { linker, instances: HashMap::new(), @@ -195,8 +209,14 @@ impl Engine { Some(module) => module, None => return Ok(None), }; + let start = Instant::now(); // We can cache the "pre instance" because our linker only has host functions. let pre = cache.linker.instantiate_pre(&mut *store, module)?; + log::info!( + "instantiated {k} for {kernel} in {duration}", + kernel = std::any::type_name::(), + duration = start.elapsed().as_nanos(), + ); e.insert(pre) } }; @@ -206,6 +226,34 @@ impl Engine { /// Construct a new wasmtime "store" from the given kernel. pub fn new_store(&self, kernel: K) -> wasmtime::Store> { - wasmtime::Store::new(&self.0.engine, InvocationData::new(kernel)) + fn call_hook( + data: &mut InvocationData, + h: wasmtime::CallHook, + ) -> Result<(), Trap> { + use wasmtime::CallHook::*; + match h { + CallingWasm => data.last_actor_call = Some(Instant::now()), + CallingHost => data.last_syscall_call = Some(Instant::now()), + ReturningFromWasm => { + data.actor_time += data + .last_actor_call + .take() + .expect("wasm return with no matching call") + .elapsed(); + } + + ReturningFromHost => { + data.syscall_time += data + .last_syscall_call + .take() + .expect("syscall return with no matching call") + .elapsed(); + } + } + Ok(()) + } + let mut store = wasmtime::Store::new(&self.0.engine, InvocationData::new(kernel)); + store.call_hook(call_hook); + store } } diff --git a/fvm/src/syscalls/bind.rs b/fvm/src/syscalls/bind.rs index eec5c1226..6bd0e5c21 100644 --- a/fvm/src/syscalls/bind.rs +++ b/fvm/src/syscalls/bind.rs @@ -114,9 +114,43 @@ macro_rules! impl_bind_syscalls { if mem::size_of::() == 0 { // If we're returning a zero-sized "value", we return no value therefore and expect no out pointer. self.func_wrap(module, name, move |mut caller: Caller<'_, InvocationData> $(, $t: $t)*| { - let (mut memory, mut data) = memory_and_data(&mut caller)?; - let ctx = Context{kernel: &mut data.kernel, memory: &mut memory}; - Ok(match syscall(ctx $(, $t)*).into()? { + #[cfg(feature = "tracing")] + let (label, fuel_consumed) = ([module, name].join("::"), caller.fuel_consumed()); + + let (mut memory, data) = memory_and_data(&mut caller)?; + + #[cfg(feature = "tracing")] + { + let point = crate::gas::tracer::Point{ + event: crate::gas::tracer::Event::PreSyscall, + label: label.clone(), + }; + let consumption = crate::gas::tracer::Consumption{ + fuel_consumed, + gas_consumed: None, + }; + (&mut data.kernel).record_trace(point, consumption); + } + + let sys_ret = { + let ctx = Context{kernel: &mut data.kernel, memory: &mut memory}; + syscall(ctx $(, $t)*) + }; + + #[cfg(feature = "tracing")] + { + let point = crate::gas::tracer::Point{ + event: crate::gas::tracer::Event::PostSyscall, + label, + }; + let consumption = crate::gas::tracer::Consumption{ + fuel_consumed, + gas_consumed: None, + }; + (&mut data.kernel).record_trace(point, consumption); + } + + Ok(match sys_ret.into()? { Ok(_) => { log::trace!("syscall {}::{}: ok", module, name); data.last_error = None; @@ -133,18 +167,50 @@ macro_rules! impl_bind_syscalls { } else { // If we're returning an actual value, we need to write it back into the wasm module's memory. self.func_wrap(module, name, move |mut caller: Caller<'_, InvocationData>, ret: u32 $(, $t: $t)*| { - let (mut memory, mut data) = memory_and_data(&mut caller)?; + #[cfg(feature = "tracing")] + let (label, fuel_consumed) = ([module, name].join("::"), caller.fuel_consumed()); + let (mut memory, data) = memory_and_data(&mut caller)?; // We need to check to make sure we can store the return value _before_ we do anything. if (ret as u64) > (memory.len() as u64) || memory.len() - (ret as usize) < mem::size_of::() { - let code = ErrorNumber::IllegalArgument; - data.last_error = Some(backtrace::Cause::new(module, name, SyscallError(format!("no space for return value"), code))); - return Ok(code as u32); + let code = ErrorNumber::IllegalArgument; + data.last_error = Some(backtrace::Cause::new(module, name, SyscallError(format!("no space for return value"), code))); + return Ok(code as u32); + } + + #[cfg(feature = "tracing")] + { + let point = crate::gas::tracer::Point{ + event: crate::gas::tracer::Event::PreSyscall, + label: label.clone(), + }; + let consumption = crate::gas::tracer::Consumption{ + fuel_consumed, + gas_consumed: None, + }; + (&mut data.kernel).record_trace(point, consumption); + } + + let sys_ret = { + let ctx = Context{kernel: &mut data.kernel, memory: &mut memory}; + syscall(ctx $(, $t)*) + }; + + #[cfg(feature = "tracing")] + { + let point = crate::gas::tracer::Point{ + event: crate::gas::tracer::Event::PostSyscall, + label, + }; + let consumption = crate::gas::tracer::Consumption{ + fuel_consumed, + gas_consumed: None, + }; + (&mut data.kernel).record_trace(point, consumption); } - let ctx = Context{kernel: &mut data.kernel, memory: &mut memory}; - Ok(match syscall(ctx $(, $t)*).into()? { + Ok(match sys_ret.into()? { Ok(value) => { log::trace!("syscall {}::{}: ok", module, name); unsafe { *(memory.as_mut_ptr().offset(ret as isize) as *mut Ret::Value) = value }; diff --git a/fvm/src/syscalls/mod.rs b/fvm/src/syscalls/mod.rs index 2e77dd890..78f57beeb 100644 --- a/fvm/src/syscalls/mod.rs +++ b/fvm/src/syscalls/mod.rs @@ -1,3 +1,5 @@ +use std::time::{Duration, Instant}; + use cid::Cid; use wasmtime::Linker; @@ -29,6 +31,12 @@ pub struct InvocationData { /// The last-seen syscall error. This error is considered the abort "cause" if an actor aborts /// after receiving this error without calling any other syscalls. pub last_error: Option, + /// The time spent processing syscalls, including sends to other actors. + /// TODO: make this optional. + pub syscall_time: Duration, + pub actor_time: Duration, + pub last_syscall_call: Option, + pub last_actor_call: Option, } impl InvocationData { @@ -36,6 +44,10 @@ impl InvocationData { Self { kernel, last_error: None, + syscall_time: Duration::default(), + actor_time: Duration::default(), + last_syscall_call: None, + last_actor_call: None, } } } diff --git a/testing/conformance/Cargo.toml b/testing/conformance/Cargo.toml index 4598cb4a7..e4a310185 100644 --- a/testing/conformance/Cargo.toml +++ b/testing/conformance/Cargo.toml @@ -53,6 +53,7 @@ libipld-core = { version = "0.13.1", features = ["serde-codec"] } [features] vtune = ["wasmtime/vtune", "ittapi-rs"] +tracing = ["fvm/tracing"] [dev-dependencies] pretty_env_logger = "0.4.0" diff --git a/testing/conformance/src/bin/perf-conformance.rs b/testing/conformance/src/bin/perf-conformance.rs index b323fd736..1a7865e5a 100644 --- a/testing/conformance/src/bin/perf-conformance.rs +++ b/testing/conformance/src/bin/perf-conformance.rs @@ -40,6 +40,7 @@ fn main() { } let engine = Engine::new( wasmtime::Config::default() + .consume_fuel(true) .profiler(wasmtime::ProfilingStrategy::VTune) .expect("failed to configure profiler"), ) diff --git a/testing/conformance/src/vm.rs b/testing/conformance/src/vm.rs index fe9ae5baa..9afd0a89b 100644 --- a/testing/conformance/src/vm.rs +++ b/testing/conformance/src/vm.rs @@ -3,7 +3,7 @@ use std::convert::TryFrom; use cid::Cid; use futures::executor::block_on; -use fvm::call_manager::{Backtrace, CallManager, DefaultCallManager, InvocationResult}; +use fvm::call_manager::{Backtrace, CallManager, CallStats, DefaultCallManager, InvocationResult}; use fvm::gas::{GasTracker, PriceList}; use fvm::kernel::*; use fvm::machine::{DefaultMachine, Engine, Machine, MachineContext}; @@ -222,10 +222,20 @@ where }) } - fn finish(self) -> (i64, Backtrace, Self::Machine) { + fn finish(self) -> (i64, Backtrace, CallStats, Self::Machine) { self.0.finish() } + #[cfg(feature = "tracing")] + fn record_trace( + &self, + context: fvm::gas::tracer::Context, + point: fvm::gas::tracer::Point, + consumption: fvm::gas::tracer::Consumption, + ) { + self.0.record_trace(context, point, consumption) + } + fn machine(&self) -> &Self::Machine { self.0.machine() } @@ -325,6 +335,15 @@ where data, ) } + + #[cfg(feature = "tracing")] + fn record_trace( + &self, + point: fvm::gas::tracer::Point, + consumption: fvm::gas::tracer::Consumption, + ) { + self.0.record_trace(point, consumption) + } } impl ActorOps for TestKernel From ac22e5d466afb28fa11a548e50b774f29a6ee47d Mon Sep 17 00:00:00 2001 From: Jakub Sztandera Date: Wed, 6 Apr 2022 17:54:12 +0200 Subject: [PATCH 02/17] Cleanup imports Signed-off-by: Jakub Sztandera --- fvm/src/call_manager/default.rs | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 2ebc2e2f0..69ac92d05 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -1,5 +1,4 @@ -use std::io::Write; -use std::ops::DerefMut; + use std::sync::Mutex; use std::time::{Duration, Instant}; @@ -21,6 +20,11 @@ use crate::machine::Machine; use crate::syscalls::error::Abort; use crate::{account_actor, syscall_error}; +#[cfg(feature = "tracing")] +use std::io::Write; +#[cfg(feature = "tracing")] +use std::ops::DerefMut; + /// The default [`CallManager`] implementation. #[repr(transparent)] pub struct DefaultCallManager(Option>); From 98b56231c78fc3c9c980d174df051e61b8fd6bac Mon Sep 17 00:00:00 2001 From: Jakub Sztandera Date: Wed, 6 Apr 2022 18:18:51 +0200 Subject: [PATCH 03/17] Fix typo Signed-off-by: Jakub Sztandera --- fvm/src/call_manager/default.rs | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 69ac92d05..8a49f56f9 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -1,4 +1,7 @@ - +#[cfg(feature = "tracing")] +use std::io::Write; +#[cfg(feature = "tracing")] +use std::ops::DerefMut; use std::sync::Mutex; use std::time::{Duration, Instant}; @@ -20,11 +23,6 @@ use crate::machine::Machine; use crate::syscalls::error::Abort; use crate::{account_actor, syscall_error}; -#[cfg(feature = "tracing")] -use std::io::Write; -#[cfg(feature = "tracing")] -use std::ops::DerefMut; - /// The default [`CallManager`] implementation. #[repr(transparent)] pub struct DefaultCallManager(Option>); @@ -74,7 +72,7 @@ impl std::ops::DerefMut for DefaultCallManager { lazy_static::lazy_static! { static ref TRACE_FILE : Mutex> = { - let f = std::fs::File::options().create(true).write(true).append(true).open("fuel_tqrace.json").unwrap(); + let f = std::fs::File::options().create(true).write(true).append(true).open("fuel_trace.json").unwrap(); Mutex::new(std::io::BufWriter::new(f)) }; } From f793b35b3956534da7c3367d04206fc3c090617c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Sat, 23 Apr 2022 14:03:25 +0200 Subject: [PATCH 04/17] switch to minstant. --- fvm/Cargo.toml | 5 +++-- fvm/src/gas/tracer.rs | 3 ++- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/fvm/Cargo.toml b/fvm/Cargo.toml index 043bdd4d1..278f90f69 100644 --- a/fvm/Cargo.toml +++ b/fvm/Cargo.toml @@ -27,7 +27,6 @@ fvm_ipld_blockstore = { version = "0.1.0", path = "../ipld/blockstore" } fvm_ipld_encoding = { version = "0.1.0", path = "../ipld/encoding" } serde = { version = "1.0", features = ["derive"] } serde_tuple = "0.5" -serde_json = { version = "1.0.79", optional = true } serde_repr = "0.1" lazy_static = "1.4.0" derive-getters = "0.2.0" @@ -40,6 +39,8 @@ log = "0.4.14" byteorder = "1.4.3" anymap = "0.12.1" blake2b_simd = "1.0.0" +minstant = { version = "0.1.1", optional = true } +serde_json = { version = "1.0.79", optional = true } [dependencies.wasmtime] version = "0.35.2" @@ -50,4 +51,4 @@ features = ["cranelift", "pooling-allocator", "parallel-compilation"] default = ["opencl"] opencl = ["filecoin-proofs-api/opencl"] cuda = ["filecoin-proofs-api/cuda"] -tracing = ["serde_json"] +tracing = ["serde_json", "minstant"] diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs index e759b0f5d..a40f05901 100644 --- a/fvm/src/gas/tracer.rs +++ b/fvm/src/gas/tracer.rs @@ -1,7 +1,8 @@ -use std::time::{Duration, Instant}; +use std::time::Duration; use cid::Cid; use fvm_shared::MethodNum; +use minstant::Instant; use serde::Serialize; #[derive(Debug, Serialize)] From ad572e7f8bd609170706681794a54a6117f71c19 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Mon, 25 Apr 2022 13:00:17 +0200 Subject: [PATCH 05/17] propagate execution stats. --- fvm/src/call_manager/default.rs | 16 +++++++--------- fvm/src/executor/default.rs | 1 + 2 files changed, 8 insertions(+), 9 deletions(-) diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 71e4c12e5..00711d0a7 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -52,10 +52,8 @@ pub struct InnerDefaultCallManager { backtrace: Backtrace, /// The current execution trace. exec_trace: ExecutionTrace, - /// Stats related to the message execution. - call_stats: ExecutionStats, - + exec_stats: ExecutionStats, #[cfg(feature = "tracing")] gas_tracer: Option>, } @@ -98,7 +96,7 @@ where num_actors_created: 0, call_stack_depth: 0, backtrace: Backtrace::default(), - call_stats: ExecutionStats::default(), + exec_stats: ExecutionStats::default(), exec_trace: vec![], #[cfg(feature = "tracing")] @@ -217,7 +215,7 @@ where let inner = self.0.take().expect("call manager is poisoned"); let gas_used = inner.gas_tracker.gas_used().max(0); - let mut stats = inner.call_stats; + let mut stats = inner.exec_stats; stats.compute_gas = inner.gas_tracker.compute_gas_real().max(0) as u64; // TODO: Having to check against zero here is fishy, but this is what lotus does. @@ -531,11 +529,11 @@ where // mainnet unless explicitly enabled. let call_duration = call_start.elapsed(); - cm.call_stats.fuel_used += fuel_used; - cm.call_stats.call_count += 1; - cm.call_stats.call_overhead += + cm.exec_stats.fuel_used += fuel_used; + cm.exec_stats.call_count += 1; + cm.exec_stats.call_overhead += (call_duration - invocation_data.actor_time).max(Default::default()); - cm.call_stats.wasm_duration += (invocation_data.actor_time + cm.exec_stats.wasm_duration += (invocation_data.actor_time - invocation_data.syscall_time) .max(Duration::default()); diff --git a/fvm/src/executor/default.rs b/fvm/src/executor/default.rs index 5bafa8aee..24b64229c 100644 --- a/fvm/src/executor/default.rs +++ b/fvm/src/executor/default.rs @@ -166,6 +166,7 @@ where .finish_message(msg, receipt, failure_info, gas_cost) .map(|mut apply_ret| { apply_ret.exec_trace = exec_trace; + apply_ret.exec_stats = Some(stats); apply_ret }), ApplyKind::Implicit => Ok(ApplyRet { From 0d48a6c95a4d995bcdff2d498ba2560181617cc6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Mon, 25 Apr 2022 14:14:25 +0200 Subject: [PATCH 06/17] switch exec stats to minstant. --- fvm/Cargo.toml | 4 ++-- fvm/src/call_manager/default.rs | 3 ++- fvm/src/gas/tracer.rs | 7 ++++--- 3 files changed, 8 insertions(+), 6 deletions(-) diff --git a/fvm/Cargo.toml b/fvm/Cargo.toml index 61d017669..e3cfde308 100644 --- a/fvm/Cargo.toml +++ b/fvm/Cargo.toml @@ -39,7 +39,7 @@ log = "0.4.14" byteorder = "1.4.3" anymap = "0.12.1" blake2b_simd = "1.0.0" -minstant = { version = "0.1.1", optional = true } +minstant = { version = "0.1.1" } serde_json = { version = "1.0.79", optional = true } [dependencies.wasmtime] @@ -51,4 +51,4 @@ features = ["cranelift", "pooling-allocator", "parallel-compilation"] default = ["opencl"] opencl = ["filecoin-proofs-api/opencl"] cuda = ["filecoin-proofs-api/cuda"] -tracing = ["serde_json", "minstant"] +tracing = ["serde_json"] diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 00711d0a7..16dc82a08 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -4,7 +4,7 @@ use std::io::Write; #[cfg(feature = "tracing")] use std::ops::DerefMut; use std::sync::Mutex; -use std::time::{Duration, Instant}; +use std::time::Duration; use anyhow::Context as _; use derive_more::{Deref, DerefMut}; @@ -15,6 +15,7 @@ use fvm_shared::econ::TokenAmount; use fvm_shared::error::{ErrorNumber, ExitCode}; use fvm_shared::version::NetworkVersion; use fvm_shared::{ActorID, MethodNum, METHOD_SEND}; +use minstant::Instant; use num_traits::Zero; use super::{Backtrace, CallManager, ExecutionStats, InvocationResult, NO_DATA_BLOCK_ID}; diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs index a40f05901..93353c1d9 100644 --- a/fvm/src/gas/tracer.rs +++ b/fvm/src/gas/tracer.rs @@ -1,3 +1,4 @@ +use std::collections::LinkedList; use std::time::Duration; use cid::Cid; @@ -12,7 +13,7 @@ pub struct GasTracer { #[serde(skip_serializing)] previous: Instant, /// Accumulated traces. - traces: Vec, + traces: LinkedList, } impl GasTracer { @@ -40,10 +41,10 @@ impl GasTracer { } }, }; - self.traces.push(trace) + self.traces.push_back(trace) } - pub fn finish(self) -> Vec { + pub fn finish(self) -> LinkedList { self.traces } } From 265f57df983f10ccf59879a7ed567e7db0743256 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Mon, 25 Apr 2022 14:43:34 +0200 Subject: [PATCH 07/17] flatten traces. --- fvm/src/gas/tracer.rs | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs index 93353c1d9..f717c39e3 100644 --- a/fvm/src/gas/tracer.rs +++ b/fvm/src/gas/tracer.rs @@ -6,13 +6,10 @@ use fvm_shared::MethodNum; use minstant::Instant; use serde::Serialize; -#[derive(Debug, Serialize)] +#[derive(Debug)] pub struct GasTracer { - #[serde(skip_serializing)] started: Instant, - #[serde(skip_serializing)] previous: Instant, - /// Accumulated traces. traces: LinkedList, } @@ -51,13 +48,17 @@ impl GasTracer { #[derive(Debug, Serialize)] pub struct GasTrace { - /// Context annotates the trace with the source context. + /// Context annotates the trace with the source context. + #[serde(flatten)] pub context: Context, /// Point represents the location from where the trace was emitted. + #[serde(flatten)] pub point: Point, /// The consumption at the moment of trace. + #[serde(flatten)] pub consumption: Consumption, /// Timing information. + #[serde(flatten)] pub timing: Timing, } From 7730a4c83106f4c818865064a73e241938f37089 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Mon, 25 Apr 2022 19:45:02 +0200 Subject: [PATCH 08/17] simplify ownership of tracer; add benchmark. --- fvm/Cargo.toml | 8 +++++ fvm/benches/gas_tracing.rs | 39 ++++++++++++++++++++++++ fvm/src/call_manager/default.rs | 53 ++++++++++++++------------------- fvm/src/call_manager/mod.rs | 2 +- fvm/src/gas/tracer.rs | 37 +++++++++++------------ fvm/src/kernel/default.rs | 2 +- fvm/src/kernel/mod.rs | 2 +- testing/conformance/src/vm.rs | 10 +++---- 8 files changed, 93 insertions(+), 60 deletions(-) create mode 100644 fvm/benches/gas_tracing.rs diff --git a/fvm/Cargo.toml b/fvm/Cargo.toml index e3cfde308..864e4ccc1 100644 --- a/fvm/Cargo.toml +++ b/fvm/Cargo.toml @@ -42,6 +42,14 @@ blake2b_simd = "1.0.0" minstant = { version = "0.1.1" } serde_json = { version = "1.0.79", optional = true } +[dev-dependencies] +criterion = "0.3.5" + +[[bench]] +name = "gas_tracing" +harness = false +required-features = ["tracing"] + [dependencies.wasmtime] version = "0.35.2" default-features = false diff --git a/fvm/benches/gas_tracing.rs b/fvm/benches/gas_tracing.rs new file mode 100644 index 000000000..f75425203 --- /dev/null +++ b/fvm/benches/gas_tracing.rs @@ -0,0 +1,39 @@ +use std::time::Duration; + +use criterion::{criterion_group, criterion_main, BatchSize, BenchmarkId, Criterion, Throughput}; +use fvm::gas::tracer::{Consumption, Context, Event, GasTrace, Point}; + +pub fn benchmark_gas_tracing(c: &mut Criterion) { + let mut group = c.benchmark_group("gas_tracing"); + + for size in [16, 32, 64, 128, 256].iter() { + group.warm_up_time(Duration::from_secs(5)); + group.measurement_time(Duration::from_secs(20)); + group.throughput(Throughput::Elements(*size as u64)); + + group.bench_with_input(BenchmarkId::from_parameter(size), size, |b, &size| { + b.iter_batched_ref( + || GasTrace::start(), + move |gt| { + let ctx = Context { + code_cid: Default::default(), + method_num: size, + }; + let point = Point { + event: Event::Started, + label: "foo".to_string(), + }; + let consumption = Consumption { + fuel_consumed: Some(1234 + size), + gas_consumed: Some((1111 + size) as i64), + }; + gt.record(ctx, point, consumption); + }, + BatchSize::SmallInput, + ); + }); + } +} + +criterion_group!(benches, benchmark_gas_tracing); +criterion_main!(benches); diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 16dc82a08..e85ddff64 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -56,7 +56,7 @@ pub struct InnerDefaultCallManager { /// Stats related to the message execution. exec_stats: ExecutionStats, #[cfg(feature = "tracing")] - gas_tracer: Option>, + gas_trace: crate::gas::tracer::GasTrace, } #[doc(hidden)] @@ -101,18 +101,17 @@ where exec_trace: vec![], #[cfg(feature = "tracing")] - gas_tracer: { - use crate::gas::tracer::Point; - let mut tracer = crate::gas::tracer::GasTracer::new(); + gas_trace: { + let mut tracer = crate::gas::tracer::GasTrace::start(); tracer.record( Default::default(), - Point { + crate::gas::tracer::Point { event: crate::gas::tracer::Event::Started, label: Default::default(), }, Default::default(), ); - Some(std::cell::RefCell::new(tracer)) + tracer }, }))) } @@ -193,24 +192,20 @@ where #[cfg(feature = "tracing")] { use crate::gas::tracer::{Consumption, Point}; - let tracer = self.gas_tracer.take().unwrap(); - let traces = { - let mut tracer = tracer.into_inner(); - tracer.record( - Default::default(), - Point { - event: crate::gas::tracer::Event::Finished, - label: Default::default(), - }, - Consumption { - fuel_consumed: None, - gas_consumed: Some(self.gas_tracker.gas_used()), - }, - ); - tracer.finish() - }; + let gas_used = self.gas_tracker.gas_used(); + self.gas_trace.record( + Default::default(), + Point { + event: crate::gas::tracer::Event::Finished, + label: Default::default(), + }, + Consumption { + fuel_consumed: None, + gas_consumed: Some(gas_used), + }, + ); let mut tf = TRACE_FILE.lock().unwrap(); - serde_json::to_writer(tf.deref_mut(), &traces).unwrap(); + serde_json::to_writer(tf.deref_mut(), &self.gas_trace).unwrap(); tf.flush().unwrap(); } @@ -233,16 +228,12 @@ where #[cfg(feature = "tracing")] fn record_trace( - &self, + &mut self, context: crate::gas::tracer::Context, point: crate::gas::tracer::Point, consumption: crate::gas::tracer::Consumption, ) { - self.gas_tracer - .as_ref() - .unwrap() - .borrow_mut() - .record(context, point, consumption) + self.gas_trace.record(context, point, consumption) } // Accessor methods so the trait can implement some common methods by default. @@ -392,7 +383,7 @@ where { use crate::gas::tracer::{Consumption, Context, Point}; let gas_used = self.gas_tracker.gas_used(); - self.gas_tracer.as_mut().unwrap().get_mut().record( + self.gas_trace.record( Context { code_cid: state.code.clone(), method_num: method, @@ -510,7 +501,7 @@ where { use crate::gas::tracer::{Consumption, Context, Point}; let gas_used = cm.gas_tracker.gas_used(); - cm.gas_tracer.as_mut().unwrap().get_mut().record( + cm.gas_trace.record( Context { code_cid: state.code.clone(), method_num: method, diff --git a/fvm/src/call_manager/mod.rs b/fvm/src/call_manager/mod.rs index a04cb9df8..de63ecb2b 100644 --- a/fvm/src/call_manager/mod.rs +++ b/fvm/src/call_manager/mod.rs @@ -125,7 +125,7 @@ pub trait CallManager: 'static { /// Record a gas trace. #[cfg(feature = "tracing")] fn record_trace( - &self, + &mut self, context: crate::gas::tracer::Context, point: crate::gas::tracer::Point, consumption: crate::gas::tracer::Consumption, diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs index f717c39e3..9928b9f52 100644 --- a/fvm/src/gas/tracer.rs +++ b/fvm/src/gas/tracer.rs @@ -6,25 +6,27 @@ use fvm_shared::MethodNum; use minstant::Instant; use serde::Serialize; -#[derive(Debug)] -pub struct GasTracer { +#[derive(Debug, Serialize)] +pub struct GasTrace { + #[serde(skip)] started: Instant, + #[serde(skip)] previous: Instant, - traces: LinkedList, + spans: LinkedList, } -impl GasTracer { - pub fn new() -> GasTracer { +impl GasTrace { + pub fn start() -> GasTrace { let now = Instant::now(); - GasTracer { + GasTrace { started: now, previous: now, - traces: Default::default(), + spans: Default::default(), } } pub fn record(&mut self, context: Context, point: Point, consumption: Consumption) { - let trace = GasTrace { + let trace = GasSpan { context, point, consumption, @@ -38,16 +40,12 @@ impl GasTracer { } }, }; - self.traces.push_back(trace) - } - - pub fn finish(self) -> LinkedList { - self.traces + self.spans.push_back(trace) } } #[derive(Debug, Serialize)] -pub struct GasTrace { +pub struct GasSpan { /// Context annotates the trace with the source context. #[serde(flatten)] pub context: Context, @@ -115,8 +113,8 @@ pub enum Event { #[test] fn test_tracer() { - let mut tracer = GasTracer::new(); - tracer.record( + let mut trace = GasTrace::start(); + trace.record( Context { code_cid: Default::default(), method_num: 0, @@ -132,7 +130,7 @@ fn test_tracer() { ); std::thread::sleep(Duration::from_millis(1000)); - tracer.record( + trace.record( Context { code_cid: Default::default(), method_num: 0, @@ -146,10 +144,9 @@ fn test_tracer() { gas_consumed: None, }, ); - let traces = tracer.finish(); - println!("{:?}", traces); + println!("{:?}", trace); - let str = serde_json::to_string(&traces).unwrap(); + let str = serde_json::to_string(&trace).unwrap(); println!("{}", str); } diff --git a/fvm/src/kernel/default.rs b/fvm/src/kernel/default.rs index 0436ffde2..ff802aa9b 100644 --- a/fvm/src/kernel/default.rs +++ b/fvm/src/kernel/default.rs @@ -142,7 +142,7 @@ where #[cfg(feature = "tracing")] fn record_trace( - &self, + &mut self, point: crate::gas::tracer::Point, mut consumption: crate::gas::tracer::Consumption, ) { diff --git a/fvm/src/kernel/mod.rs b/fvm/src/kernel/mod.rs index 54f822244..10d14c07f 100644 --- a/fvm/src/kernel/mod.rs +++ b/fvm/src/kernel/mod.rs @@ -68,7 +68,7 @@ pub trait Kernel: #[cfg(feature = "tracing")] fn record_trace( - &self, + &mut self, point: crate::gas::tracer::Point, consumption: crate::gas::tracer::Consumption, ); diff --git a/testing/conformance/src/vm.rs b/testing/conformance/src/vm.rs index 83a6dc3d9..7abfcf474 100644 --- a/testing/conformance/src/vm.rs +++ b/testing/conformance/src/vm.rs @@ -3,9 +3,7 @@ use std::convert::TryFrom; use cid::Cid; use futures::executor::block_on; -use fvm::call_manager::{ - Backtrace, CallManager, DefaultCallManager, ExecutionStats, FinishRet, InvocationResult, -}; +use fvm::call_manager::{CallManager, DefaultCallManager, FinishRet, InvocationResult}; use fvm::gas::{GasTracker, PriceList}; use fvm::kernel::*; use fvm::machine::{DefaultMachine, Engine, Machine, MachineContext, NetworkConfig}; @@ -213,13 +211,13 @@ where }) } - fn finish(self) -> (FinishRet, ExecutionStats, Self::Machine) { + fn finish(self) -> (FinishRet, Self::Machine) { self.0.finish() } #[cfg(feature = "tracing")] fn record_trace( - &self, + &mut self, context: fvm::gas::tracer::Context, point: fvm::gas::tracer::Point, consumption: fvm::gas::tracer::Consumption, @@ -329,7 +327,7 @@ where #[cfg(feature = "tracing")] fn record_trace( - &self, + &mut self, point: fvm::gas::tracer::Point, consumption: fvm::gas::tracer::Consumption, ) { From 586a0b787a5c23a88d6dd2d7eae97fe21eb4d91d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Mon, 25 Apr 2022 20:44:47 +0200 Subject: [PATCH 09/17] enhance benchmarks. --- fvm/Cargo.toml | 1 + fvm/benches/gas_tracing.rs | 53 +++++++++++++++++++++++++++++++++----- fvm/src/gas/tracer.rs | 18 +++++++------ 3 files changed, 58 insertions(+), 14 deletions(-) diff --git a/fvm/Cargo.toml b/fvm/Cargo.toml index 864e4ccc1..31674b67e 100644 --- a/fvm/Cargo.toml +++ b/fvm/Cargo.toml @@ -44,6 +44,7 @@ serde_json = { version = "1.0.79", optional = true } [dev-dependencies] criterion = "0.3.5" +rand = "0.8.5" [[bench]] name = "gas_tracing" diff --git a/fvm/benches/gas_tracing.rs b/fvm/benches/gas_tracing.rs index f75425203..04805c59f 100644 --- a/fvm/benches/gas_tracing.rs +++ b/fvm/benches/gas_tracing.rs @@ -1,22 +1,25 @@ -use std::time::Duration; +use std::time::{Duration, Instant}; -use criterion::{criterion_group, criterion_main, BatchSize, BenchmarkId, Criterion, Throughput}; +use criterion::{ + black_box, criterion_group, criterion_main, BatchSize, BenchmarkId, Criterion, Throughput, +}; +use fvm::call_manager::ExecutionStats; use fvm::gas::tracer::{Consumption, Context, Event, GasTrace, Point}; +use rand::{thread_rng, Rng}; pub fn benchmark_gas_tracing(c: &mut Criterion) { let mut group = c.benchmark_group("gas_tracing"); for size in [16, 32, 64, 128, 256].iter() { - group.warm_up_time(Duration::from_secs(5)); - group.measurement_time(Duration::from_secs(20)); group.throughput(Throughput::Elements(*size as u64)); + let cid = cid::Cid::default(); group.bench_with_input(BenchmarkId::from_parameter(size), size, |b, &size| { b.iter_batched_ref( || GasTrace::start(), move |gt| { let ctx = Context { - code_cid: Default::default(), + code_cid: cid.clone(), method_num: size, }; let point = Point { @@ -35,5 +38,43 @@ pub fn benchmark_gas_tracing(c: &mut Criterion) { } } -criterion_group!(benches, benchmark_gas_tracing); +pub fn benchmark_accumulator(c: &mut Criterion) { + let mut group = c.benchmark_group("accumulator"); + + group.bench_function("exec stats accumulator", |b| { + // generate a random number to perform math with + let r: u64 = thread_rng().gen(); + b.iter_batched_ref( + || (ExecutionStats::default(), Instant::now()), + move |(exec_stats, now)| { + let call_duration = now.elapsed(); + exec_stats.fuel_used += r; + exec_stats.call_count += 1; + exec_stats.call_overhead += call_duration; + exec_stats.wasm_duration += + (call_duration + call_duration).max(Duration::default()); + }, + BatchSize::SmallInput, + ) + }); +} + +pub fn benchmark_time(c: &mut Criterion) { + let mut group = c.benchmark_group("time"); + + group.bench_function("std::time::Instant::now()", |b| { + b.iter(|| black_box(std::time::Instant::now())) + }); + group.bench_function("minstant::Instant::now()", |b| { + b.iter(|| black_box(minstant::Instant::now())) + }); +} + +criterion_group!( + benches, + benchmark_gas_tracing, + benchmark_accumulator, + benchmark_time +); + criterion_main!(benches); diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs index 9928b9f52..72ad7617f 100644 --- a/fvm/src/gas/tracer.rs +++ b/fvm/src/gas/tracer.rs @@ -8,19 +8,18 @@ use serde::Serialize; #[derive(Debug, Serialize)] pub struct GasTrace { - #[serde(skip)] - started: Instant, #[serde(skip)] previous: Instant, + #[serde(skip)] + cum: Duration, spans: LinkedList, } impl GasTrace { pub fn start() -> GasTrace { - let now = Instant::now(); GasTrace { - started: now, - previous: now, + previous: Instant::now(), + cum: Default::default(), spans: Default::default(), } } @@ -32,11 +31,14 @@ impl GasTrace { consumption, timing: { let now = Instant::now(); - let prev = self.previous; + let elapsed_rel = now - self.previous; + + self.cum += elapsed_rel; self.previous = now; + Timing { - elapsed_cum: now.duration_since(self.started), - elapsed_rel: now.duration_since(prev), + elapsed_cum: self.cum, + elapsed_rel, } }, }; From 63b4f7e68fc27151e69785e7e501d96a99d31f9a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Mon, 25 Apr 2022 20:52:31 +0200 Subject: [PATCH 10/17] use minstant again; better benches. --- fvm/benches/gas_tracing.rs | 27 +++++++++++++++------------ fvm/src/gas/tracer.rs | 23 +++++++++++------------ fvm/src/machine/engine.rs | 2 +- fvm/src/syscalls/mod.rs | 3 ++- 4 files changed, 29 insertions(+), 26 deletions(-) diff --git a/fvm/benches/gas_tracing.rs b/fvm/benches/gas_tracing.rs index 04805c59f..bdcf0a30b 100644 --- a/fvm/benches/gas_tracing.rs +++ b/fvm/benches/gas_tracing.rs @@ -1,4 +1,4 @@ -use std::time::{Duration, Instant}; +use std::time::Duration; use criterion::{ black_box, criterion_group, criterion_main, BatchSize, BenchmarkId, Criterion, Throughput, @@ -7,28 +7,30 @@ use fvm::call_manager::ExecutionStats; use fvm::gas::tracer::{Consumption, Context, Event, GasTrace, Point}; use rand::{thread_rng, Rng}; -pub fn benchmark_gas_tracing(c: &mut Criterion) { - let mut group = c.benchmark_group("gas_tracing"); +pub fn benchmark_tracing(c: &mut Criterion) { + let mut group = c.benchmark_group("tracing"); - for size in [16, 32, 64, 128, 256].iter() { + for size in [32, 64, 128, 256].iter() { group.throughput(Throughput::Elements(*size as u64)); let cid = cid::Cid::default(); group.bench_with_input(BenchmarkId::from_parameter(size), size, |b, &size| { + // generate a random number to perform math with so that the compiler has no chance to optimize + let r: u64 = thread_rng().gen(); b.iter_batched_ref( || GasTrace::start(), move |gt| { let ctx = Context { - code_cid: cid.clone(), + code_cid: cid, // copy, include the Cid copy cost method_num: size, }; let point = Point { event: Event::Started, - label: "foo".to_string(), + label: "foo".to_string(), // include the string allocation cost }; let consumption = Consumption { - fuel_consumed: Some(1234 + size), - gas_consumed: Some((1111 + size) as i64), + fuel_consumed: Some(r), + gas_consumed: Some(r as i64), }; gt.record(ctx, point, consumption); }, @@ -42,11 +44,12 @@ pub fn benchmark_accumulator(c: &mut Criterion) { let mut group = c.benchmark_group("accumulator"); group.bench_function("exec stats accumulator", |b| { - // generate a random number to perform math with + // generate a random number to perform math with so that the compiler has no chance to optimize let r: u64 = thread_rng().gen(); b.iter_batched_ref( - || (ExecutionStats::default(), Instant::now()), - move |(exec_stats, now)| { + || ExecutionStats::default(), + move |exec_stats| { + let now = minstant::Instant::now(); let call_duration = now.elapsed(); exec_stats.fuel_used += r; exec_stats.call_count += 1; @@ -72,7 +75,7 @@ pub fn benchmark_time(c: &mut Criterion) { criterion_group!( benches, - benchmark_gas_tracing, + benchmark_tracing, benchmark_accumulator, benchmark_time ); diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs index 72ad7617f..d94f8d646 100644 --- a/fvm/src/gas/tracer.rs +++ b/fvm/src/gas/tracer.rs @@ -25,22 +25,21 @@ impl GasTrace { } pub fn record(&mut self, context: Context, point: Point, consumption: Consumption) { + let now = Instant::now(); + let elapsed_rel = now - self.previous; + + self.cum += elapsed_rel; + self.previous = now; + + let timing = Timing { + elapsed_cum: self.cum, + elapsed_rel, + }; let trace = GasSpan { context, point, consumption, - timing: { - let now = Instant::now(); - let elapsed_rel = now - self.previous; - - self.cum += elapsed_rel; - self.previous = now; - - Timing { - elapsed_cum: self.cum, - elapsed_rel, - } - }, + timing, }; self.spans.push_back(trace) } diff --git a/fvm/src/machine/engine.rs b/fvm/src/machine/engine.rs index 4447cb84f..d6a5384ff 100644 --- a/fvm/src/machine/engine.rs +++ b/fvm/src/machine/engine.rs @@ -2,11 +2,11 @@ use std::collections::hash_map::Entry; use std::collections::HashMap; use std::ops::Deref; use std::sync::{Arc, Mutex}; -use std::time::Instant; use anyhow::anyhow; use cid::Cid; use fvm_ipld_blockstore::Blockstore; +use minstant::Instant; use wasmtime::{Linker, Module, Trap}; use crate::syscalls::{bind_syscalls, InvocationData}; diff --git a/fvm/src/syscalls/mod.rs b/fvm/src/syscalls/mod.rs index 81905ad7b..dbbff18da 100644 --- a/fvm/src/syscalls/mod.rs +++ b/fvm/src/syscalls/mod.rs @@ -1,6 +1,7 @@ -use std::time::{Duration, Instant}; +use std::time::Duration; use cid::Cid; +use minstant::Instant; use wasmtime::Linker; use crate::call_manager::backtrace; From a5d4a3841945f86aa6e473dcc3346466be7741f7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Tue, 26 Apr 2022 22:14:55 +0200 Subject: [PATCH 11/17] switch to a rotating log scheme. --- fvm/Cargo.toml | 3 ++- fvm/src/call_manager/default.rs | 17 ++++++++++++----- fvm/src/gas/tracer.rs | 6 +++++- 3 files changed, 19 insertions(+), 7 deletions(-) diff --git a/fvm/Cargo.toml b/fvm/Cargo.toml index 31674b67e..db23e43b5 100644 --- a/fvm/Cargo.toml +++ b/fvm/Cargo.toml @@ -41,6 +41,7 @@ anymap = "0.12.1" blake2b_simd = "1.0.0" minstant = { version = "0.1.1" } serde_json = { version = "1.0.79", optional = true } +file-rotate = { version = "0.6.0", optional = true } [dev-dependencies] criterion = "0.3.5" @@ -60,4 +61,4 @@ features = ["cranelift", "pooling-allocator", "parallel-compilation"] default = ["opencl"] opencl = ["filecoin-proofs-api/opencl"] cuda = ["filecoin-proofs-api/cuda"] -tracing = ["serde_json"] +tracing = ["serde_json", "file-rotate"] diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index e85ddff64..e3e5d0af8 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -1,7 +1,7 @@ use std::cmp::max; +use std::env; #[cfg(feature = "tracing")] use std::io::Write; -#[cfg(feature = "tracing")] use std::ops::DerefMut; use std::sync::Mutex; use std::time::Duration; @@ -76,9 +76,16 @@ impl std::ops::DerefMut for DefaultCallManager { } lazy_static::lazy_static! { - static ref TRACE_FILE : Mutex> = { - let f = std::fs::File::options().create(true).write(true).append(true).open("fuel_trace.json").unwrap(); - Mutex::new(std::io::BufWriter::new(f)) + static ref TRACE_FILE : Mutex> = { + use file_rotate::{FileRotate, ContentLimit, suffix::AppendCount, compression::Compression}; + let dir = env::var_os("FVM_GAS_TRACING_LOG").unwrap_or("gas_tracing".into()); + let ret = FileRotate::new( + dir.clone(), + AppendCount::new(usize::MAX), + ContentLimit::BytesSurpassed(1 << 30), + Compression::None + ); + Mutex::new(ret) }; } @@ -205,7 +212,7 @@ where }, ); let mut tf = TRACE_FILE.lock().unwrap(); - serde_json::to_writer(tf.deref_mut(), &self.gas_trace).unwrap(); + serde_json::to_writer(tf.deref_mut(), &self.gas_trace.spans).unwrap(); tf.flush().unwrap(); } diff --git a/fvm/src/gas/tracer.rs b/fvm/src/gas/tracer.rs index d94f8d646..37e9ad45b 100644 --- a/fvm/src/gas/tracer.rs +++ b/fvm/src/gas/tracer.rs @@ -12,7 +12,7 @@ pub struct GasTrace { previous: Instant, #[serde(skip)] cum: Duration, - spans: LinkedList, + pub spans: LinkedList, } impl GasTrace { @@ -24,6 +24,10 @@ impl GasTrace { } } + pub fn finish(self) -> LinkedList { + self.spans + } + pub fn record(&mut self, context: Context, point: Point, consumption: Consumption) { let now = Instant::now(); let elapsed_rel = now - self.previous; From d8b38d36736e75f78aed2cc91e11b2ffd13b9c75 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Wed, 27 Apr 2022 13:26:23 +0200 Subject: [PATCH 12/17] write newline. --- fvm/src/call_manager/default.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index e3e5d0af8..7cd419a6e 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -212,7 +212,9 @@ where }, ); let mut tf = TRACE_FILE.lock().unwrap(); - serde_json::to_writer(tf.deref_mut(), &self.gas_trace.spans).unwrap(); + let mut w = tf.deref_mut(); + serde_json::to_writer(w, &self.gas_trace.spans).unwrap(); + writeln!(w); tf.flush().unwrap(); } From 69dd8fe5e41390e052b749862e54c7477273f752 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Wed, 27 Apr 2022 13:34:07 +0200 Subject: [PATCH 13/17] no rotate. --- fvm/src/call_manager/default.rs | 25 +++++++++++++++---------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 7cd419a6e..074aa13d4 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -76,17 +76,22 @@ impl std::ops::DerefMut for DefaultCallManager { } lazy_static::lazy_static! { - static ref TRACE_FILE : Mutex> = { - use file_rotate::{FileRotate, ContentLimit, suffix::AppendCount, compression::Compression}; - let dir = env::var_os("FVM_GAS_TRACING_LOG").unwrap_or("gas_tracing".into()); - let ret = FileRotate::new( - dir.clone(), - AppendCount::new(usize::MAX), - ContentLimit::BytesSurpassed(1 << 30), - Compression::None - ); - Mutex::new(ret) + static ref TRACE_FILE : Mutex> = { + let file = env::var_os("FVM_GAS_TRACING_LOG").unwrap_or("gas_tracing.ndjson".into()); + let f = std::fs::File::options().create(true).write(true).append(true).open(file).unwrap(); + Mutex::new(std::io::BufWriter::new(f)) }; + // static ref TRACE_FILE : Mutex> = { + // use file_rotate::{FileRotate, ContentLimit, suffix::AppendCount, compression::Compression}; + // let dir = env::var_os("FVM_GAS_TRACING_LOG").unwrap_or("gas_tracing".into()); + // let ret = FileRotate::new( + // dir.clone(), + // AppendCount::new(usize::MAX), + // ContentLimit::BytesSurpassed(1 << 30), + // Compression::None + // ); + // Mutex::new(ret) + // }; } impl CallManager for DefaultCallManager From 05aa524789b49b8e377282936f674417f7100f8c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Wed, 27 Apr 2022 13:45:01 +0200 Subject: [PATCH 14/17] fix --- fvm/src/call_manager/default.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 074aa13d4..827e3e2d5 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -217,9 +217,9 @@ where }, ); let mut tf = TRACE_FILE.lock().unwrap(); - let mut w = tf.deref_mut(); - serde_json::to_writer(w, &self.gas_trace.spans).unwrap(); - writeln!(w); + let w = tf.deref_mut(); + serde_json::to_writer(&mut *w, &self.gas_trace.spans).unwrap(); + writeln!(w).unwrap(); tf.flush().unwrap(); } From 8d8c2ccf8ce0b1c0b2a74818838de83265ee814b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Wed, 27 Apr 2022 13:53:22 +0200 Subject: [PATCH 15/17] entirely remove filerotate. --- fvm/Cargo.toml | 3 +-- fvm/src/call_manager/default.rs | 11 ----------- 2 files changed, 1 insertion(+), 13 deletions(-) diff --git a/fvm/Cargo.toml b/fvm/Cargo.toml index db23e43b5..31674b67e 100644 --- a/fvm/Cargo.toml +++ b/fvm/Cargo.toml @@ -41,7 +41,6 @@ anymap = "0.12.1" blake2b_simd = "1.0.0" minstant = { version = "0.1.1" } serde_json = { version = "1.0.79", optional = true } -file-rotate = { version = "0.6.0", optional = true } [dev-dependencies] criterion = "0.3.5" @@ -61,4 +60,4 @@ features = ["cranelift", "pooling-allocator", "parallel-compilation"] default = ["opencl"] opencl = ["filecoin-proofs-api/opencl"] cuda = ["filecoin-proofs-api/cuda"] -tracing = ["serde_json", "file-rotate"] +tracing = ["serde_json"] diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index 827e3e2d5..fe72564a2 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -81,17 +81,6 @@ lazy_static::lazy_static! { let f = std::fs::File::options().create(true).write(true).append(true).open(file).unwrap(); Mutex::new(std::io::BufWriter::new(f)) }; - // static ref TRACE_FILE : Mutex> = { - // use file_rotate::{FileRotate, ContentLimit, suffix::AppendCount, compression::Compression}; - // let dir = env::var_os("FVM_GAS_TRACING_LOG").unwrap_or("gas_tracing".into()); - // let ret = FileRotate::new( - // dir.clone(), - // AppendCount::new(usize::MAX), - // ContentLimit::BytesSurpassed(1 << 30), - // Compression::None - // ); - // Mutex::new(ret) - // }; } impl CallManager for DefaultCallManager From 588abec1e19db91e5fa28f6c4f2cb17d0d465b02 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Thu, 28 Apr 2022 23:12:09 +0200 Subject: [PATCH 16/17] exec stats: track number of syscalls and externs. --- fvm/src/call_manager/default.rs | 6 +++++- fvm/src/call_manager/mod.rs | 8 ++++++++ fvm/src/kernel/default.rs | 8 ++++++++ fvm/src/machine/engine.rs | 5 ++++- fvm/src/syscalls/mod.rs | 2 ++ testing/conformance/src/vm.rs | 8 +++++++- 6 files changed, 34 insertions(+), 3 deletions(-) diff --git a/fvm/src/call_manager/default.rs b/fvm/src/call_manager/default.rs index fe72564a2..06e75a686 100644 --- a/fvm/src/call_manager/default.rs +++ b/fvm/src/call_manager/default.rs @@ -2,7 +2,6 @@ use std::cmp::max; use std::env; #[cfg(feature = "tracing")] use std::io::Write; -use std::ops::DerefMut; use std::sync::Mutex; use std::time::Duration; @@ -257,6 +256,10 @@ where &mut self.gas_tracker } + fn exec_stats_mut(&mut self) -> &mut ExecutionStats { + &mut self.exec_stats + } + // Other accessor methods fn origin(&self) -> Address { @@ -531,6 +534,7 @@ where cm.exec_stats.wasm_duration += (invocation_data.actor_time - invocation_data.syscall_time) .max(Duration::default()); + cm.exec_stats.num_syscalls += invocation_data.num_syscalls; // Process the result, updating the backtrace if necessary. let ret = match result { diff --git a/fvm/src/call_manager/mod.rs b/fvm/src/call_manager/mod.rs index de63ecb2b..1e45103a4 100644 --- a/fvm/src/call_manager/mod.rs +++ b/fvm/src/call_manager/mod.rs @@ -122,6 +122,10 @@ pub trait CallManager: 'static { Ok(()) } + /// Returns a mutable reference to the execution stats to allow other + /// components to update them. + fn exec_stats_mut(&mut self) -> &mut ExecutionStats; + /// Record a gas trace. #[cfg(feature = "tracing")] fn record_trace( @@ -170,6 +174,10 @@ pub struct ExecutionStats { pub call_count: u64, /// Compute gas actually used. pub compute_gas: u64, + /// Number of syscalls invoked. + pub num_syscalls: u64, + /// Number of externs invoked. + pub num_externs: u64, } /// The returned values upon finishing a call manager. diff --git a/fvm/src/kernel/default.rs b/fvm/src/kernel/default.rs index ff802aa9b..06845f58a 100644 --- a/fvm/src/kernel/default.rs +++ b/fvm/src/kernel/default.rs @@ -364,6 +364,8 @@ where self.call_manager .charge_gas(self.call_manager.price_list().on_block_open_base())?; + self.call_manager.exec_stats_mut().num_externs += 1; + let data = self .call_manager .blockstore() @@ -662,6 +664,8 @@ where record_trace!(self, PreExtern, "verify_consensus_fault"); + self.call_manager.exec_stats_mut().num_externs += 1; + // This syscall cannot be resolved inside the FVM, so we need to traverse // the node boundary through an extern. let (fault, gas) = self @@ -874,6 +878,8 @@ where record_trace!(self, PreExtern, "get_chain_randomness"); + self.call_manager.exec_stats_mut().num_externs += 1; + // TODO: Check error code let ret = self .call_manager @@ -901,6 +907,8 @@ where record_trace!(self, PreExtern, "get_beacon_randomness"); + self.call_manager.exec_stats_mut().num_externs += 1; + // TODO: Check error code let ret = self .call_manager diff --git a/fvm/src/machine/engine.rs b/fvm/src/machine/engine.rs index d6a5384ff..10a4467ea 100644 --- a/fvm/src/machine/engine.rs +++ b/fvm/src/machine/engine.rs @@ -239,7 +239,10 @@ impl Engine { use wasmtime::CallHook::*; match h { CallingWasm => data.last_actor_call = Some(Instant::now()), - CallingHost => data.last_syscall_call = Some(Instant::now()), + CallingHost => { + data.last_syscall_call = Some(Instant::now()); + data.num_syscalls += 1; + } ReturningFromWasm => { data.actor_time += data .last_actor_call diff --git a/fvm/src/syscalls/mod.rs b/fvm/src/syscalls/mod.rs index dbbff18da..f738cb578 100644 --- a/fvm/src/syscalls/mod.rs +++ b/fvm/src/syscalls/mod.rs @@ -50,6 +50,7 @@ pub struct InvocationData { pub actor_time: Duration, pub last_syscall_call: Option, pub last_actor_call: Option, + pub num_syscalls: u64, } impl InvocationData { @@ -64,6 +65,7 @@ impl InvocationData { actor_time: Duration::default(), last_syscall_call: None, last_actor_call: None, + num_syscalls: 0, } } diff --git a/testing/conformance/src/vm.rs b/testing/conformance/src/vm.rs index 7abfcf474..6abe20ffe 100644 --- a/testing/conformance/src/vm.rs +++ b/testing/conformance/src/vm.rs @@ -3,7 +3,9 @@ use std::convert::TryFrom; use cid::Cid; use futures::executor::block_on; -use fvm::call_manager::{CallManager, DefaultCallManager, FinishRet, InvocationResult}; +use fvm::call_manager::{ + CallManager, DefaultCallManager, ExecutionStats, FinishRet, InvocationResult, +}; use fvm::gas::{GasTracker, PriceList}; use fvm::kernel::*; use fvm::machine::{DefaultMachine, Engine, Machine, MachineContext, NetworkConfig}; @@ -280,6 +282,10 @@ where fn charge_gas(&mut self, charge: fvm::gas::GasCharge) -> Result<()> { self.0.charge_gas(charge) } + + fn exec_stats_mut(&mut self) -> &mut ExecutionStats { + self.0.exec_stats_mut() + } } /// A kernel for intercepting syscalls. From 6a9d08f2786303df2d60fbfa69194ec09c8407be Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20Kripalani?= Date: Tue, 3 May 2022 22:42:22 +0100 Subject: [PATCH 17/17] capture bytes read/written. --- fvm/src/call_manager/mod.rs | 4 ++++ fvm/src/kernel/default.rs | 15 +++++++++------ 2 files changed, 13 insertions(+), 6 deletions(-) diff --git a/fvm/src/call_manager/mod.rs b/fvm/src/call_manager/mod.rs index 1e45103a4..8965ffc80 100644 --- a/fvm/src/call_manager/mod.rs +++ b/fvm/src/call_manager/mod.rs @@ -178,6 +178,10 @@ pub struct ExecutionStats { pub num_syscalls: u64, /// Number of externs invoked. pub num_externs: u64, + /// Number of bytes read from state via ipld::block_open. + pub block_bytes_read: u64, + /// Number of bytes staged/written via ipld::block_write. + pub block_bytes_written: u64, } /// The returned values upon finishing a call manager. diff --git a/fvm/src/kernel/default.rs b/fvm/src/kernel/default.rs index 06845f58a..cfa9d17d6 100644 --- a/fvm/src/kernel/default.rs +++ b/fvm/src/kernel/default.rs @@ -378,12 +378,12 @@ where .or_fatal()?; let block = Block::new(cid.codec(), data); + let size = block.size() as usize; - self.call_manager.charge_gas( - self.call_manager - .price_list() - .on_block_open_per_byte(block.size() as usize), - )?; + self.call_manager + .charge_gas(self.call_manager.price_list().on_block_open_per_byte(size))?; + + self.call_manager.exec_stats_mut().block_bytes_read += size as u64; let stat = block.stat(); @@ -393,8 +393,11 @@ where } fn block_create(&mut self, codec: u64, data: &[u8]) -> Result { + let size = data.len(); self.call_manager - .charge_gas(self.call_manager.price_list().on_block_create(data.len()))?; + .charge_gas(self.call_manager.price_list().on_block_create(size))?; + + self.call_manager.exec_stats_mut().block_bytes_written += size as u64; self.blocks .put(Block::new(codec, data))