From 5d5c9ea15adeb722853f864ece78a04d0ad251fc Mon Sep 17 00:00:00 2001 From: jatking <53228426+Jatkingmodern@users.noreply.github.com> Date: Mon, 3 Nov 2025 15:52:58 +0530 Subject: [PATCH] Implement runtime metrics collection in Evaluator Added EvalMetrics struct to collect runtime metrics during evaluation, including instruction count, GC count, memory usage, and execution time. Updated Evaluator to track these metrics and provide methods to collect and reset them. --- starlark/src/eval/runtime/evaluator.rs | 84 ++++++++++++++++++++++++-- 1 file changed, 78 insertions(+), 6 deletions(-) diff --git a/starlark/src/eval/runtime/evaluator.rs b/starlark/src/eval/runtime/evaluator.rs index 0d482605d..2b7178e96 100644 --- a/starlark/src/eval/runtime/evaluator.rs +++ b/starlark/src/eval/runtime/evaluator.rs @@ -18,6 +18,7 @@ use std::collections::HashSet; use std::mem; use std::mem::MaybeUninit; +use std::time::Instant; use dupe::Dupe; use starlark_syntax::eval_exception::EvalException; @@ -117,6 +118,35 @@ const INFREQUENT_INSTRUCTION_CHECK_PERIOD: u32 = 1000; /// Default value for max starlark stack size pub(crate) const DEFAULT_STACK_SIZE: usize = 50; +/// Lightweight runtime metrics collected during evaluation (kept small and copyable). +#[derive(Clone, Debug, Default)] +pub struct EvalMetrics { + /// Approximate number of instructions executed (incremented periodically). + pub instructions_executed: u64, + /// Number of garbage collections that happened. + pub gc_count: u64, + /// Maximum allocated bytes observed at GC points. + pub max_allocated_bytes: usize, + /// Total time spent executing bytecode in nanoseconds (approx). + pub total_exec_time_ns: u128, + /// Timestamp (ns since evaluator creation) of last GC if any. + pub last_gc_time_ns: Option, +} + +impl EvalMetrics { + pub fn to_json(&self) -> String { + // Manual JSON encoding to avoid adding serde as a dependency. + format!( + "{{\"instructions_executed\":{},\"gc_count\":{},\"max_allocated_bytes\":{},\"total_exec_time_ns\":{},\"last_gc_time_ns\":{} }}", + self.instructions_executed, + self.gc_count, + self.max_allocated_bytes, + self.total_exec_time_ns, + match self.last_gc_time_ns { Some(v) => v.to_string(), None => "null".to_owned() } + ) + } +} + /// Holds everything about an ongoing evaluation (local variables, globals, module resolution etc). pub struct Evaluator<'v, 'a, 'e> { // The module that is being used for this evaluation @@ -175,6 +205,10 @@ pub struct Evaluator<'v, 'a, 'e> { pub(crate) is_cancelled: Box bool + 'a>, /// A counter to track when to perform "infrequent" checks like cancellation, timeouts, etc pub(crate) infrequent_instr_check_counter: u32, + /// Runtime-collected lightweight metrics + pub(crate) metrics: EvalMetrics, + /// Instant when evaluator was created (used to compute relative times) + pub(crate) start_instant: Instant, } // We use this to validate that the Evaluator lifetimes have the expected variance. @@ -270,6 +304,8 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { max_callstack_size: None, is_cancelled: Box::new(|| false), infrequent_instr_check_counter: 0, + metrics: EvalMetrics::default(), + start_instant: Instant::now(), } } @@ -404,9 +440,7 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { ProfileMode::BytecodePairs => self.gen_bc_pairs_profile(), ProfileMode::TimeFlame => self.time_flame_profile.r#gen(), ProfileMode::Typecheck => self.typecheck_profile.r#gen(), - ProfileMode::None => Ok(ProfileData { - profile: ProfileDataImpl::None, - }), + ProfileMode::None => Ok(ProfileData { profile: ProfileDataImpl::None }), } } @@ -783,6 +817,15 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { self.time_flame_profile .record_call_enter(const_frozen_string!("GC").to_value()); + // Record metrics: GC count and max allocated bytes at GC time + self.metrics.gc_count += 1; + let current_alloc = self.heap().allocated_bytes(); + if current_alloc > self.metrics.max_allocated_bytes { + self.metrics.max_allocated_bytes = current_alloc; + } + let rel_time = Instant::now().duration_since(self.start_instant).as_nanos(); + self.metrics.last_gc_time_ns = Some(rel_time); + self.heap().garbage_collect(|tracer| self.trace(tracer)); self.time_flame_profile.record_call_exit(); @@ -846,14 +889,19 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { ) -> Result, EvalException> { debug_assert!(self.eval_instrumentation.enabled); if self.eval_instrumentation.heap_or_flame_profile { + // measure time spent in bc.run + let t0 = Instant::now(); self.heap_profile.record_call_enter(def, self.heap()); self.time_flame_profile.record_call_enter(def); let res = bc.run(self, &mut EvalCallbacksDisabled); + let elapsed = t0.elapsed().as_nanos(); + self.metrics.total_exec_time_ns += elapsed as u128; self.heap_profile.record_call_exit(self.heap()); self.time_flame_profile.record_call_exit(); res } else { - bc.run( + let t0 = Instant::now(); + let res = bc.run( self, &mut EvalCallbacksEnabled { mode: match ( @@ -876,7 +924,10 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { stmt_locs: &bc.instrs.stmt_locs, bc_start_ptr: bc.instrs.start_ptr(), }, - ) + ); + let elapsed = t0.elapsed().as_nanos(); + self.metrics.total_exec_time_ns += elapsed as u128; + res } } @@ -885,7 +936,11 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { if self.eval_instrumentation.enabled { self.eval_bc_with_callbacks(def, bc) } else { - bc.run(self, &mut EvalCallbacksDisabled) + let t0 = Instant::now(); + let res = bc.run(self, &mut EvalCallbacksDisabled); + let elapsed = t0.elapsed().as_nanos(); + self.metrics.total_exec_time_ns += elapsed as u128; + res } } @@ -905,7 +960,14 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { #[inline(always)] pub(crate) fn run_infrequent_instr_checks(&mut self) -> crate::Result<()> { self.infrequent_instr_check_counter += 1; + // Approximate the number of instructions executed. + // Some callers increment more frequently; this provides a minimal estimate. if self.infrequent_instr_check_counter >= INFREQUENT_INSTRUCTION_CHECK_PERIOD { + // update instruction count by the period + self.metrics.instructions_executed = self.metrics.instructions_executed.saturating_add( + INFREQUENT_INSTRUCTION_CHECK_PERIOD as u64, + ); + if (self.is_cancelled)() { return Err(crate::Error::new_other(EvaluatorError::Cancelled)); } @@ -915,6 +977,16 @@ impl<'v, 'a, 'e: 'a> Evaluator<'v, 'a, 'e> { // TODO(T219887296): implement CPU-time-limiting checks here Ok(()) } + + /// Return a copy of the current runtime metrics. Cheap and copyable. + pub fn collect_metrics(&self) -> EvalMetrics { + self.metrics.clone() + } + + /// Reset runtime metrics (keeps start time unchanged). + pub fn reset_metrics(&mut self) { + self.metrics = EvalMetrics::default(); + } } pub(crate) trait EvaluationCallbacks {