Add time tracker (#1279)

### What

Add a time tracker to the budget. 

### Why

Such that we can track the time spent in individual cost type, notably
`VmInstantiation`.
Combined with the cpu cost per type. We can come up with metrics in the
downstream such as "metered cpu per nsecs excluding VM".

### Known limitations

Most of types are not being tracked, and will show as 0. 
We are primarily interested in the `VmInstantiation` which is being
tracked.

---------

Co-authored-by: Graydon Hoare <graydon@pobox.com>

cackle.toml

@@ -125,6 +125,9 @@ allow_unsafe = true
 build.allow_apis = [
     "env",
 ]
+allow_apis = [
+    "time",
+]
 
 [pkg.unicode-ident]
 allow_unsafe = true

soroban-env-host/src/budget.rs

@@ -17,7 +17,7 @@ use std::{
 use crate::{
     host::error::TryBorrowOrErr,
     xdr::{ContractCostParams, ContractCostType, ScErrorCode, ScErrorType},
-    Host, HostError,
+    Error, Host, HostError,
 };
 
 use dimension::{BudgetDimension, IsCpu, IsShadowMode};
@@ -40,6 +40,8 @@ struct BudgetTracker {
     meter_count: u32,
     #[cfg(any(test, feature = "testutils", feature = "bench"))]
     wasm_memory: u64,
+    // Tracks the real time (in nsecs) spent on various `CostType`
+    time_tracker: [u64; ContractCostType::variants().len()],
 }
 
 impl Default for BudgetTracker {
@@ -49,6 +51,7 @@ impl Default for BudgetTracker {
             meter_count: Default::default(),
             #[cfg(any(test, feature = "testutils", feature = "bench"))]
             wasm_memory: Default::default(),
+            time_tracker: Default::default(),
         };
         for (ct, tracker) in ContractCostType::variants()
             .iter()
@@ -108,6 +111,24 @@ impl BudgetTracker {
         }
         self.wasm_memory = 0;
     }
+
+    fn track_time(&mut self, ty: ContractCostType, duration: u64) -> Result<(), HostError> {
+        let t = self.time_tracker.get_mut(ty as usize).ok_or_else(|| {
+            HostError::from(Error::from_type_and_code(
+                ScErrorType::Budget,
+                ScErrorCode::InternalError,
+            ))
+        })?;
+        *t += duration;
+        Ok(())
+    }
+
+    fn get_time(&self, ty: ContractCostType) -> Result<u64, HostError> {
+        self.time_tracker
+            .get(ty as usize)
+            .map(|t| *t)
+            .ok_or_else(|| (ScErrorType::Budget, ScErrorCode::InternalError).into())
+    }
 }
 
 #[derive(Clone)]
@@ -717,6 +738,17 @@ impl Budget {
             .ok_or_else(|| (ScErrorType::Budget, ScErrorCode::InternalError).into())
     }
 
+    pub fn get_time(&self, ty: ContractCostType) -> Result<u64, HostError> {
+        self.0.try_borrow_or_err()?.tracker.get_time(ty)
+    }
+
+    pub fn track_time(&self, ty: ContractCostType, duration: u64) -> Result<(), HostError> {
+        self.0
+            .try_borrow_mut_or_err()?
+            .tracker
+            .track_time(ty, duration)
+    }
+
     pub fn get_cpu_insns_consumed(&self) -> Result<u64, HostError> {
         Ok(self.0.try_borrow_or_err()?.cpu_insns.get_total_count())
     }

soroban-env-host/src/test/invocation.rs

@@ -33,6 +33,13 @@ fn invoke_single_contract_function() -> Result<(), HostError> {
         host.test_vec_obj(&[a, c])?,
     );
     let code = (ScErrorType::WasmVm, ScErrorCode::InvalidAction);
+
+    eprintln!(
+        "time ellapsed in nano-seconds for VmInstantiation: {}",
+        host.as_budget()
+            .get_time(ContractCostType::VmInstantiation)?
+    );
+
     assert!(HostError::result_matches_err(res, code));
     Ok(())
 }

soroban-env-host/src/vm.rs

@@ -24,7 +24,7 @@ use crate::{
     ConversionError, Host, HostError, Symbol, SymbolStr, TryIntoVal, Val, WasmiMarshal,
     DEFAULT_XDR_RW_LIMITS,
 };
-use std::{cell::RefCell, io::Cursor, rc::Rc};
+use std::{cell::RefCell, io::Cursor, rc::Rc, time::Instant};
 
 use fuel_refillable::FuelRefillable;
 use func_info::HOST_FUNCTIONS;
@@ -231,6 +231,7 @@ impl Vm {
         module_wasm_code: &[u8],
     ) -> Result<Rc<Self>, HostError> {
         let _span = tracy_span!("Vm::new");
+        let now = Instant::now();
 
         host.charge_budget(
             ContractCostType::VmInstantiation,
@@ -297,13 +298,19 @@ impl Vm {
         // Here we do _not_ supply the store with any fuel. Fuel is supplied
         // right before the VM is being run, i.e., before crossing the host->VM
         // boundary.
-        Ok(Rc::new(Self {
+        let vm = Rc::new(Self {
             contract_id,
             module,
             store: RefCell::new(store),
             instance,
             memory,
-        }))
+        });
+
+        host.as_budget().track_time(
+            ContractCostType::VmInstantiation,
+            now.elapsed().as_nanos() as u64,
+        )?;
+        Ok(vm)
     }
 
     pub(crate) fn get_memory(&self, host: &Host) -> Result<Memory, HostError> {