Add duration to snapshot compute-state json output (#3748)

CHANGELOG.md

@@ -29,6 +29,9 @@
 
 ### Added
 
+- [#3748](https://github.com/ChainSafe/forest/pull/3748) Add timing for each
+ message and gas charge in the JSON output of
+ `forest-tool snapshot compute-state` and `Filecoin.StateCall` RPC API.
 - [#3720](https://github.com/ChainSafe/forest/pull/3750) Implement the
  `Filecoin.StateMinerInfo` lotus-compatible RPC API.
 

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>>;
 
+pub type ApplyResult = anyhow::Result<(ApplyRet, Duration)>;
+
 /// Comes from <https://github.com/filecoin-project/lotus/blob/v1.23.2/chain/vm/fvm.go#L473>
 pub 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/state_manager/mod.rs

@@ -21,7 +21,8 @@ use crate::chain::{
  ChainStore, HeadChange,
 };
 use crate::interpreter::{
- resolve_to_key_addr, BlockMessages, CalledAt, ExecutionContext, IMPLICIT_MESSAGE_GAS_LIMIT, VM,
+ resolve_to_key_addr, ApplyResult, BlockMessages, CalledAt, ExecutionContext,
+ IMPLICIT_MESSAGE_GAS_LIMIT, VM,
 };
 use crate::message::{ChainMessage, Message as MessageTrait};
 use crate::networks::ChainConfig;
@@ -457,14 +458,14 @@ where
  let mut msg = msg.clone();
  msg.gas_limit = IMPLICIT_MESSAGE_GAS_LIMIT as u64;
 
- let apply_ret = vm.apply_implicit_message(&msg)?;
+ let (apply_ret, duration) = vm.apply_implicit_message(&msg)?;
 
  Ok(ApiInvocResult {
  msg: msg.clone(),
  msg_rct: Some(apply_ret.msg_receipt()),
  msg_cid: msg.cid().map_err(|err| Error::Other(err.to_string()))?,
  error: apply_ret.failure_info().unwrap_or_default(),
- duration: 0,
+ duration: duration.as_nanos().clamp(0, u64::MAX as u128) as u64,
  gas_cost: MessageGasCost::default(),
  execution_trace: structured::parse_events(apply_ret.exec_trace()).unwrap_or_default(),
  })
@@ -504,7 +505,7 @@ where
 
  // FVM requires a stack size of 64MiB. The alternative is to use `ThreadedExecutor` from
  // FVM, but that introduces some constraints, and possible deadlocks.
- let ret = stacker::grow(64 << 20, || -> anyhow::Result<ApplyRet> {
+ let (ret, _) = stacker::grow(64 << 20, || -> ApplyResult {
  let mut vm = VM::new(
  ExecutionContext {
  heaviest_tipset: Arc::clone(&ts),

src/state_manager/utils.rs

@@ -469,7 +469,7 @@ pub mod structured {
  total_gas: gc.total().round_up(),
  compute_gas: gc.compute_gas().round_up(),
  storage_gas: gc.other_gas().round_up(),
- time_taken: 0,
+ time_taken: gc.elapsed().as_nanos(),
  }
  }
 }

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 {
@@ -465,16 +470,17 @@ mod structured {
  message::{ChainMessage, Message as _},
  shim::executor::ApplyRet,
  };
+ 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<_>, _>>()?
  }))
  }
@@ -483,6 +489,7 @@ mod structured {
  chain_message: ChainMessage,
  apply_ret: ApplyRet,
  called_at: CalledAt,
+ duration: Duration,
  ) -> anyhow::Result<serde_json::Value> {
  use crate::lotus_json::Stringify;
 
@@ -507,8 +514,7 @@ mod structured {
  "TotalCost": LotusJson(chain_message.message().required_funds() - &apply_ret.refund())
  },
  "ExecutionTrace": LotusJson(structured::parse_events(apply_ret.exec_trace())?),
- // Only include timing fields for an easier diff with lotus
- "Duration": null,
+ "Duration": duration.as_nanos().clamp(0, u64::MAX as u128) as u64,
  }))
  }
 }