Add duration to snapshot compute-state json output

src/interpreter/vm.rs

@@ -53,6 +53,7 @@ use fvm_ipld_blockstore::Blockstore;
 use fvm_ipld_encoding::{to_vec, RawBytes};
 use fvm_shared2::clock::ChainEpoch;
 use num::Zero;
+use std::time::{Duration, Instant};
 
 pub(in crate::interpreter) type ForestMachineV2<DB> =
     DefaultMachine_v2<Arc<DB>, ForestExternsV2<DB>>;
@@ -72,6 +73,8 @@ type ForestExecutorV2<DB> = DefaultExecutor_v2<ForestKernelV2<DB>>;
 type ForestExecutorV3<DB> = DefaultExecutor_v3<ForestKernelV3<DB>>;
 type ForestExecutorV4<DB> = DefaultExecutor_v4<ForestKernelV4<DB>>;
 
+type ApplyResult = anyhow::Result<(ApplyRet, Duration)>;
+
 /// Comes from <https://github.com/filecoin-project/lotus/blob/v1.23.2/chain/vm/fvm.go#L473>
 const IMPLICIT_MESSAGE_GAS_LIMIT: i64 = i64::MAX / 2;
 
@@ -323,7 +326,7 @@ where
         }
         .into();
 
-        let ret = self.apply_implicit_message(&cron_msg)?;
+        let (ret, duration) = self.apply_implicit_message(&cron_msg)?;
         if let Some(err) = ret.failure_info() {
             anyhow::bail!("failed to apply block cron message: {}", err);
         }
@@ -334,6 +337,7 @@ where
                 message: &ChainMessage::Unsigned(cron_msg),
                 apply_ret: &ret,
                 at: CalledAt::Cron,
+                duration,
             })?;
         }
         Ok(())
@@ -362,14 +366,15 @@ where
                 if processed.contains(&cid) {
                     return Ok(());
                 }
-                let ret = self.apply_message(message)?;
+                let (ret, duration) = self.apply_message(message)?;
 
                 if let Some(cb) = &mut callback {
                     cb(&MessageCallbackCtx {
                         cid,
                         message,
                         apply_ret: &ret,
                         at: CalledAt::Applied,
+                        duration,
                     })?;
                 }
 
@@ -392,7 +397,7 @@ where
             if let Some(rew_msg) =
                 self.reward_message(epoch, block.miner, block.win_count, penalty, gas_reward)?
             {
-                let ret = self.apply_implicit_message(&rew_msg)?;
+                let (ret, duration) = self.apply_implicit_message(&rew_msg)?;
                 if let Some(err) = ret.failure_info() {
                     anyhow::bail!(
                         "failed to apply reward message for miner {}: {}",
@@ -414,6 +419,7 @@ where
                         message: &ChainMessage::Unsigned(rew_msg),
                         apply_ret: &ret,
                         at: CalledAt::Reward,
+                        duration,
                     })?
                 }
             }
@@ -427,42 +433,32 @@ where
     }
 
     /// Applies single message through VM and returns result from execution.
-    pub fn apply_implicit_message(&mut self, msg: &Message) -> anyhow::Result<ApplyRet> {
+    pub fn apply_implicit_message(&mut self, msg: &Message) -> ApplyResult {
+        let start = Instant::now();
+
         // raw_length is not used for Implicit messages.
         let raw_length = to_vec(msg).expect("encoding error").len();
 
-        match self {
-            VM::VM2(fvm_executor) => {
-                let ret = fvm_executor.execute_message(
-                    msg.into(),
-                    fvm2::executor::ApplyKind::Implicit,
-                    raw_length,
-                )?;
-                Ok(ret.into())
-            }
-            VM::VM3(fvm_executor) => {
-                let ret = fvm_executor.execute_message(
-                    msg.into(),
-                    fvm3::executor::ApplyKind::Implicit,
-                    raw_length,
-                )?;
-                Ok(ret.into())
-            }
-            VM::VM4(fvm_executor) => {
-                let ret = fvm_executor.execute_message(
-                    msg.into(),
-                    fvm4::executor::ApplyKind::Implicit,
-                    raw_length,
-                )?;
-                Ok(ret.into())
-            }
-        }
+        let ret = match self {
+            VM::VM2(fvm_executor) => fvm_executor
+                .execute_message(msg.into(), fvm2::executor::ApplyKind::Implicit, raw_length)?
+                .into(),
+            VM::VM3(fvm_executor) => fvm_executor
+                .execute_message(msg.into(), fvm3::executor::ApplyKind::Implicit, raw_length)?
+                .into(),
+            VM::VM4(fvm_executor) => fvm_executor
+                .execute_message(msg.into(), fvm4::executor::ApplyKind::Implicit, raw_length)?
+                .into(),
+        };
+        Ok((ret, start.elapsed()))
     }
 
     /// Applies the state transition for a single message.
     /// Returns `ApplyRet` structure which contains the message receipt and some
     /// meta data.
-    pub fn apply_message(&mut self, msg: &ChainMessage) -> anyhow::Result<ApplyRet> {
+    pub fn apply_message(&mut self, msg: &ChainMessage) -> ApplyResult {
+        let start = Instant::now();
+
         // Basic validity check
         msg.message().check()?;
 
@@ -509,14 +505,15 @@ where
                 ret.into()
             }
         };
+        let duration = start.elapsed();
 
         let exit_code = ret.msg_receipt().exit_code();
 
         if !exit_code.is_success() {
             tracing::debug!(?exit_code, "VM message execution failure.")
         }
 
-        Ok(ret)
+        Ok((ret, duration))
     }
 
     fn reward_message(
@@ -556,6 +553,7 @@ pub struct MessageCallbackCtx<'a> {
     pub message: &'a ChainMessage,
     pub apply_ret: &'a ApplyRet,
     pub at: CalledAt,
+    pub duration: Duration,
 }
 
 #[derive(Debug, Clone, Copy)]

