Inlined functions profiling

CHANGELOG.md

@@ -13,6 +13,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 - `--max-function-stack-trace-depth` allowing to specify maximum depth of the function tree in function level profiling
 - `--split-generics` flag allowing to differentiate between non-inlined generics monomorphised with different types
+- `--show-inlined-functions` flag to show inlined functions in the profile. Requires Scarb >= 2.7.0 and setting
+ `unstable-add-statements-functions-debug-info = true` in `[cairo]` section of Scarb.toml.
 
 ## [0.3.0] - 2024-05-20
 

crates/cairo-profiler/src/main.rs

@@ -44,6 +44,11 @@ struct Cli {
  /// E.g. treat `function<felt252>` as different from `function<u8>`.
  #[arg(long)]
  split_generics: bool,
+
+ /// Show inlined function in a trace tree. Requires Scarb >= 2.7.0 and setting
+ /// `unstable-add-statements-functions-debug-info = true` in `[cairo]` section of Scarb.toml.
+ #[arg(long)]
+ show_inlined_functions: bool,
 }
 
 fn main() -> Result<()> {

crates/cairo-profiler/src/profiler_config.rs

@@ -4,6 +4,7 @@ pub struct ProfilerConfig {
  pub show_details: bool,
  pub max_function_stack_trace_depth: usize,
  pub split_generics: bool,
+ pub show_inlined_functions: bool,
 }
 
 impl From<&Cli> for ProfilerConfig {
@@ -12,20 +13,23 @@ impl From<&Cli> for ProfilerConfig {
  show_details: cli.show_details,
  max_function_stack_trace_depth: cli.max_function_stack_trace_depth,
  split_generics: cli.split_generics,
+ show_inlined_functions: cli.show_inlined_functions,
  }
  }
 }
 
 pub struct FunctionLevelConfig {
  pub max_function_stack_trace_depth: usize,
  pub split_generics: bool,
+ pub show_inlined_functions: bool,
 }
 
 impl From<&ProfilerConfig> for FunctionLevelConfig {
  fn from(profiler_config: &ProfilerConfig) -> FunctionLevelConfig {
  FunctionLevelConfig {
  max_function_stack_trace_depth: profiler_config.max_function_stack_trace_depth,
  split_generics: profiler_config.split_generics,
+ show_inlined_functions: profiler_config.show_inlined_functions,
  }
  }
 }

crates/cairo-profiler/src/sierra_loader.rs

@@ -37,11 +37,13 @@ impl SierraProgram {
  }
 }
 
-#[allow(dead_code)]
+/// This struct maps sierra statement index to a stack of fully qualified paths of cairo functions
+/// consisting of a function which caused the statement to be generated and all functions that were
+/// inlined or generated along the way, up to the first non-inlined function from the original code.
+/// The map represents the stack from the least meaningful elements.
 #[derive(Default, Clone)]
 pub struct StatementsFunctionsMap(HashMap<StatementIdx, Vec<FunctionName>>);
 
