svm repo split: fork measure (#7441)

Cargo.lock

@@ -364,7 +364,6 @@ dependencies = [
  "solana-keccak-hasher",
  "solana-last-restart-slot",
  "solana-loader-v3-interface",
- "solana-measure",
  "solana-poseidon",
  "solana-program",
  "solana-program-entrypoint",
@@ -380,6 +379,7 @@ dependencies = [
  "solana-svm-callback",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-timings",
  "solana-svm-type-overrides",
  "solana-sysvar",
@@ -7286,7 +7286,6 @@ dependencies = [
  "solana-last-restart-slot",
  "solana-loader-v3-interface",
  "solana-loader-v4-interface",
- "solana-measure",
  "solana-packet",
  "solana-program",
  "solana-program-entrypoint",
@@ -7299,6 +7298,7 @@ dependencies = [
  "solana-svm-callback",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-type-overrides",
  "solana-system-interface",
  "solana-transaction-context",
@@ -9047,13 +9047,13 @@ dependencies = [
  "solana-instruction",
  "solana-loader-v3-interface",
  "solana-loader-v4-interface",
- "solana-measure",
  "solana-packet",
  "solana-program-runtime",
  "solana-pubkey",
  "solana-sbpf",
  "solana-sdk-ids",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-type-overrides",
  "solana-sysvar",
  "solana-transaction-context",
@@ -9657,7 +9657,6 @@ dependencies = [
  "solana-instruction",
  "solana-keypair",
  "solana-last-restart-slot",
- "solana-measure",
  "solana-metrics",
  "solana-program-entrypoint",
  "solana-program-runtime",
@@ -9670,6 +9669,7 @@ dependencies = [
  "solana-svm-callback",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-timings",
  "solana-svm-transaction",
  "solana-svm-type-overrides",
@@ -10905,7 +10905,6 @@ dependencies = [
  "solana-loader-v4-interface",
  "solana-loader-v4-program",
  "solana-logger 3.0.0",
- "solana-measure",
  "solana-message",
  "solana-native-token",
  "solana-nonce",
@@ -10927,6 +10926,7 @@ dependencies = [
  "solana-svm-callback",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-timings",
  "solana-svm-transaction",
  "solana-svm-type-overrides",
@@ -10965,6 +10965,10 @@ dependencies = [
  "log",
 ]
 
+[[package]]
+name = "solana-svm-measure"
+version = "3.0.0"
+
 [[package]]
 name = "solana-svm-timings"
 version = "3.0.0"

Cargo.toml

@@ -105,6 +105,7 @@ members = [
     "svm-callback",
     "svm-feature-set",
     "svm-log-collector",
+    "svm-measure",
     "svm-timings",
     "svm-transaction",
     "svm-type-overrides",
@@ -523,6 +524,7 @@ solana-svm = { path = "svm", version = "=3.0.0" }
 solana-svm-callback = { path = "svm-callback", version = "=3.0.0" }
 solana-svm-feature-set = { path = "svm-feature-set", version = "=3.0.0" }
 solana-svm-log-collector = { path = "svm-log-collector", version = "=3.0.0" }
+solana-svm-measure = { path = "svm-measure", version = "=3.0.0" }
 solana-svm-timings = { path = "svm-timings", version = "=3.0.0" }
 solana-svm-transaction = { path = "svm-transaction", version = "=3.0.0" }
 solana-svm-type-overrides = { path = "svm-type-overrides", version = "=3.0.0" }

program-runtime/Cargo.toml

@@ -45,7 +45,6 @@ solana-frozen-abi-macro = { workspace = true, optional = true, features = [
 solana-hash = { workspace = true }
 solana-instruction = { workspace = true }
 solana-last-restart-slot = { workspace = true }
-solana-measure = { workspace = true }
 solana-metrics = { workspace = true, optional = true }
 solana-program-entrypoint = { workspace = true }
 solana-pubkey = { workspace = true }
@@ -56,6 +55,7 @@ solana-slot-hashes = { workspace = true }
 solana-svm-callback = { workspace = true }
 solana-svm-feature-set = { workspace = true }
 solana-svm-log-collector = { workspace = true }
+solana-svm-measure = { workspace = true }
 solana-svm-timings = { workspace = true }
 solana-svm-transaction = { workspace = true }
 solana-svm-type-overrides = { workspace = true }

program-runtime/src/invoke_context.rs

@@ -13,7 +13,6 @@ use {
     solana_epoch_schedule::EpochSchedule,
     solana_hash::Hash,
     solana_instruction::{error::InstructionError, AccountMeta, Instruction},
-    solana_measure::measure::Measure,
     solana_pubkey::Pubkey,
     solana_sbpf::{
         ebpf::MM_HEAP_START,
@@ -28,6 +27,7 @@ use {
     solana_svm_callback::InvokeContextCallback,
     solana_svm_feature_set::SVMFeatureSet,
     solana_svm_log_collector::{ic_msg, LogCollector},
+    solana_svm_measure::measure::Measure,
     solana_svm_timings::{ExecuteDetailsTimings, ExecuteTimings},
     solana_svm_transaction::{instruction::SVMInstruction, svm_message::SVMMessage},
     solana_svm_type_overrides::sync::Arc,

program-runtime/src/loaded_programs.rs

@@ -25,7 +25,7 @@ use {
     },
 };
 #[cfg(feature = "metrics")]
-use {solana_measure::measure::Measure, solana_svm_timings::ExecuteDetailsTimings};
+use {solana_svm_measure::measure::Measure, solana_svm_timings::ExecuteDetailsTimings};
 
 pub type ProgramRuntimeEnvironment = Arc<BuiltinProgram<InvokeContext<'static>>>;
 pub const MAX_LOADED_ENTRY_COUNT: usize = 512;

programs/bpf_loader/Cargo.toml

@@ -36,7 +36,6 @@ solana-clock = { workspace = true }
 solana-instruction = { workspace = true }
 solana-loader-v3-interface = { workspace = true, features = ["serde"] }
 solana-loader-v4-interface = { workspace = true, features = ["bincode"] }
-solana-measure = { workspace = true }
 solana-packet = { workspace = true }
 solana-program-entrypoint = { workspace = true }
 solana-program-runtime = { workspace = true }
@@ -45,6 +44,7 @@ solana-sbpf = { workspace = true }
 solana-sdk-ids = { workspace = true }
 solana-svm-feature-set = { workspace = true }
 solana-svm-log-collector = { workspace = true }
+solana-svm-measure = { workspace = true }
 solana-svm-type-overrides = { workspace = true }
 solana-system-interface = { workspace = true }
 solana-transaction-context = { workspace = true, features = ["bincode"] }

programs/bpf_loader/src/lib.rs

@@ -10,7 +10,6 @@ use {
     solana_loader_v3_interface::{
         instruction::UpgradeableLoaderInstruction, state::UpgradeableLoaderState,
     },
-    solana_measure::measure::Measure,
     solana_program_entrypoint::{MAX_PERMITTED_DATA_INCREASE, SUCCESS},
     solana_program_runtime::{
         execution_budget::MAX_INSTRUCTION_STACK_DEPTH,
@@ -38,6 +37,7 @@ use {
         bpf_loader, bpf_loader_deprecated, bpf_loader_upgradeable, loader_v4, native_loader,
     },
     solana_svm_log_collector::{ic_logger_msg, ic_msg, LogCollector},
+    solana_svm_measure::measure::Measure,
     solana_svm_type_overrides::sync::{atomic::Ordering, Arc},
     solana_system_interface::{instruction as system_instruction, MAX_PERMITTED_DATA_LENGTH},
     solana_transaction_context::{IndexOfAccount, InstructionContext, TransactionContext},

programs/loader-v4/Cargo.toml

@@ -33,13 +33,13 @@ solana-bpf-loader-program = { workspace = true, features = ["svm-internal"] }
 solana-instruction = { workspace = true }
 solana-loader-v3-interface = { workspace = true }
 solana-loader-v4-interface = { workspace = true, features = ["serde"] }
-solana-measure = { workspace = true }
 solana-packet = { workspace = true }
 solana-program-runtime = { workspace = true }
 solana-pubkey = { workspace = true }
 solana-sbpf = { workspace = true }
 solana-sdk-ids = { workspace = true }
 solana-svm-log-collector = { workspace = true }
+solana-svm-measure = { workspace = true }
 solana-svm-type-overrides = { workspace = true }
 solana-transaction-context = { workspace = true }
 

programs/loader-v4/src/lib.rs

@@ -10,7 +10,6 @@ use {
         state::{LoaderV4State, LoaderV4Status},
         DEPLOYMENT_COOLDOWN_IN_SLOTS,
     },
-    solana_measure::measure::Measure,
     solana_program_runtime::{
         invoke_context::InvokeContext,
         loaded_programs::{ProgramCacheEntry, ProgramCacheEntryOwner, ProgramCacheEntryType},
@@ -19,6 +18,7 @@ use {
     solana_sbpf::{declare_builtin_function, memory_region::MemoryMapping},
     solana_sdk_ids::{bpf_loader, bpf_loader_deprecated, bpf_loader_upgradeable, loader_v4},
     solana_svm_log_collector::{ic_logger_msg, LogCollector},
+    solana_svm_measure::measure::Measure,
     solana_svm_type_overrides::sync::Arc,
     solana_transaction_context::{BorrowedAccount, InstructionContext},
     std::{cell::RefCell, rc::Rc},

programs/sbf/Cargo.lock

@@ -155,7 +155,6 @@ dependencies = [
  "solana-instruction",
  "solana-keccak-hasher",
  "solana-loader-v3-interface 5.0.0",
- "solana-measure",
  "solana-poseidon",
  "solana-program-entrypoint",
  "solana-program-runtime",
@@ -168,6 +167,7 @@ dependencies = [
  "solana-svm-callback",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-timings",
  "solana-svm-type-overrides",
  "solana-sysvar",
@@ -5837,7 +5837,6 @@ dependencies = [
  "solana-instruction",
  "solana-loader-v3-interface 5.0.0",
  "solana-loader-v4-interface",
- "solana-measure",
  "solana-packet",
  "solana-program-entrypoint",
  "solana-program-runtime",
@@ -5846,6 +5845,7 @@ dependencies = [
  "solana-sdk-ids",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-type-overrides",
  "solana-system-interface",
  "solana-transaction-context",
@@ -7066,13 +7066,13 @@ dependencies = [
  "solana-instruction",
  "solana-loader-v3-interface 5.0.0",
  "solana-loader-v4-interface",
- "solana-measure",
  "solana-packet",
  "solana-program-runtime",
  "solana-pubkey",
  "solana-sbpf",
  "solana-sdk-ids",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-type-overrides",
  "solana-transaction-context",
 ]
@@ -7494,7 +7494,6 @@ dependencies = [
  "solana-hash",
  "solana-instruction",
  "solana-last-restart-slot",
- "solana-measure",
  "solana-metrics",
  "solana-program-entrypoint",
  "solana-pubkey",
@@ -7505,6 +7504,7 @@ dependencies = [
  "solana-svm-callback",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-timings",
  "solana-svm-transaction",
  "solana-svm-type-overrides",
@@ -9242,7 +9242,6 @@ dependencies = [
  "solana-loader-v3-interface 5.0.0",
  "solana-loader-v4-interface",
  "solana-loader-v4-program",
- "solana-measure",
  "solana-message",
  "solana-nonce",
  "solana-nonce-account",
@@ -9256,6 +9255,7 @@ dependencies = [
  "solana-svm-callback",
  "solana-svm-feature-set",
  "solana-svm-log-collector",
+ "solana-svm-measure",
  "solana-svm-timings",
  "solana-svm-transaction",
  "solana-svm-type-overrides",
@@ -9288,6 +9288,10 @@ dependencies = [
  "log",
 ]
 
+[[package]]
+name = "solana-svm-measure"
+version = "3.0.0"
+
 [[package]]
 name = "solana-svm-timings"
 version = "3.0.0"

svm-measure/Cargo.toml

@@ -0,0 +1,14 @@
+[package]
+name = "solana-svm-measure"
+description = "Timing measurement utilities for SVM"
+documentation = "https://docs.rs/solana-svm-measure"
+readme = "../README.md"
+version = { workspace = true }
+authors = { workspace = true }
+repository = { workspace = true }
+homepage = { workspace = true }
+license = { workspace = true }
+edition = { workspace = true }
+
+[package.metadata.docs.rs]
+targets = ["x86_64-unknown-linux-gnu"]

svm-measure/src/lib.rs

@@ -0,0 +1,3 @@
+#![allow(clippy::arithmetic_side_effects)]
+pub mod macros;
+pub mod measure;

svm-measure/src/macros.rs

@@ -0,0 +1,238 @@
+/// Measure this expression
+///
+/// Use `measure_time!()` when you have an expression that you want to measure.  `measure_time!()` will start
+/// a new [`Measure`], evaluate your expression, stop the [`Measure`], and then return the
+/// [`Measure`] object along with your expression's return value.
+///
+/// Use `measure_us!()` when you want to measure an expression in microseconds.
+///
+/// Use `meas_dur!()` when you want to measure an expression and get the Duration.
+///
+/// [`Measure`]: crate::measure::Measure
+///
+/// # Examples
+///
+/// ```
+/// // Measure functions
+/// # use solana_svm_measure::{measure_time, measure_us, meas_dur};
+/// # fn foo() {}
+/// # fn bar(x: i32) {}
+/// # fn add(x: i32, y: i32) -> i32 {x + y}
+/// let (result, measure) = measure_time!(foo(), "foo takes no parameters");
+/// let (result, measure) = measure_time!(bar(42), "bar takes one parameter");
+/// let (result, measure) = measure_time!(add(1, 2), "add takes two parameters and returns a value");
+/// let (result, measure_us) = measure_us!(add(1, 2));
+/// let (result, duration) = meas_dur!(add(1, 2));
+/// # assert_eq!(result, 1 + 2);
+/// ```
+///
+/// ```
+/// // Measure methods
+/// # use solana_svm_measure::{measure_time, measure_us, meas_dur};
+/// # struct Foo {
+/// #     f: i32,
+/// # }
+/// # impl Foo {
+/// #     fn frobnicate(&self, bar: i32) -> i32 {
+/// #         self.f * bar
+/// #     }
+/// # }
+/// let foo = Foo { f: 42 };
+/// let (result, measure) = measure_time!(foo.frobnicate(2), "measure methods");
+/// let (result, measure_us) = measure_us!(foo.frobnicate(2));
+/// let (result, duration) = meas_dur!(foo.frobnicate(2));
+/// # assert_eq!(result, 42 * 2);
+/// ```
+///
+/// ```
+/// // Measure expression blocks
+/// # use solana_svm_measure::measure_time;
+/// # fn complex_calculation() -> i32 { 42 }
+/// # fn complex_transform(x: i32) -> i32 { x + 3 }
+/// # fn record_result(y: i32) {}
+/// let (result, measure) = measure_time!(
+///     {
+///         let x = complex_calculation();
+///         # assert_eq!(x, 42);
+///         let y = complex_transform(x);
+///         # assert_eq!(y, 42 + 3);
+///         record_result(y);
+///         y
+///     },
+///     "measure a block of many operations",
+/// );
+/// # assert_eq!(result, 42 + 3);
+/// ```
+///
+/// ```
+/// // The `name` parameter is optional
+/// # use solana_svm_measure::{measure_time, measure_us};
+/// # fn meow() {};
+/// let (result, measure) = measure_time!(meow());
+/// let (result, measure_us) = measure_us!(meow());
+/// ```
+#[macro_export]
+macro_rules! measure_time {
+    ($val:expr, $name:tt $(,)?) => {{
+        let mut measure = $crate::measure::Measure::start($name);
+        let result = $val;
+        measure.stop();
+        (result, measure)
+    }};
+    ($val:expr) => {
+        measure_time!($val, "")
+    };
+}
+
+#[macro_export]
+macro_rules! measure_us {
+    ($expr:expr) => {{
+        let (result, duration) = $crate::meas_dur!($expr);
+        (result, duration.as_micros() as u64)
+    }};
+}
+
+/// Measures how long it takes to execute an expression, and returns a Duration
+///
+/// # Examples
+///
+/// ```
+/// # use solana_svm_measure::meas_dur;
+/// # fn meow(x: i32, y: i32) -> i32 {x + y}
+/// let (result, duration) = meas_dur!(meow(1, 2) + 3);
+/// # assert_eq!(result, 1 + 2 + 3);
+/// ```
+//
+// The macro name, `meas_dur`, is "measure" + "duration".
+// When said aloud, the pronunciation is close to "measure".
+#[macro_export]
+macro_rules! meas_dur {
+    ($expr:expr) => {{
+        let start = std::time::Instant::now();
+        let result = $expr;
+        (result, start.elapsed())
+    }};
+}
+
+#[cfg(test)]
+mod tests {
+    use std::{thread::sleep, time::Duration};
+
+    fn my_multiply(x: i32, y: i32) -> i32 {
+        x * y
+    }
+
+    fn square(x: i32) -> i32 {
+        my_multiply(x, x)
+    }
+
+    struct SomeStruct {
+        x: i32,
+    }
+    impl SomeStruct {
+        fn add_to(&self, x: i32) -> i32 {
+            x + self.x
+        }
+    }
+
+    #[test]
+    fn test_measure_macro() {
+        // Ensure that the measurement side actually works
+        {
+            let (_result, measure) = measure_time!(sleep(Duration::from_millis(1)), "test");
+            assert!(measure.as_s() > 0.0);
+            assert!(measure.as_ms() > 0);
+            assert!(measure.as_us() > 0);
+        }
+
+        // Ensure that the macro can be called with functions
+        {
+            let (result, _measure) = measure_time!(my_multiply(3, 4), "test");
+            assert_eq!(result, 3 * 4);
+
+            let (result, _measure) = measure_time!(square(5), "test");
+            assert_eq!(result, 5 * 5)
+        }
+
+        // Ensure that the macro can be called with methods
+        {
+            let some_struct = SomeStruct { x: 42 };
+            let (result, _measure) = measure_time!(some_struct.add_to(4), "test");
+            assert_eq!(result, 42 + 4);
+        }
+
+        // Ensure that the macro can be called with blocks
+        {
+            let (result, _measure) = measure_time!({ 1 + 2 }, "test");
+            assert_eq!(result, 3);
+        }
+
+        // Ensure that the macro can be called with a trailing comma
+        {
+            let (result, _measure) = measure_time!(square(5), "test",);
+            assert_eq!(result, 5 * 5)
+        }
+
+        // Ensure that the macro can be called without a name
+        {
+            let (result, _measure) = measure_time!(square(5));
+            assert_eq!(result, 5 * 5)
+        }
+    }
+
+    #[test]
+    fn test_measure_us_macro() {
+        // Ensure that the measurement side actually works
+        {
+            let (_result, measure) = measure_us!(sleep(Duration::from_millis(1)));
+            assert!(measure > 0);
+        }
+
+        // Ensure that the macro can be called with functions
+        {
+            let (result, _measure) = measure_us!(my_multiply(3, 4));
+            assert_eq!(result, 3 * 4);
+
+            let (result, _measure) = measure_us!(square(5));
+            assert_eq!(result, 5 * 5)
+        }
+
+        // Ensure that the macro can be called with methods
+        {
+            let some_struct = SomeStruct { x: 42 };
+            let (result, _measure) = measure_us!(some_struct.add_to(4));
+            assert_eq!(result, 42 + 4);
+        }
+
+        // Ensure that the macro can be called with blocks
+        {
+            let (result, _measure) = measure_us!({ 1 + 2 });
+            assert_eq!(result, 3);
+        }
+    }
+
+    #[test]
+    fn test_meas_dur_macro() {
+        // Ensure that the macro can be called with functions
+        {
+            let (result, _duration) = meas_dur!(my_multiply(3, 4));
+            assert_eq!(result, 3 * 4);
+
+            let (result, _duration) = meas_dur!(square(5));
+            assert_eq!(result, 5 * 5)
+        }
+
+        // Ensure that the macro can be called with methods
+        {
+            let some_struct = SomeStruct { x: 42 };
+            let (result, _duration) = meas_dur!(some_struct.add_to(4));
+            assert_eq!(result, 42 + 4);
+        }
+
+        // Ensure that the macro can be called with blocks
+        {
+            let (result, _duration) = meas_dur!({ 1 + 2 });
+            assert_eq!(result, 3);
+        }
+    }
+}

svm-measure/src/measure.rs

@@ -0,0 +1,145 @@
+use std::{
+    fmt,
+    time::{Duration, Instant},
+};
+
+#[derive(Debug)]
+pub struct Measure {
+    name: &'static str,
+    start: Instant,
+    duration: u64,
+}
+
+impl Measure {
+    pub fn start(name: &'static str) -> Self {
+        Self {
+            name,
+            start: Instant::now(),
+            duration: 0,
+        }
+    }
+
+    pub fn stop(&mut self) {
+        self.duration = self.start.elapsed().as_nanos() as u64;
+    }
+
+    pub fn as_ns(&self) -> u64 {
+        self.duration
+    }
+
+    pub fn as_us(&self) -> u64 {
+        self.duration / 1000
+    }
+
+    pub fn as_ms(&self) -> u64 {
+        self.duration / (1000 * 1000)
+    }
+
+    pub fn as_s(&self) -> f32 {
+        self.duration as f32 / (1000.0f32 * 1000.0f32 * 1000.0f32)
+    }
+
+    pub fn as_duration(&self) -> Duration {
+        Duration::from_nanos(self.as_ns())
+    }
+
+    pub fn end_as_ns(self) -> u64 {
+        self.start.elapsed().as_nanos() as u64
+    }
+
+    pub fn end_as_us(self) -> u64 {
+        self.start.elapsed().as_micros() as u64
+    }
+
+    pub fn end_as_ms(self) -> u64 {
+        self.start.elapsed().as_millis() as u64
+    }
+
+    pub fn end_as_s(self) -> f32 {
+        self.start.elapsed().as_secs_f32()
+    }
+
+    pub fn end_as_duration(self) -> Duration {
+        self.start.elapsed()
+    }
+}
+
+impl fmt::Display for Measure {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        if self.duration == 0 {
+            write!(f, "{} running", self.name)
+        } else if self.as_us() < 1 {
+            write!(f, "{} took {}ns", self.name, self.duration)
+        } else if self.as_ms() < 1 {
+            write!(f, "{} took {}us", self.name, self.as_us())
+        } else if self.as_s() < 1. {
+            write!(f, "{} took {}ms", self.name, self.as_ms())
+        } else {
+            write!(f, "{} took {:.1}s", self.name, self.as_s())
+        }
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use {super::*, std::thread::sleep};
+
+    #[test]
+    fn test_measure() {
+        let test_duration = Duration::from_millis(100);
+        let mut measure = Measure::start("test");
+        sleep(test_duration);
+        measure.stop();
+        assert!(measure.as_duration() >= test_duration);
+    }
+
+    #[test]
+    fn test_measure_as() {
+        let test_duration = Duration::from_millis(100);
+        let measure = Measure {
+            name: "test",
+            start: Instant::now(),
+            duration: test_duration.as_nanos() as u64,
+        };
+
+        assert!(f32::abs(measure.as_s() - 0.1f32) <= f32::EPSILON);
+        assert_eq!(measure.as_ms(), 100);
+        assert_eq!(measure.as_us(), 100_000);
+        assert_eq!(measure.as_ns(), 100_000_000);
+        assert_eq!(measure.as_duration(), test_duration);
+    }
+
+    #[test]
+    fn test_measure_display() {
+        let measure = Measure {
+            name: "test_ns",
+            start: Instant::now(),
+            duration: 1,
+        };
+        assert_eq!(format!("{measure}"), "test_ns took 1ns");
+
+        let measure = Measure {
+            name: "test_us",
+            start: Instant::now(),
+            duration: 1000,
+        };
+        assert_eq!(format!("{measure}"), "test_us took 1us");
+
+        let measure = Measure {
+            name: "test_ms",
+            start: Instant::now(),
+            duration: 1000 * 1000,
+        };
+        assert_eq!(format!("{measure}"), "test_ms took 1ms");
+
+        let measure = Measure {
+            name: "test_s",
+            start: Instant::now(),
+            duration: 1000 * 1000 * 1000,
+        };
+        assert_eq!(format!("{measure}"), "test_s took 1.0s");
+
+        let measure = Measure::start("test_not_stopped");
+        assert_eq!(format!("{measure}"), "test_not_stopped running");
+    }
+}

svm/Cargo.toml

@@ -56,7 +56,6 @@ solana-instructions-sysvar = { workspace = true }
 solana-loader-v3-interface = { workspace = true, features = ["bincode"] }
 solana-loader-v4-interface = { workspace = true }
 solana-loader-v4-program = { workspace = true }
-solana-measure = { workspace = true }
 solana-message = { workspace = true }
 solana-nonce = { workspace = true }
 solana-nonce-account = { workspace = true }
@@ -70,6 +69,7 @@ solana-sdk-ids = { workspace = true }
 solana-svm-callback = { workspace = true }
 solana-svm-feature-set = { workspace = true }
 solana-svm-log-collector = { workspace = true }
+solana-svm-measure = { workspace = true }
 solana-svm-timings = { workspace = true }
 solana-svm-transaction = { workspace = true }
 solana-svm-type-overrides = { workspace = true }

svm/src/message_processor.rs

@@ -1,6 +1,6 @@
 use {
-    solana_measure::measure_us,
     solana_program_runtime::invoke_context::InvokeContext,
+    solana_svm_measure::measure_us,
     solana_svm_timings::{ExecuteDetailsTimings, ExecuteTimings},
     solana_svm_transaction::svm_message::SVMMessage,
     solana_transaction_context::IndexOfAccount,

svm/src/transaction_processor.rs

@@ -24,7 +24,6 @@ use {
     solana_clock::{Epoch, Slot},
     solana_hash::Hash,
     solana_instruction::TRANSACTION_LEVEL_STACK_HEIGHT,
-    solana_measure::{measure::Measure, measure_us},
     solana_message::{
         compiled_instruction::CompiledInstruction,
         inner_instruction::{InnerInstruction, InnerInstructionsList},
@@ -49,6 +48,7 @@ use {
     solana_svm_callback::TransactionProcessingCallback,
     solana_svm_feature_set::SVMFeatureSet,
     solana_svm_log_collector::LogCollector,
+    solana_svm_measure::{measure::Measure, measure_us},
     solana_svm_timings::{ExecuteTimingType, ExecuteTimings},
     solana_svm_transaction::{svm_message::SVMMessage, svm_transaction::SVMTransaction},
     solana_svm_type_overrides::sync::{atomic::Ordering, Arc, RwLock, RwLockReadGuard},

syscalls/Cargo.toml

@@ -38,7 +38,6 @@ solana-hash = { workspace = true }
 solana-instruction = { workspace = true }
 solana-keccak-hasher = { workspace = true }
 solana-loader-v3-interface = { workspace = true, features = ["serde"] }
-solana-measure = { workspace = true }
 solana-poseidon = { workspace = true }
 solana-program-entrypoint = { workspace = true }
 solana-program-runtime = { workspace = true }
@@ -51,6 +50,7 @@ solana-stable-layout = { workspace = true }
 solana-svm-callback = { workspace = true }
 solana-svm-feature-set = { workspace = true }
 solana-svm-log-collector = { workspace = true }
+solana-svm-measure = { workspace = true }
 solana-svm-timings = { workspace = true }
 solana-svm-type-overrides = { workspace = true }
 solana-sysvar = { workspace = true }

syscalls/src/cpi.rs

@@ -3,13 +3,13 @@ use {
     crate::{translate_inner, translate_slice_inner, translate_type_inner},
     solana_instruction::Instruction,
     solana_loader_v3_interface::instruction as bpf_loader_upgradeable,
-    solana_measure::measure::Measure,
     solana_program_runtime::{
         invoke_context::SerializedAccountMetadata,
         serialization::{create_memory_region_of_account, modify_memory_region_of_account},
     },
     solana_sbpf::ebpf,
     solana_stable_layout::stable_instruction::StableInstruction,
+    solana_svm_measure::measure::Measure,
     solana_transaction_context::BorrowedAccount,
     std::mem,
 };