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 {