GAS-1051: Gas time stats and visualization (to master) (filecoin-project#1259)

* GAS-1051: syscall (re-)pricing stats (filecoin-project#1054)
* GAS-1150: Add timers to new charges.
* GAS-1147: Visualize traces (filecoin-project#1148)
* GAS-1160: Calibration contract (filecoin-project#1192)

Author: aakoshh

.github/workflows/ci.yml

@@ -61,7 +61,7 @@ jobs:
             key: v3-cov
             covname: lcov.info
             command: llvm-cov
-            args: --all --exclude fvm --exclude fvm_conformance_tests --exclude fvm_integration_tests --exclude "*actor" --lcov --output-path lcov.info
+            args: --all --exclude fvm --exclude fvm_conformance_tests --exclude fvm_integration_tests --exclude fvm_gas_calibration --exclude "*actor" --lcov --output-path lcov.info
             components: llvm-tools-preview
           - name: integration
             key: v3

.gitignore

@@ -2,5 +2,6 @@ target
 *.wat
 *.wasm
 !testing/integration/tests/assets/*
+testing/conformance/traces
 .idea/
 lcov.info

Cargo.lock

@@ -6,8 +6,10 @@ members = [
     "shared",
     "testing/conformance",
     "testing/integration",
+    "testing/calibration",
     "ipld/*",
-    "testing/integration/tests/*-actor"
+    "testing/integration/tests/*-actor",
+    "testing/calibration/contract/*-actor"
 ]
 
 [profile.actor]

Cargo.toml

@@ -42,6 +42,8 @@ yastl = "0.1.2"
 arbitrary = { version = "1.1.0", optional = true, features = ["derive"] }
 rand = "0.8.5"
 quickcheck = { version = "1", optional = true }
+once_cell = "1.5"
+minstant = "0.1.2"
 
 [dev-dependencies]
 pretty_assertions = "1.2.1"

fvm/Cargo.toml

@@ -19,7 +19,7 @@ use super::{Backtrace, CallManager, InvocationResult, NO_DATA_BLOCK_ID};
 use crate::call_manager::backtrace::Frame;
 use crate::call_manager::FinishRet;
 use crate::engine::Engine;
-use crate::gas::{Gas, GasTracker};
+use crate::gas::{Gas, GasTimer, GasTracker};
 use crate::kernel::{Block, BlockRegistry, ExecutionError, Kernel, Result, SyscallError};
 use crate::machine::limiter::ExecMemory;
 use crate::machine::Machine;
@@ -309,6 +309,7 @@ where
         actor_id: ActorID,
         predictable_address: Option<Address>,
     ) -> Result<()> {
+        let start = GasTimer::start();
         // TODO https://github.com/filecoin-project/builtin-actors/issues/492
         let singleton = self.machine.builtin_actors().is_singleton_actor(&code_id);
 
@@ -346,9 +347,10 @@ where
             // Create a new actor.
             None => (ActorState::new_empty(code_id, predictable_address), true),
         };
-        self.charge_gas(self.price_list().on_create_actor(is_new))?;
+        let t = self.charge_gas(self.price_list().on_create_actor(is_new))?;
         self.state_tree_mut().set_actor(actor_id, actor)?;
         self.num_actors_created += 1;
+        t.stop_with(start);
         Ok(())
     }
 
@@ -381,7 +383,7 @@ where
     where
         K: Kernel<CallManager = Self>,
     {
-        self.charge_gas(self.price_list().on_create_actor(true))?;
+        let t = self.charge_gas(self.price_list().on_create_actor(true))?;
 
         if addr.is_bls_zero_address() {
             return Err(
@@ -408,6 +410,9 @@ where
             syscall_error!(IllegalArgument; "failed to serialize params: {}", e)
         })?;
 
+        // The cost of sending the message is measured independently.
+        t.stop();
+
         self.send_resolved::<K>(
             account_actor::SYSTEM_ACTOR_ID,
             id,
@@ -423,13 +428,13 @@ where
     where
         K: Kernel<CallManager = Self>,
     {
-        self.charge_gas(self.price_list().on_create_actor(true))?;
+        let t = self.charge_gas(self.price_list().on_create_actor(true))?;
 
         // Create the actor in the state tree, but don't call any constructor.
         let code_cid = self.builtin_actors().get_embryo_code();
 
         let state = ActorState::new_empty(*code_cid, Some(*addr));
-        self.machine.create_actor(addr, state)
+        t.record(self.machine.create_actor(addr, state))
     }
 
     /// Send without checking the call depth.
@@ -485,7 +490,7 @@ where
             .ok_or_else(|| syscall_error!(NotFound; "actor does not exist: {}", to))?;
 
         // Charge the method gas. Not sure why this comes second, but it does.
-        self.charge_gas(self.price_list().on_method_invocation(value, method))?;
+        let _ = self.charge_gas(self.price_list().on_method_invocation(value, method))?;
 
         // Transfer, if necessary.
         if !value.is_zero() {

fvm/src/call_manager/default.rs

@@ -7,7 +7,7 @@ use fvm_shared::error::ExitCode;
 use fvm_shared::{ActorID, MethodNum};
 
 use crate::engine::Engine;
-use crate::gas::{Gas, GasCharge, GasTracker, PriceList};
+use crate::gas::{Gas, GasCharge, GasTimer, GasTracker, PriceList};
 use crate::kernel::{self, Result};
 use crate::machine::{Machine, MachineContext};
 use crate::state_tree::StateTree;
@@ -147,9 +147,8 @@ pub trait CallManager: 'static {
     }
 
     /// Charge gas.
-    fn charge_gas(&self, charge: GasCharge) -> Result<()> {
-        self.gas_tracker().apply_charge(charge)?;
-        Ok(())
+    fn charge_gas(&self, charge: GasCharge) -> Result<GasTimer> {
+        self.gas_tracker().apply_charge(charge)
     }
 
     /// Limit memory usage throughout a message execution.

fvm/src/call_manager/mod.rs

@@ -16,10 +16,10 @@ use wasmtime::{
     Module, Mutability, PoolingAllocationStrategy, Val, ValType,
 };
 
-use crate::gas::WasmGasPrices;
+use crate::gas::{GasTimer, WasmGasPrices};
 use crate::machine::limiter::ExecMemory;
 use crate::machine::{Machine, NetworkConfig};
-use crate::syscalls::{bind_syscalls, charge_for_init, InvocationData};
+use crate::syscalls::{bind_syscalls, charge_for_init, record_init_time, InvocationData};
 use crate::Kernel;
 
 /// Container managing engines with different consensus-affecting configurations.
@@ -508,9 +508,15 @@ impl Engine {
             // pay for the minimum memory requirements. The module instrumentation in `inject` only
             // adds code to charge for _growing_ the memory, but not for the amount made accessible
             // initially. The limits are checked by wasmtime during instantiation, though.
-            charge_for_init(store, module)?;
+            let t = charge_for_init(store, module)?;
 
-            let inst = cache.linker.instantiate(store, module)?;
+            let inst = cache.linker.instantiate(&mut *store, module)?;
+
+            // Record the time it took for the linker to instantiate the module.
+            // This should also include everything that happens above in this method.
+            // Note that this does _not_ contain the time it took the load the Wasm file,
+            // which could have been cached already.
+            record_init_time(store, t);
 
             Ok(Some(inst))
         };
@@ -541,6 +547,7 @@ impl Engine {
             avail_gas_global: self.0.dummy_gas_global,
             last_milligas_available: 0,
             last_memory_bytes: memory_bytes,
+            last_charge_time: GasTimer::start(),
             memory: self.0.dummy_memory,
         };
 

fvm/src/engine.rs

@@ -129,7 +129,7 @@ where
 
                 // Charge for including the result (before we end the transaction).
                 if let Some(value) = &ret.value {
-                    cm.charge_gas(
+                    let _ = cm.charge_gas(
                         cm.context()
                             .price_list
                             .on_chain_return_value(value.size() as usize),

fvm/src/executor/default.rs

@@ -4,6 +4,7 @@
 
 use std::borrow::Cow;
 
+use super::timer::GasDuration;
 use super::Gas;
 
 /// Single gas charge in the VM. Contains information about what gas was for, as well
@@ -15,6 +16,8 @@ pub struct GasCharge {
     pub compute_gas: Gas,
     /// Storage costs
     pub storage_gas: Gas,
+    /// Execution time related to this charge, if traced and successfully measured.
+    pub elapsed: GasDuration,
 }
 
 impl GasCharge {
@@ -24,6 +27,7 @@ impl GasCharge {
             name,
             compute_gas,
             storage_gas,
+            elapsed: GasDuration::default(),
         }
     }
 

fvm/src/gas/charge.rs

@@ -11,11 +11,13 @@ use num_traits::Zero;
 pub use self::charge::GasCharge;
 pub(crate) use self::outputs::GasOutputs;
 pub use self::price_list::{price_list_by_network_version, PriceList, WasmGasPrices};
+pub use self::timer::{GasInstant, GasTimer};
 use crate::kernel::{ExecutionError, Result};
 
 mod charge;
 mod outputs;
 mod price_list;
+mod timer;
 
 pub const MILLIGAS_PRECISION: i64 = 1000;
 
@@ -211,24 +213,31 @@ impl GasTracker {
 
     /// Safely consumes gas and returns an out of gas error if there is not sufficient
     /// enough gas remaining for charge.
-    pub fn charge_gas(&self, name: &str, to_use: Gas) -> Result<()> {
+    pub fn charge_gas(&self, name: &str, to_use: Gas) -> Result<GasTimer> {
         log::trace!("charging gas: {} {}", name, to_use);
+        let res = self.charge_gas_inner(to_use);
         if let Some(trace) = &self.trace {
-            trace
-                .borrow_mut()
-                .push(GasCharge::new(name.to_owned(), to_use, Gas::zero()))
+            let mut charge = GasCharge::new(name.to_owned(), to_use, Gas::zero());
+            let timer = GasTimer::new(&mut charge.elapsed);
+            trace.borrow_mut().push(charge);
+            res.map(|_| timer)
+        } else {
+            res.map(|_| GasTimer::empty())
         }
-        self.charge_gas_inner(to_use)
     }
 
     /// Applies the specified gas charge, where quantities are supplied in milligas.
-    pub fn apply_charge(&self, charge: GasCharge) -> Result<()> {
+    pub fn apply_charge(&self, mut charge: GasCharge) -> Result<GasTimer> {
         let to_use = charge.total();
         log::trace!("charging gas: {} {}", &charge.name, to_use);
+        let res = self.charge_gas_inner(to_use);
         if let Some(trace) = &self.trace {
+            let timer = GasTimer::new(&mut charge.elapsed);
             trace.borrow_mut().push(charge);
+            res.map(|_| timer)
+        } else {
+            res.map(|_| GasTimer::empty())
         }
-        self.charge_gas_inner(to_use)
     }
 
     /// Absorbs another GasTracker (usually a nested one) into this one, charging for gas
@@ -293,9 +302,9 @@ mod tests {
     #[allow(clippy::identity_op)]
     fn basic_gas_tracker() -> Result<()> {
         let t = GasTracker::new(Gas::new(20), Gas::new(10), false);
-        t.apply_charge(GasCharge::new("", Gas::new(5), Gas::zero()))?;
+        let _ = t.apply_charge(GasCharge::new("", Gas::new(5), Gas::zero()))?;
         assert_eq!(t.gas_used(), Gas::new(15));
-        t.apply_charge(GasCharge::new("", Gas::new(5), Gas::zero()))?;
+        let _ = t.apply_charge(GasCharge::new("", Gas::new(5), Gas::zero()))?;
         assert_eq!(t.gas_used(), Gas::new(20));
         assert!(t
             .apply_charge(GasCharge::new("", Gas::new(1), Gas::zero()))