-#[allow(dead_code)]
 impl StatementsFunctionsMap {
  pub fn get(&self, key: StatementIdx) -> Option<&Vec<FunctionName>> {
  self.0.get(&key)

crates/cairo-profiler/src/trace_reader.rs

@@ -69,6 +69,7 @@ fn collect_samples<'a>(
  compiled_artifacts.sierra_program.get_program(),
  &compiled_artifacts.casm_debug_info,
  cairo_execution_info.casm_level_info.run_with_call_header,
+ &compiled_artifacts.maybe_statements_functions_map,
  &FunctionLevelConfig::from(profiler_config),
  );
 

crates/cairo-profiler/src/trace_reader/function_trace_builder.rs

@@ -1,21 +1,22 @@
 use crate::profiler_config::FunctionLevelConfig;
+use crate::sierra_loader::StatementsFunctionsMap;
 use crate::trace_reader::function_name::FunctionName;
 use crate::trace_reader::function_trace_builder::function_stack_trace::{
- CallStack, CurrentCallType,
-};
-use crate::trace_reader::sample::{
- FunctionCall, InternalFunctionCall, MeasurementUnit, MeasurementValue, Sample,
+ CallStack, VecWithLimitedCapacity,
 };
+use crate::trace_reader::function_trace_builder::inlining::build_original_call_stack_with_inlined_calls;
+use crate::trace_reader::sample::{FunctionCall, MeasurementUnit, MeasurementValue, Sample};
 use cairo_lang_sierra::extensions::core::{CoreConcreteLibfunc, CoreLibfunc, CoreType};
 use cairo_lang_sierra::program::{GenStatement, Program, StatementIdx};
 use cairo_lang_sierra::program_registry::ProgramRegistry;
 use cairo_lang_sierra_to_casm::compiler::CairoProgramDebugInfo;
-use itertools::{chain, Itertools};
+use itertools::Itertools;
 use std::collections::HashMap;
 use std::ops::AddAssign;
 use trace_data::TraceEntry;
 
 mod function_stack_trace;
+mod inlining;
 
 pub struct FunctionLevelProfilingInfo {
  pub functions_samples: Vec<Sample>,
@@ -48,6 +49,7 @@ pub fn collect_function_level_profiling_info(
  program: &Program,
  casm_debug_info: &CairoProgramDebugInfo,
  run_with_call_header: bool,
+ maybe_statements_functions_map: &Option<StatementsFunctionsMap>,
  function_level_config: &FunctionLevelConfig,
 ) -> FunctionLevelProfilingInfo {
  let sierra_program_registry = &ProgramRegistry::<CoreType, CoreLibfunc>::new(program).unwrap();
@@ -76,12 +78,11 @@ pub fn collect_function_level_profiling_info(
  // profile tree. It is because technically they don't belong to any function, but still increase
  // the number of total steps. The value is different from zero only for functions run with header.
  let mut header_steps = Steps(0);
- let mut current_function_steps = Steps(0);
  let mut end_of_program_reached = false;
 
  for step in trace {
- // Skip the header. This only makes sense when a header was added to CASM program.
- if step.pc < real_minimal_pc && run_with_call_header {
+ // Skip the header.
+ if step.pc < real_minimal_pc {
  header_steps += 1;
  continue;
  }
@@ -93,8 +94,6 @@ pub fn collect_function_level_profiling_info(
  unreachable!("End of program reached, but trace continues.");
  }
 
- current_function_steps += 1;
-
  let maybe_sierra_statement_idx =
  maybe_sierra_statement_index_by_pc(casm_debug_info, real_pc_code_offset);
  let sierra_statement_idx = match maybe_sierra_statement_idx {
@@ -112,6 +111,18 @@ pub fn collect_function_level_profiling_info(
  function_level_config.split_generics,
  );
 
+ let current_call_stack = build_current_call_stack(
+ &call_stack,
+ current_function_name.clone(),
+ function_level_config.show_inlined_functions,
+ sierra_statement_idx,
+ maybe_statements_functions_map.as_ref(),
+ );
+
+ *functions_stack_traces
+ .entry(current_call_stack.into())
+ .or_insert(Steps(0)) += 1;
+
  let Some(gen_statement) = program.statements.get(sierra_statement_idx.0) else {
  panic!("Failed fetching statement index {}", sierra_statement_idx.0);
  };
@@ -122,42 +133,20 @@ pub fn collect_function_level_profiling_info(
  sierra_program_registry.get_libfunc(&invocation.libfunc_id),
  Ok(CoreConcreteLibfunc::FunctionCall(_))
  ) {
- call_stack
- .enter_function_call(current_function_name, &mut current_function_steps);
+ let current_call_stack = build_current_call_stack(
+ &call_stack,
+ current_function_name.clone(),
+ function_level_config.show_inlined_functions,
+ sierra_statement_idx,
+ maybe_statements_functions_map.as_ref(),
+ );
+
+ call_stack.enter_function_call(current_call_stack);
  }
  }
  GenStatement::Return(_) => {
- if let Some(exited_call) = call_stack.exit_function_call() {
- if let CurrentCallType::Regular((function_name, steps)) = exited_call {
- let names_call_stack = chain!(
- call_stack.current_function_names_stack(),
- [function_name, current_function_name]
- )
- .collect_vec();
-
- let call_stack = names_call_stack
- .into_iter()
- .map(|function_name| {
- FunctionCall::InternalFunctionCall(
- InternalFunctionCall::NonInlined(function_name),
- )
- })
- .collect();
-
- *functions_stack_traces.entry(call_stack).or_insert(Steps(0)) +=
- current_function_steps;
- // Set to the caller function steps to continue counting its cost.
- current_function_steps = steps;
- }
- } else {
+ if call_stack.exit_function_call().is_none() {
  end_of_program_reached = true;
-
- let call_stack = vec![FunctionCall::InternalFunctionCall(
- InternalFunctionCall::NonInlined(current_function_name),
- )];
-
- *functions_stack_traces.entry(call_stack).or_insert(Steps(0)) +=
- current_function_steps;
  }
  }
  }
@@ -208,3 +197,25 @@ fn maybe_sierra_statement_index_by_pc(
  MaybeSierraStatementIndex::SierraStatementIndex(statement_index)
  }
 }
+
+fn build_current_call_stack(
+ call_stack: &CallStack,
+ current_function_name: FunctionName,
+ show_inlined_functions: bool,
+ sierra_statement_idx: StatementIdx,
+ maybe_statements_functions_map: Option<&StatementsFunctionsMap>,
+) -> VecWithLimitedCapacity<FunctionCall> {
+ let current_function_call_stack = call_stack.current_function_call_stack(current_function_name);
+
+ if show_inlined_functions {
+ let (current_function_call_stack, max_capacity) = current_function_call_stack.deconstruct();
+ let current_call_stack_with_inlined_calls = build_original_call_stack_with_inlined_calls(
+ sierra_statement_idx,
+ maybe_statements_functions_map,
+ current_function_call_stack,
+ );
+ VecWithLimitedCapacity::from(current_call_stack_with_inlined_calls, max_capacity)
+ } else {
+ current_function_call_stack
+ }
+}

crates/cairo-profiler/src/trace_reader/function_trace_builder/function_stack_trace.rs

@@ -1,94 +1,92 @@
 use crate::trace_reader::function_name::FunctionName;
-use crate::trace_reader::function_trace_builder::Steps;
-
-struct CallStackElement {
- pub function_name: FunctionName,
- /// Steps of the function at the moment of putting it on the stack.
- pub function_steps: Steps,
- /// Consecutive recursive calls to this function that are currently on the stack.
- recursive_calls_count: usize,
-}
+use crate::trace_reader::sample::{FunctionCall, InternalFunctionCall};
 
 /// The function call stack of the current function, excluding the current function call.
 pub(super) struct CallStack {
- stack: Vec<CallStackElement>,
- /// Tracks the depth of the function call stack, without limit. This is usually equal to
- /// `stack.len()`, but if the actual stack is deeper than `max_function_trace_depth`,
- /// this remains reliable while `stack` does not.
- real_function_stack_depth: usize,
- /// Constant through existence of the object.
- max_function_stack_trace_depth: usize,
-}
-
-/// Call that we moved to by exiting a call.
-pub(super) enum CurrentCallType {
- /// Regular function call.
- Regular((FunctionName, Steps)),
- /// Function call that has stack trace depth exceeding the limit.
- Hidden,
- /// Recursive function call.
- Recursive,
+ stack: VecWithLimitedCapacity<FunctionCall>,
+ /// The last element of this vector is always a number of elements of the stack before the last
+ /// function call.
+ previous_stack_lengths: Vec<usize>,
 }
 
 impl CallStack {
  pub fn new(max_function_stack_trace_depth: usize) -> Self {
  Self {
- stack: vec![],
- real_function_stack_depth: 0,
- max_function_stack_trace_depth,
+ stack: VecWithLimitedCapacity::new(max_function_stack_trace_depth),
+ previous_stack_lengths: vec![],
  }
  }
 
- pub fn enter_function_call(
- &mut self,
- function_name: FunctionName,
- current_function_steps: &mut Steps,
- ) {
- if let Some(stack_element) = self.stack.last_mut() {
- if function_name == stack_element.function_name {
- stack_element.recursive_calls_count += 1;
- return;
- }
+ pub fn enter_function_call(&mut self, new_call_stack: VecWithLimitedCapacity<FunctionCall>) {
+ self.previous_stack_lengths.push(self.stack.len());
+
+ self.stack = new_call_stack;
+ }
+
+ pub fn exit_function_call(&mut self) -> Option<()> {
+ let previous_stack_len = self.previous_stack_lengths.pop()?;
+ self.stack.truncate(previous_stack_len);
+ Some(())
+ }
+
+ /// Returns current call stack truncated to `max_function_stack_trace_depth`.
+ pub fn current_function_call_stack(
+ &self,
+ current_function_name: FunctionName,
+ ) -> VecWithLimitedCapacity<FunctionCall> {
+ let mut current_call_stack = self.stack.clone();
+
+ current_call_stack.push(FunctionCall::InternalFunctionCall(
+ InternalFunctionCall::NonInlined(current_function_name),
+ ));
+
+ current_call_stack
+ }
+}
+
+#[derive(Clone)]
+pub struct VecWithLimitedCapacity<T> {
+ vector: Vec<T>,
+ max_capacity: usize,
+}
+
+impl<T> VecWithLimitedCapacity<T> {
+ pub fn new(max_capacity: usize) -> Self {
+ Self {
+ vector: vec![],
+ max_capacity,
  }
+ }
 
- if self.real_function_stack_depth < self.max_function_stack_trace_depth {
- self.stack.push(CallStackElement {
- function_name,
- function_steps: *current_function_steps,
- recursive_calls_count: 0,
- });
- // Reset steps to count new function's steps.
- *current_function_steps = Steps(0);
+ pub fn from(mut vector: Vec<T>, max_capacity: usize) -> Self {
+ vector.truncate(max_capacity);
+ Self {
+ vector,
+ max_capacity,
  }
- self.real_function_stack_depth += 1;
  }
 
- pub fn exit_function_call(&mut self) -> Option<CurrentCallType> {
- if self.real_function_stack_depth <= self.max_function_stack_trace_depth {
- let mut stack_element = self.stack.pop()?;
-
- if stack_element.recursive_calls_count > 0 {
- stack_element.recursive_calls_count -= 1;
- self.stack.push(stack_element);
-
- Some(CurrentCallType::Recursive)
- } else {
- self.real_function_stack_depth -= 1;
- Some(CurrentCallType::Regular((
- stack_element.function_name,
- stack_element.function_steps,
- )))
- }
- } else {
- self.real_function_stack_depth -= 1;
- Some(CurrentCallType::Hidden)
+ pub fn push(&mut self, el: T) {
+ if self.vector.len() < self.max_capacity {
+ self.vector.push(el);
  }
  }
 
- pub fn current_function_names_stack(&self) -> Vec<FunctionName> {
- self.stack
- .iter()
- .map(|stack_element| stack_element.function_name.clone())
- .collect()
+ pub fn truncate(&mut self, len: usize) {
+ self.vector.truncate(len);
+ }
+
+ pub fn len(&self) -> usize {
+ self.vector.len()
+ }
+
+ pub fn deconstruct(self) -> (Vec<T>, usize) {
+ (self.vector, self.max_capacity)
+ }
+}
+
+impl<T> From<VecWithLimitedCapacity<T>> for Vec<T> {
+ fn from(value: VecWithLimitedCapacity<T>) -> Self {
+ value.vector
  }
 }