chore: cleanup metrics (#1947)

jonathanpwang · web-flow · commit be8d0d44e8c9 · 2025-08-07T16:57:58.000-07:00
- rename `execute_e3_time_ms` to `execute_preflight_time_ms` and now it
includes `memory_finalize_time_ms`.
- the `single_trace_gen` info spans are skipped if record is empty just
to reduce log verbosity
diff --git a/crates/prof/src/aggregate.rs b/crates/prof/src/aggregate.rs
@@ -355,7 +355,7 @@ impl AggregateMetrics {
                             metric_name, summary.avg, "-", "-", "-",
                         )?;
                     } else if metric_name == EXECUTE_E1_INSN_MI_S_LABEL
-                        || metric_name == EXECUTE_E3_INSN_MI_S_LABEL
+                        || metric_name == EXECUTE_PREFLIGHT_INSN_MI_S_LABEL
                         || metric_name == EXECUTE_METERED_INSN_MI_S_LABEL
                     {
                         // skip sum because it is misleading
@@ -469,8 +469,8 @@ pub const EXECUTE_E1_TIME_LABEL: &str = "execute_e1_time_ms";
 pub const EXECUTE_E1_INSN_MI_S_LABEL: &str = "execute_e1_insn_mi/s";
 pub const EXECUTE_METERED_TIME_LABEL: &str = "execute_metered_time_ms";
 pub const EXECUTE_METERED_INSN_MI_S_LABEL: &str = "execute_metered_insn_mi/s";
-pub const EXECUTE_E3_TIME_LABEL: &str = "execute_e3_time_ms";
-pub const EXECUTE_E3_INSN_MI_S_LABEL: &str = "execute_e3_insn_mi/s";
+pub const EXECUTE_PREFLIGHT_TIME_LABEL: &str = "execute_preflight_time_ms";
+pub const EXECUTE_PREFLIGHT_INSN_MI_S_LABEL: &str = "execute_preflight_insn_mi/s";
 pub const TRACE_GEN_TIME_LABEL: &str = "trace_gen_time_ms";
 pub const MEM_FIN_TIME_LABEL: &str = "memory_finalize_time_ms";
 pub const BOUNDARY_FIN_TIME_LABEL: &str = "boundary_finalize_time_ms";
@@ -486,8 +486,8 @@ pub const VM_METRIC_NAMES: &[&str] = &[
     EXECUTE_E1_INSN_MI_S_LABEL,
     EXECUTE_METERED_TIME_LABEL,
     EXECUTE_METERED_INSN_MI_S_LABEL,
-    EXECUTE_E3_TIME_LABEL,
-    EXECUTE_E3_INSN_MI_S_LABEL,
+    EXECUTE_PREFLIGHT_TIME_LABEL,
+    EXECUTE_PREFLIGHT_INSN_MI_S_LABEL,
     TRACE_GEN_TIME_LABEL,
     MEM_FIN_TIME_LABEL,
     BOUNDARY_FIN_TIME_LABEL,
diff --git a/crates/prof/src/lib.rs b/crates/prof/src/lib.rs
@@ -5,7 +5,7 @@ use eyre::Result;
 use memmap2::Mmap;
 
 use crate::{
-    aggregate::{EXECUTE_E3_TIME_LABEL, EXECUTE_METERED_TIME_LABEL},
+    aggregate::{EXECUTE_METERED_TIME_LABEL, EXECUTE_PREFLIGHT_TIME_LABEL},
     types::{Labels, Metric, MetricDb, MetricsFile},
 };
 
@@ -47,14 +47,20 @@ impl MetricDb {
         for metrics in self.flat_dict.values_mut() {
             let get = |key: &str| metrics.iter().find(|m| m.name == key).map(|m| m.value);
             let execute_metered_time = get(EXECUTE_METERED_TIME_LABEL);
-            let execute_e3_time = get(EXECUTE_E3_TIME_LABEL);
+            let execute_preflight_time = get(EXECUTE_PREFLIGHT_TIME_LABEL);
             let trace_gen_time = get(TRACE_GEN_TIME_LABEL);
             let prove_excl_trace_time = get(PROVE_EXCL_TRACE_TIME_LABEL);
-            if let (Some(execute_e3_time), Some(trace_gen_time), Some(prove_excl_trace_time)) =
-                (execute_e3_time, trace_gen_time, prove_excl_trace_time)
-            {
+            if let (
+                Some(execute_preflight_time),
+                Some(trace_gen_time),
+                Some(prove_excl_trace_time),
+            ) = (
+                execute_preflight_time,
+                trace_gen_time,
+                prove_excl_trace_time,
+            ) {
                 let total_time = execute_metered_time.unwrap_or(0.0)
-                    + execute_e3_time
+                    + execute_preflight_time
                     + trace_gen_time
                     + prove_excl_trace_time;
                 metrics.push(Metric::new(PROOF_TIME_LABEL.to_string(), total_time));
diff --git a/crates/prof/src/summary.rs b/crates/prof/src/summary.rs
@@ -5,7 +5,7 @@ use itertools::Itertools;
 
 use crate::{
     aggregate::{
-        AggregateMetrics, EXECUTE_E3_TIME_LABEL, EXECUTE_METERED_TIME_LABEL, INSNS_LABEL,
+        AggregateMetrics, EXECUTE_METERED_TIME_LABEL, EXECUTE_PREFLIGHT_TIME_LABEL, INSNS_LABEL,
         MAIN_CELLS_USED_LABEL, PROOF_TIME_LABEL, PROVE_EXCL_TRACE_TIME_LABEL, TRACE_GEN_TIME_LABEL,
     },
     types::MdTableCell,
@@ -169,8 +169,8 @@ impl AggregateMetrics {
                 .get(EXECUTE_METERED_TIME_LABEL)
                 .map(|s| s.sum.val)
                 .unwrap_or(0.0);
-            let execute_e3 = stats
-                .get(EXECUTE_E3_TIME_LABEL)
+            let execute_preflight = stats
+                .get(EXECUTE_PREFLIGHT_TIME_LABEL)
                 .map(|s| s.sum.val)
                 .unwrap_or(0.0);
             // If total_proof_time_ms is not available, compute it from components
@@ -184,9 +184,12 @@ impl AggregateMetrics {
                 .unwrap_or(0.0);
             println!(
                 "{} {} {} {}",
-                execute_metered, execute_e3, trace_gen, stark_prove
+                execute_metered, execute_preflight, trace_gen, stark_prove
             );
-            MdTableCell::new(execute_metered + execute_e3 + trace_gen + stark_prove, None)
+            MdTableCell::new(
+                execute_metered + execute_preflight + trace_gen + stark_prove,
+                None,
+            )
         };
         println!("{}", self.total_proof_time.val);
         let par_proof_time_ms = if let Some(proof_stats) = stats.get(PROOF_TIME_LABEL) {
@@ -197,8 +200,8 @@ impl AggregateMetrics {
                 .get(EXECUTE_METERED_TIME_LABEL)
                 .map(|s| s.max.val)
                 .unwrap_or(0.0);
-            let execute_e3 = stats
-                .get(EXECUTE_E3_TIME_LABEL)
+            let execute_preflight = stats
+                .get(EXECUTE_PREFLIGHT_TIME_LABEL)
                 .map(|s| s.max.val)
                 .unwrap_or(0.0);
             let trace_gen = stats
@@ -209,7 +212,10 @@ impl AggregateMetrics {
                 .get(PROVE_EXCL_TRACE_TIME_LABEL)
                 .map(|s| s.max.val)
                 .unwrap_or(0.0);
-            MdTableCell::new(execute_metered + execute_e3 + trace_gen + stark_prove, None)
+            MdTableCell::new(
+                execute_metered + execute_preflight + trace_gen + stark_prove,
+                None,
+            )
         };
         let cells_used = stats
             .get(MAIN_CELLS_USED_LABEL)
diff --git a/crates/vm/src/arch/extensions.rs b/crates/vm/src/arch/extensions.rs
@@ -35,10 +35,13 @@ use rustc_hash::FxHashMap;
 use tracing::info_span;
 
 use super::{GenerationError, PhantomSubExecutor, SystemConfig};
-use crate::system::{
-    memory::{BOUNDARY_AIR_OFFSET, MERKLE_AIR_OFFSET},
-    phantom::PhantomExecutor,
-    SystemAirInventory, SystemChipComplex, SystemRecords,
+use crate::{
+    arch::Arena,
+    system::{
+        memory::{BOUNDARY_AIR_OFFSET, MERKLE_AIR_OFFSET},
+        phantom::PhantomExecutor,
+        SystemAirInventory, SystemChipComplex, SystemRecords,
+    },
 };
 
 /// Global AIR ID in the VM circuit verifying key.
@@ -641,6 +644,7 @@ pub enum ChipInventoryError {
 impl<SC, RA, PB, SCC> VmChipComplex<SC, RA, PB, SCC>
 where
     SC: StarkGenericConfig,
+    RA: Arena,
     PB: ProverBackend,
     SCC: SystemChipComplex<RA, PB>,
 {
@@ -692,9 +696,12 @@ where
             .chain(
                 zip(self.inventory.chips.iter().enumerate().rev(), record_arenas).map(
                     |((insertion_idx, chip), records)| {
-                        let air_name = self.inventory.airs.ext_airs[insertion_idx].name();
-                        info_span!("single_trace_gen", air = air_name)
-                            .in_scope(|| chip.generate_proving_ctx(records))
+                        // Only create a span if record is not empty:
+                        let _span = (!records.is_empty()).then(|| {
+                            let air_name = self.inventory.airs.ext_airs[insertion_idx].name();
+                            info_span!("single_trace_gen", air = air_name).entered()
+                        });
+                        chip.generate_proving_ctx(records)
                     },
                 ),
             )
diff --git a/crates/vm/src/arch/interpreter_preflight.rs b/crates/vm/src/arch/interpreter_preflight.rs
@@ -114,7 +114,8 @@ where
     }
 }
 
-/// Macro for executing with a compile-time span name for better tracing performance
+/// Macro for executing and emitting metrics for instructions/s and number of instructions executed.
+/// Does not include any tracing span.
 #[macro_export]
 macro_rules! execute_spanned {
     ($name:literal, $executor:expr, $state:expr) => {{
@@ -123,7 +124,7 @@ macro_rules! execute_spanned {
         #[cfg(feature = "metrics")]
         let start_instret = $state.instret;
 
-        let result = tracing::info_span!($name).in_scope(|| $executor.execute_from_state($state));
+        let result = $executor.execute_from_state($state);
 
         #[cfg(feature = "metrics")]
         {
diff --git a/crates/vm/src/arch/record_arena.rs b/crates/vm/src/arch/record_arena.rs
@@ -15,6 +15,8 @@ pub trait Arena {
     /// Currently `width` always refers to the main trace width.
     fn with_capacity(height: usize, width: usize) -> Self;
 
+    fn is_empty(&self) -> bool;
+
     /// Only used for metric collection purposes. Intended usage is that for a record arena that
     /// corresponds to a single trace matrix, this function can extract the current number of used
     /// rows of the corresponding trace matrix. This is currently expected to work only for
@@ -117,6 +119,10 @@ impl<F: Field> Arena for MatrixRecordArena<F> {
         }
     }
 
+    fn is_empty(&self) -> bool {
+        self.trace_offset == 0
+    }
+
     #[cfg(feature = "metrics")]
     fn current_trace_height(&self) -> usize {
         self.trace_offset / self.width
@@ -244,6 +250,10 @@ impl Arena for DenseRecordArena {
         let size_bytes = height * (width * size_of::<u32>());
         Self::with_byte_capacity(size_bytes)
     }
+
+    fn is_empty(&self) -> bool {
+        self.allocated().is_empty()
+    }
 }
 
 // =================== Helper Functions =================================
diff --git a/crates/vm/src/arch/vm.rs b/crates/vm/src/arch/vm.rs
@@ -388,6 +388,7 @@ where
     ///
     /// This function should rarely be called on its own. Users are advised to call
     /// [`prove`](Self::prove) directly.
+    #[instrument(name = "execute_preflight", skip_all)]
     pub fn execute_preflight(
         &self,
         exe: &VmExe<Val<E::SC>>,
@@ -444,7 +445,7 @@ where
             metrics: state.metrics,
         };
         let mut exec_state = VmExecState::new(vm_state, ctx);
-        execute_spanned!("execute_e3", instance, &mut exec_state)?;
+        execute_spanned!("execute_preflight", instance, &mut exec_state)?;
         let filtered_exec_frequencies = instance.handler.filtered_execution_frequencies();
         let touched_memory = exec_state
             .vm_state
@@ -1256,6 +1257,8 @@ mod vm_metrics {
                 total_cells_used +=
                     width.total_width(<E::SC as StarkGenericConfig>::Challenge::D) * *height;
             }
+            tracing::debug!(?heights);
+            tracing::info!(main_cells_used, total_cells_used);
             counter!("main_cells_used").absolute(main_cells_used as u64);
             counter!("total_cells_used").absolute(total_cells_used as u64);
 
diff --git a/crates/vm/src/system/memory/merkle/trace.rs b/crates/vm/src/system/memory/merkle/trace.rs
@@ -27,7 +27,7 @@ use crate::{
 };
 
 impl<const CHUNK: usize, F: PrimeField32> MemoryMerkleChip<CHUNK, F> {
-    #[instrument(name = "merkle_finalize", skip_all)]
+    #[instrument(name = "merkle_finalize", level = "debug", skip_all)]
     pub(crate) fn finalize(
         &mut self,
         initial_memory: &MemoryImage,
diff --git a/crates/vm/src/system/memory/persistent.rs b/crates/vm/src/system/memory/persistent.rs
@@ -207,7 +207,7 @@ impl<const CHUNK: usize, F: PrimeField32> PersistentBoundaryChip<F, CHUNK> {
         }
     }
 
-    #[instrument(name = "boundary_finalize", skip_all)]
+    #[instrument(name = "boundary_finalize", level = "debug", skip_all)]
     pub(crate) fn finalize<H>(
         &mut self,
         initial_memory: &MemoryImage,
diff --git a/crates/vm/src/system/memory/volatile/mod.rs b/crates/vm/src/system/memory/volatile/mod.rs
@@ -219,7 +219,7 @@ impl<F: PrimeField32> VolatileBoundaryChip<F> {
     }
     /// Volatile memory requires the starting and final memory to be in equipartition with block
     /// size `1`. When block size is `1`, then the `label` is the same as the address pointer.
-    #[instrument(name = "boundary_finalize", skip_all)]
+    #[instrument(name = "boundary_finalize", level = "debug", skip_all)]
     pub fn finalize(&mut self, final_memory: TimestampedEquipartition<F, 1>) {
         self.final_memory = Some(final_memory);
     }
diff --git a/docs/crates/metrics.md b/docs/crates/metrics.md
@@ -10,17 +10,15 @@ To scope metrics from different proofs, we use the [`metrics_tracing_context`](h
 For a segment proof, the following metrics are collected:
 
 - `execute_metered_time_ms` (gauge): The metered execution time of the segment in milliseconds. This is timed across **all** segments in the group.
-- `execute_e3_time_ms` (gauge): The preflight execution time of the segment in milliseconds.
+- `execute_preflight_time_ms` (gauge): The preflight execution time of the segment in milliseconds.
   - If this is a segment in a VM with continuations enabled, a `segment: segment_idx` label is added to the metric.
+  - `memory_finalize_time_ms` (gauge): The time at the end of preflight execution spent on memory finalization.
 - `trace_gen_time_ms` (gauge): The time to generate non-cached trace matrices from execution records.
   - If this is a segment in a VM with continuations enabled, a `segment: segment_idx` label is added to the metric.
-  - `memory_finalize_time_ms` (gauge): The time in trace generation spent on memory finalization.
-    - `boundary_finalize_time_ms` (gauge): The time in memory finalization spent on boundary finalization.
-    - `merkle_finalize_time_ms` (gauge): The time in memory finalization spent on merkle tree finalization.
 - All metrics collected by [`openvm-stark-backend`](https://github.com/openvm-org/stark-backend/blob/main/docs/metrics.md), in particular `stark_prove_excluding_trace_time_ms` (gauge).
 - The `total_proof_time_ms` of the proof is:
-  - The sum `execute_e3_time_ms + trace_gen_time_ms + stark_prove_excluding_trace_time_ms` for app proofs. The `execute_metered_time_ms` is excluded for app proofs because it is not run on a per-segment basis.
-  - The sum `execute_metered_time_ms + execute_e3_time_ms + trace_gen_time_ms + stark_prove_excluding_trace_time_ms` for non-app proofs.
+  - The sum `execute_preflight_time_ms + trace_gen_time_ms + stark_prove_excluding_trace_time_ms` for app proofs. The `execute_metered_time_ms` is excluded for app proofs because it is not run on a per-segment basis.
+  - The sum `execute_metered_time_ms + execute_preflight_time_ms + trace_gen_time_ms + stark_prove_excluding_trace_time_ms` for non-app proofs.
 - `insns` (counter): The total number of instructions executed in the segment.
 - `main_cells_used` (counter): The total number of main trace cells used by all chips in the segment. This does not include cells needed to pad rows to power-of-two matrix heights. Only main trace cells, not preprocessed or permutation trace cells, are counted.
 - `total_cells_used` (counter): The total number of preprocessed, main, and permutation trace cells used by all chips in the segment. This does not include cells needed to pad rows to power-of-two matrix heights.

Original file line number	Diff line number	Diff line change
`@@ -114,7 +114,8 @@ where`
`114`	`114`	`}`
`115`	`115`	`}`
`116`	`116`
`117`		`-/// Macro for executing with a compile-time span name for better tracing performance`
	`117`	`+/// Macro for executing and emitting metrics for instructions/s and number of instructions executed.`
	`118`	`+/// Does not include any tracing span.`
`118`	`119`	`#[macro_export]`
`119`	`120`	`macro_rules! execute_spanned {`
`120`	`121`	`($name:literal, $executor:expr, $state:expr) => {{`
`@@ -123,7 +124,7 @@ macro_rules! execute_spanned {`
`123`	`124`	`#[cfg(feature = "metrics")]`
`124`	`125`	`let start_instret = $state.instret;`
`125`	`126`
`126`		`- let result = tracing::info_span!($name).in_scope(\|\| $executor.execute_from_state($state));`
	`127`	`+ let result = $executor.execute_from_state($state);`
`127`	`128`
`128`	`129`	`#[cfg(feature = "metrics")]`
`129`	`130`	`{`
Original file line number	Diff line number	Diff line change
`@@ -207,7 +207,7 @@ impl<const CHUNK: usize, F: PrimeField32> PersistentBoundaryChip<F, CHUNK> {`
`207`	`207`	`}`
`208`	`208`	`}`
`209`	`209`
`210`		`- #[instrument(name = "boundary_finalize", skip_all)]`
	`210`	`+ #[instrument(name = "boundary_finalize", level = "debug", skip_all)]`
`211`	`211`	`pub(crate) fn finalize<H>(`
`212`	`212`	`&mut self,`
`213`	`213`	`initial_memory: &MemoryImage,`
Original file line number	Diff line number	Diff line change
`@@ -219,7 +219,7 @@ impl<F: PrimeField32> VolatileBoundaryChip<F> {`
`219`	`219`	`}`
`220`	`220`	`/// Volatile memory requires the starting and final memory to be in equipartition with block`
`221`	`221`	/// size `1`. When block size is `1`, then the `label` is the same as the address pointer.
`222`		`- #[instrument(name = "boundary_finalize", skip_all)]`
	`222`	`+ #[instrument(name = "boundary_finalize", level = "debug", skip_all)]`
`223`	`223`	`pub fn finalize(&mut self, final_memory: TimestampedEquipartition<F, 1>) {`
`224`	`224`	`self.final_memory = Some(final_memory);`
`225`	`225`	`}`