feat: measure fuel usage and timing stats

fvm/Cargo.toml

@@ -39,6 +39,17 @@ log = "0.4.14"
 byteorder = "1.4.3"
 anymap = "0.12.1"
 blake2b_simd = "1.0.0"
+minstant = { version = "0.1.1" }
+serde_json = { version = "1.0.79", optional = true }
+
+[dev-dependencies]
+criterion = "0.3.5"
+rand = "0.8.5"
+
+[[bench]]
+name = "gas_tracing"
+harness = false
+required-features = ["tracing"]
 
 [dependencies.wasmtime]
 version = "0.35.2"
@@ -49,5 +60,5 @@ features = ["cranelift", "pooling-allocator", "parallel-compilation"]
 default = ["opencl"]
 opencl = ["filecoin-proofs-api/opencl"]
 cuda = ["filecoin-proofs-api/cuda"]
+tracing = ["serde_json"]
 testing = []
-

fvm/benches/gas_tracing.rs

@@ -0,0 +1,83 @@
+use std::time::Duration;
+
+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_tracing(c: &mut Criterion) {
+    let mut group = c.benchmark_group("tracing");
+
+    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, // copy, include the Cid copy cost
+                        method_num: size,
+                    };
+                    let point = Point {
+                        event: Event::Started,
+                        label: "foo".to_string(), // include the string allocation cost
+                    };
+                    let consumption = Consumption {
+                        fuel_consumed: Some(r),
+                        gas_consumed: Some(r as i64),
+                    };
+                    gt.record(ctx, point, consumption);
+                },
+                BatchSize::SmallInput,
+            );
+        });
+    }
+}
+
+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 so that the compiler has no chance to optimize
+        let r: u64 = thread_rng().gen();
+        b.iter_batched_ref(
+            || 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;
+                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_tracing,
+    benchmark_accumulator,
+    benchmark_time
+);
+
+criterion_main!(benches);

fvm/src/call_manager/default.rs

@@ -1,6 +1,11 @@
 use std::cmp::max;
+use std::env;
+#[cfg(feature = "tracing")]
+use std::io::Write;
+use std::sync::Mutex;
+use std::time::Duration;
 
-use anyhow::Context;
+use anyhow::Context as _;
 use derive_more::{Deref, DerefMut};
 use fvm_ipld_encoding::{RawBytes, DAG_CBOR};
 use fvm_shared::actor::builtin::Type;
@@ -9,9 +14,10 @@ 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, InvocationResult, NO_DATA_BLOCK_ID};
+use super::{Backtrace, CallManager, ExecutionStats, InvocationResult, NO_DATA_BLOCK_ID};
 use crate::call_manager::backtrace::Frame;
 use crate::call_manager::FinishRet;
 use crate::gas::GasTracker;
@@ -46,6 +52,10 @@ pub struct InnerDefaultCallManager<M> {
     backtrace: Backtrace,
     /// The current execution trace.
     exec_trace: ExecutionTrace,
+    /// Stats related to the message execution.
+    exec_stats: ExecutionStats,
+    #[cfg(feature = "tracing")]
+    gas_trace: crate::gas::tracer::GasTrace,
 }
 
 #[doc(hidden)]
@@ -64,6 +74,14 @@ impl<M> std::ops::DerefMut for DefaultCallManager<M> {
     }
 }
 
+lazy_static::lazy_static! {
+    static ref TRACE_FILE : Mutex<std::io::BufWriter<std::fs::File>> = {
+        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))
+    };
+}
+
 impl<M> CallManager for DefaultCallManager<M>
 where
     M: Machine,
@@ -79,7 +97,22 @@ where
             num_actors_created: 0,
             call_stack_depth: 0,
             backtrace: Backtrace::default(),
+            exec_stats: ExecutionStats::default(),
             exec_trace: vec![],
+
+            #[cfg(feature = "tracing")]
+            gas_trace: {
+                let mut tracer = crate::gas::tracer::GasTrace::start();
+                tracer.record(
+                    Default::default(),
+                    crate::gas::tracer::Point {
+                        event: crate::gas::tracer::Event::Started,
+                        label: Default::default(),
+                    },
+                    Default::default(),
+                );
+                tracer
+            },
         })))
     }
 
@@ -156,20 +189,55 @@ where
     }
 
     fn finish(mut self) -> (FinishRet, Self::Machine) {
-        let gas_used = self.gas_tracker.gas_used().max(0);
+        #[cfg(feature = "tracing")]
+        {
+            use crate::gas::tracer::{Consumption, Point};
+            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();
+            let w = tf.deref_mut();
+            serde_json::to_writer(&mut *w, &self.gas_trace.spans).unwrap();
+            writeln!(w).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.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.
         (
             FinishRet {
                 gas_used,
                 backtrace: inner.backtrace,
+                exec_stats: stats,
                 exec_trace: inner.exec_trace,
             },
             inner.machine,
         )
     }
 
+    #[cfg(feature = "tracing")]
+    fn record_trace(
+        &mut self,
+        context: crate::gas::tracer::Context,
+        point: crate::gas::tracer::Point,
+        consumption: crate::gas::tracer::Consumption,
+    ) {
+        self.gas_trace.record(context, point, consumption)
+    }
+
     // Accessor methods so the trait can implement some common methods by default.
 
     fn machine(&self) -> &Self::Machine {
@@ -188,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 {
@@ -311,6 +383,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_trace.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.
@@ -368,7 +461,7 @@ where
                     // All actors will have an invoke method.
                     .map_err(Abort::Fatal)?;
 
-                // Invoke it.
+                // Invoke (and time) it.
                 let res = invoke.call(&mut store, (param_id,));
 
                 // Charge gas for the "latest" use of execution units (all the exec units used since the most recent syscall)
@@ -405,10 +498,44 @@ 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.into_call_manager();
 
+            #[cfg(feature = "tracing")]
+            {
+                use crate::gas::tracer::{Consumption, Context, Point};
+                let gas_used = cm.gas_tracker.gas_used();
+                cm.gas_trace.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.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.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 {
                 Ok(value) => Ok(InvocationResult::Return(value)),

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;
@@ -119,6 +121,19 @@ pub trait CallManager: 'static {
         self.gas_tracker_mut().charge_gas(charge)?;
         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(
+        &mut self,
+        context: crate::gas::tracer::Context,
+        point: crate::gas::tracer::Point,
+        consumption: crate::gas::tracer::Consumption,
+    );
 }
 
 /// The result of a method invocation.
@@ -147,9 +162,32 @@ impl InvocationResult {
     }
 }
 
+#[derive(Default, Clone, Debug)]
+pub struct ExecutionStats {
+    /// 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,
+    /// Number of syscalls invoked.
+    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.
 pub struct FinishRet {
     pub gas_used: i64,
     pub backtrace: Backtrace,
     pub exec_trace: ExecutionTrace,
+    pub exec_stats: ExecutionStats,
 }