src/shim/gas.rs

@@ -2,7 +2,9 @@
 // SPDX-License-Identifier: Apache-2.0, MIT
 use std::fmt::{Debug, Display};
 
-pub use super::fvm_latest::gas::{Gas as Gas_latest, GasCharge as GasCharge_latest};
+pub use super::fvm_latest::gas::{
+    Gas as Gas_latest, GasCharge as GasCharge_latest, GasDuration as GasDuration_latest,
+};
 use fvm2::gas::{
     price_list_by_network_version as price_list_by_network_version_v2, Gas as GasV2,
     GasCharge as GasChargeV2, PriceList as PriceListV2,
@@ -22,6 +24,9 @@ use crate::shim::version::NetworkVersion;
 #[derive(Hash, Eq, PartialEq, Ord, PartialOrd, Copy, Clone, Default)]
 pub struct Gas(Gas_latest);
 
+#[derive(Clone, Default)]
+pub struct GasDuration(GasDuration_latest);
+
 impl Debug for Gas {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
         if self.0.as_milligas() == 0 {
@@ -58,6 +63,16 @@ impl Gas {
     }
 }
 
+impl GasDuration {
+    pub fn as_nanos(&self) -> u64 {
+        if let Some(duration) = self.0.get() {
+            duration.as_nanos().clamp(0, u64::MAX as u128) as u64
+        } else {
+            0
+        }
+    }
+}
+
 impl From<GasV2> for Gas {
     fn from(value: GasV2) -> Self {
         Gas(Gas_latest::from_milligas(value.as_milligas() as _))
@@ -112,6 +127,9 @@ impl GasCharge {
     pub fn other_gas(&self) -> Gas {
         self.0.other_gas.into()
     }
+    pub fn elapsed(&self) -> GasDuration {
+        self.0.elapsed.clone().into()
+    }
 }
 
 impl From<GasChargeV2> for GasCharge {
@@ -172,6 +190,12 @@ impl From<GasCharge> for GasChargeV4 {
     }
 }
 
+impl From<GasDurationV4> for GasDuration {
+    fn from(value: GasDurationV4) -> Self {
+        GasDuration(value)
+    }
+}
+
 pub enum PriceList {
     V2(&'static PriceListV2),
     V3(&'static PriceListV3),

src/shim/trace.rs

@@ -6,6 +6,7 @@ use crate::shim::{
     error::ExitCode as ShimExitCode, gas::GasCharge as ShimGasCharge,
     kernel::SyscallError as ShimSyscallError,
 };
+use cid::Cid;
 use fvm2::trace::ExecutionEvent as E2;
 use fvm3::trace::ExecutionEvent as E3;
 use fvm4::trace::ExecutionEvent as E4;
@@ -20,6 +21,7 @@ pub enum ExecutionEvent {
     CallAbort(ShimExitCode),
     CallError(ShimSyscallError),
     Log(String),
+    InvokeActor(Cid),
     Unknown(Either<E3, Either<E4, E2>>),
 }
 
@@ -98,6 +100,7 @@ impl From<E3> for ExecutionEvent {
                 data: Either::Right(data),
             }),
             E3::CallError(err) => EShim::CallError(err.into()),
+            E3::InvokeActor(cid) => EShim::InvokeActor(cid),
             e => EShim::Unknown(Either::Left(e)),
         }
     }
@@ -129,6 +132,7 @@ impl From<E4> for ExecutionEvent {
                 data: Either::Right(data),
             }),
             E4::CallError(err) => EShim::CallError(err.into()),
+            E4::InvokeActor(cid) => EShim::InvokeActor(cid),
             e => EShim::Unknown(Either::Right(Either::Left(e))),
         }
     }

src/state_manager/mod.rs

@@ -424,7 +424,7 @@ where
             .get_actor(&msg.from, *bstate)?
             .ok_or_else(|| Error::Other("Could not get actor".to_string()))?;
         msg.sequence = actor.sequence;
-        let apply_ret = vm.apply_implicit_message(msg)?;
+        let (apply_ret, _) = vm.apply_implicit_message(msg)?;
         trace!(
             "gas limit {:},gas premium{:?},value {:?}",
             msg.gas_limit,
@@ -502,7 +502,7 @@ where
             .ok_or_else(|| Error::Other("cant find actor in state tree".to_string()))?;
         message.set_sequence(from_actor.sequence);
 
-        let ret = vm.apply_message(message)?;
+        let (ret, _) = vm.apply_message(message)?;
 
         Ok(InvocResult {
             msg: message.message().clone(),

src/tool/subcommands/snapshot_cmd.rs

@@ -436,7 +436,12 @@ fn print_computed_state(snapshot: PathBuf, epoch: ChainEpoch, json: bool) -> any
         &MultiEngine::default(),
         tipset,
         Some(|ctx: &MessageCallbackCtx| {
-            message_calls.push((ctx.message.clone(), ctx.apply_ret.clone(), ctx.at));
+            message_calls.push((
+                ctx.message.clone(),
+                ctx.apply_ret.clone(),
+                ctx.at,
+                ctx.duration,
+            ));
             anyhow::Ok(())
         }),
         match json {
@@ -476,16 +481,17 @@ mod structured {
     };
     use fvm_ipld_encoding::{ipld_block::IpldBlock, RawBytes};
     use itertools::Either;
+    use std::time::Duration;
 
     pub fn json(
         state_root: Cid,
-        contexts: Vec<(ChainMessage, ApplyRet, CalledAt)>,
+        contexts: Vec<(ChainMessage, ApplyRet, CalledAt, Duration)>,
     ) -> anyhow::Result<serde_json::Value> {
         Ok(json!({
         "Root": LotusJson(state_root),
         "Trace": contexts
             .into_iter()
-            .map(|(message, apply_ret, called_at)| call_json(message, apply_ret, called_at))
+            .map(|(message, apply_ret, called_at, duration)| call_json(message, apply_ret, called_at, duration))
             .collect::<Result<Vec<_>, _>>()?
         }))
     }
@@ -494,6 +500,7 @@ mod structured {
         chain_message: ChainMessage,
         apply_ret: ApplyRet,
         called_at: CalledAt,
+        duration: Duration,
     ) -> anyhow::Result<serde_json::Value> {
         use crate::lotus_json::Stringify;
 
@@ -518,8 +525,7 @@ mod structured {
                 "TotalCost": LotusJson(chain_message.message().required_funds() - &apply_ret.refund())
             },
             "ExecutionTrace": parse_events(apply_ret.exec_trace())?.map(CallTree::json),
-            // Only include timing fields for an easier diff with lotus
-            "Duration": null,
+            "Duration": duration.as_nanos().clamp(0, u64::MAX as u128) as u64,
         }))
     }
 
@@ -574,6 +580,7 @@ mod structured {
                 | ExecutionEvent::CallAbort(_)
                 | ExecutionEvent::CallError(_) => return Err(BuildCallTreeError::UnexpectedReturn),
                 ExecutionEvent::Log(_ignored) => {}
+                ExecutionEvent::InvokeActor(_cid) => {}
                 ExecutionEvent::Unknown(u) => {
                     return Err(BuildCallTreeError::UnrecognisedEvent(Box::new(u)))
                 }
@@ -719,6 +726,7 @@ mod structured {
                     ExecutionEvent::CallAbort(ab) => Some(CallTreeReturn::Abort(ab)),
                     ExecutionEvent::CallError(e) => Some(CallTreeReturn::Error(e)),
                     ExecutionEvent::Log(_ignored) => None,
+                    ExecutionEvent::InvokeActor(_cid) => None,
                     // RUST: This should be caught at compile time with #[deny(non_exhaustive_omitted_patterns)]
                     //       So that BuildCallTreeError::UnrecognisedEvent is never constructed
                     //       But that lint is not yet stabilised: https://github.com/rust-lang/rust/issues/89554
@@ -749,7 +757,7 @@ mod structured {
             "tg": gc.total().round_up(),
             "cg": gc.compute_gas().round_up(),
             "sg": gc.other_gas().round_up(),
-            "tt": null,
+            "tt": gc.elapsed().as_nanos(),
         })
     }