From 38bfd203228c5b1b21f6fac1f0d107b0f1775d0d Mon Sep 17 00:00:00 2001 From: Stan Manilov Date: Fri, 5 Jul 2024 17:44:49 +0300 Subject: [PATCH] feat(tracer): Record function calls and returns This commit also records function calls and returns from functions, without passing the actual arguments and values in either direction. That would be a follow-up. Details: * `get_variables` is now public in `tooling/debugger/src/context.rs`; it is needed to extract the stack frame from the debugger; * drive-by: `trace_metadata.json` is also stored, because the frontend expects that too; * `tail_diff_vecs` is a generic utility function to extract the difference between two vectors; it has good documentation, so details within; * a local structure `StackFrame` is introduced, because the `StackFrame` in the debugger does not own its data; here, we need to remember the previous stack trace (a vector of `StackFrame`'s) in order to discover function calls or returns, so we need to own the data; * a `stack_trace` field is added to `TracingContext`; see previous point; * the new `fn get_stack_trace` performs the conversion mentioned; * the old contents of `update_record` are the basis for `tail_diff_vecs`; the new contents use that function to perform the same operation as before; in addition, the core logic of the PR is here: return events are registered for dropped stack frames and call events are registered for new stack frames; * all tracing tests are updated, to reflect the new traces that are generated. To test: ``` cargo test trace ``` --- .../plonky2_trace/1_mul/expected_trace.json | 4 +- .../2_function_calls/expected_trace.json | 15 ++++- .../3_two_files/expected_trace.json | 15 ++++- tooling/debugger/src/context.rs | 2 +- tooling/nargo_cli/src/cli/trace_cmd.rs | 8 ++- tooling/tracer/src/lib.rs | 62 ++++++++++++++----- tooling/tracer/src/tail_diff_vecs.rs | 40 ++++++++++++ 7 files changed, 122 insertions(+), 24 deletions(-) create mode 100644 tooling/tracer/src/tail_diff_vecs.rs diff --git a/test_programs/plonky2_trace/1_mul/expected_trace.json b/test_programs/plonky2_trace/1_mul/expected_trace.json index 63481f513aa..30bc50b7a5a 100644 --- a/test_programs/plonky2_trace/1_mul/expected_trace.json +++ b/test_programs/plonky2_trace/1_mul/expected_trace.json @@ -3,8 +3,10 @@ { "Function": { "path_id": 0, "line": -1, "name": "" } }, { "Call": { "function_id": 0, "args": [] } }, { "Type": { "kind": 30, "lang_type": "None", "specific_info": { "kind": "None" } } }, - { "Path": "it-does-not-matter" }, + { "Path": "/src/main.nr" }, { "Step": { "path_id": 1, "line": 3 } }, + { "Function": { "path_id": 1, "line": 4, "name": "main" } }, + { "Call": { "function_id": 1, "args": [] } }, { "Step": { "path_id": 1, "line": 4 } }, { "Step": { "path_id": 1, "line": 5 } }, { "Step": { "path_id": 1, "line": 6 } }, diff --git a/test_programs/plonky2_trace/2_function_calls/expected_trace.json b/test_programs/plonky2_trace/2_function_calls/expected_trace.json index 6966cb03ef4..735877c322b 100644 --- a/test_programs/plonky2_trace/2_function_calls/expected_trace.json +++ b/test_programs/plonky2_trace/2_function_calls/expected_trace.json @@ -3,22 +3,35 @@ { "Function": { "path_id": 0, "line": -1, "name": "" } }, { "Call": { "function_id": 0, "args": [] } }, { "Type": { "kind": 30, "lang_type": "None", "specific_info": { "kind": "None" } } }, - { "Path": "it-does-not-matter" }, + { "Path": "/src/main.nr" }, { "Step": { "path_id": 1, "line": 9 } }, + { "Function": { "path_id": 1, "line": 10, "name": "main" } }, + { "Call": { "function_id": 1, "args": [] } }, { "Step": { "path_id": 1, "line": 10 } }, { "Step": { "path_id": 1, "line": 5 } }, + { "Function": { "path_id": 1, "line": 6, "name": "foo" } }, + { "Call": { "function_id": 2, "args": [] } }, { "Step": { "path_id": 1, "line": 6 } }, { "Step": { "path_id": 1, "line": 1 } }, + { "Function": { "path_id": 1, "line": 2, "name": "bar" } }, + { "Call": { "function_id": 3, "args": [] } }, { "Step": { "path_id": 1, "line": 2 } }, { "Step": { "path_id": 1, "line": 3 } }, + { "Type": { "kind": 30, "lang_type": "()", "specific_info": { "kind": "None" } } }, + { "Return": { "return_value": { "kind": "None", "type_id": 1 } } }, { "Step": { "path_id": 1, "line": 7 } }, + { "Return": { "return_value": { "kind": "None", "type_id": 1 } } }, { "Step": { "path_id": 1, "line": 11 } }, { "Step": { "path_id": 1, "line": 5 } }, + { "Call": { "function_id": 2, "args": [] } }, { "Step": { "path_id": 1, "line": 6 } }, { "Step": { "path_id": 1, "line": 1 } }, + { "Call": { "function_id": 3, "args": [] } }, { "Step": { "path_id": 1, "line": 2 } }, { "Step": { "path_id": 1, "line": 3 } }, + { "Return": { "return_value": { "kind": "None", "type_id": 1 } } }, { "Step": { "path_id": 1, "line": 7 } }, + { "Return": { "return_value": { "kind": "None", "type_id": 1 } } }, { "Step": { "path_id": 1, "line": 12 } }, { "Step": { "path_id": 1, "line": 13 } } ] diff --git a/test_programs/plonky2_trace/3_two_files/expected_trace.json b/test_programs/plonky2_trace/3_two_files/expected_trace.json index b140a23b9ea..a8e302d8684 100644 --- a/test_programs/plonky2_trace/3_two_files/expected_trace.json +++ b/test_programs/plonky2_trace/3_two_files/expected_trace.json @@ -3,17 +3,26 @@ { "Function": { "path_id": 0, "line": -1, "name": "" } }, { "Call": { "function_id": 0, "args": [] } }, { "Type": { "kind": 30, "lang_type": "None", "specific_info": { "kind": "None" } } }, - { "Path": "/src/main.nr" }, + { "Path": "/src/main.nr" }, { "Step": { "path_id": 1, "line": 6 } }, + { "Function": { "path_id": 1, "line": 7, "name": "main" } }, + { "Call": { "function_id": 1, "args": [] } }, { "Step": { "path_id": 1, "line": 7 } }, - { "Path": "/src/foo.nr" }, + { "Path": "/src/foo.nr" }, { "Step": { "path_id": 2, "line": 3 } }, + { "Function": { "path_id": 2, "line": 4, "name": "foo" } }, + { "Call": { "function_id": 2, "args": [] } }, { "Step": { "path_id": 2, "line": 4 } }, - { "Path": "/src/bar.nr" }, + { "Path": "/src/bar.nr" }, { "Step": { "path_id": 3, "line": 1 } }, + { "Function": { "path_id": 3, "line": 2, "name": "bar" } }, + { "Call": { "function_id": 3, "args": [] } }, { "Step": { "path_id": 3, "line": 2 } }, { "Step": { "path_id": 3, "line": 3 } }, + { "Type": { "kind": 30, "lang_type": "()", "specific_info": { "kind": "None" } } }, + { "Return": { "return_value": { "kind": "None", "type_id": 1 } } }, { "Step": { "path_id": 2, "line": 5 } }, + { "Return": { "return_value": { "kind": "None", "type_id": 1 } } }, { "Step": { "path_id": 1, "line": 8 } }, { "Step": { "path_id": 1, "line": 9 } } ] diff --git a/tooling/debugger/src/context.rs b/tooling/debugger/src/context.rs index 01e105970cf..da79cd648f3 100644 --- a/tooling/debugger/src/context.rs +++ b/tooling/debugger/src/context.rs @@ -490,7 +490,7 @@ impl<'a, B: BlackBoxFunctionSolver> DebugContext<'a, B> { } } - pub(super) fn get_variables(&self) -> Vec> { + pub fn get_variables(&self) -> Vec> { return self.foreign_call_executor.get_variables(); } diff --git a/tooling/nargo_cli/src/cli/trace_cmd.rs b/tooling/nargo_cli/src/cli/trace_cmd.rs index 5e09f157ca5..8df1ca8f66e 100644 --- a/tooling/nargo_cli/src/cli/trace_cmd.rs +++ b/tooling/nargo_cli/src/cli/trace_cmd.rs @@ -109,7 +109,13 @@ pub(crate) fn trace_program( let trace_path = Path::new(trace_dir).join("trace.json"); match tracer.store_trace_events(&trace_path) { Ok(_) => println!("Saved trace to {:?}", trace_path), - Err(_) => (), + Err(err) => println!("Warning: tracer failed to store trace events: {err}"), + } + + let trace_path = Path::new(trace_dir).join("trace_metadata.json"); + match tracer.store_trace_metadata(&trace_path) { + Ok(_) => println!("Saved trace to {:?}", trace_path), + Err(err) => println!("Warning: tracer failed to store trace metadata: {err}"), } Ok(()) diff --git a/tooling/tracer/src/lib.rs b/tooling/tracer/src/lib.rs index c5c1c95643a..722ecaa0b13 100644 --- a/tooling/tracer/src/lib.rs +++ b/tooling/tracer/src/lib.rs @@ -1,3 +1,7 @@ +pub mod tail_diff_vecs; + +use tail_diff_vecs::tail_diff_vecs; + use noir_debugger::context::{DebugCommandResult, DebugContext}; use acvm::{acir::circuit::Circuit, acir::native_types::WitnessMap}; @@ -9,7 +13,6 @@ use noir_debugger::foreign_calls::DefaultDebugForeignCallExecutor; use noirc_artifacts::debug::DebugArtifact; use fm::PathString; -use std::cmp::min; use std::path::PathBuf; use runtime_tracing::{Line, Tracer}; @@ -17,7 +20,7 @@ use runtime_tracing::{Line, Tracer}; use nargo::NargoError; /// A location in the source code: filename and line number (1-indexed). -#[derive(PartialEq)] +#[derive(Clone, Debug, PartialEq)] struct SourceLocation { filepath: PathString, line_number: isize, @@ -44,10 +47,17 @@ enum DebugStepResult { Error(Error), } +#[derive(Clone, Debug, PartialEq)] +struct StackFrame { + function_name: String, +} + pub struct TracingContext<'a, B: BlackBoxFunctionSolver> { debug_context: DebugContext<'a, B>, /// The source location at the current moment of tracing. source_locations: Vec, + /// The stack trace at the current moment; last call is last in the vector. + stack_trace: Vec, } impl<'a, B: BlackBoxFunctionSolver> TracingContext<'a, B> { @@ -69,7 +79,7 @@ impl<'a, B: BlackBoxFunctionSolver> TracingContext<'a, B> { unconstrained_functions, ); - Self { debug_context, source_locations: vec![] } + Self { debug_context, source_locations: vec![], stack_trace: vec![] } } /// Extracts the current stack of source locations from the debugger, given that the relevant @@ -151,23 +161,41 @@ impl<'a, B: BlackBoxFunctionSolver> TracingContext<'a, B> { } } + /// Converts the debugger stack frames into a vector of stack frames that own their data. + fn get_stack_frames(&mut self) -> Vec { + self.debug_context + .get_variables() + .iter() + .map(|f| StackFrame { function_name: String::from(f.function_name) }) + .collect() + } + /// Propagates information about the current execution state to `tracer`. fn update_record(&mut self, tracer: &mut Tracer, source_locations: &Vec) { - // Find the last index of the previous and current stack traces, until which they are - // identical. - let mut last_match: isize = -1; - for i in 0..min(self.source_locations.len(), source_locations.len()) { - if self.source_locations[i] == source_locations[i] { - last_match = i as isize; - continue; - } - break; + let stack_trace = self.get_stack_frames(); + let (first_nomatch, dropped_frames, new_frames) = + tail_diff_vecs(&self.stack_trace, &stack_trace); + + for _ in dropped_frames { + let type_id = tracer.ensure_type_id(runtime_tracing::TypeKind::None, "()"); + tracer.register_return(runtime_tracing::ValueRecord::None { type_id }); + } + + for i in 0..new_frames.len() { + let SourceLocation { filepath, line_number } = &source_locations[first_nomatch + i]; + let path = &PathBuf::from(filepath.to_string()); + let line = Line(*line_number as i64); + let file_id = tracer.ensure_function_id(&new_frames[i].function_name, path, line); + tracer.register_call(file_id, vec![]); } - // For the rest of the indexes of the new call stack: register a step that was performed to - // reach that frame of the call stack. - for i in ((last_match + 1) as usize)..source_locations.len() { - let SourceLocation { filepath, line_number } = &source_locations[i]; - tracer.register_step(&PathBuf::from(filepath.to_string()), Line(*line_number as i64)); + + self.stack_trace = stack_trace; + + let (_, _, new_source_locations) = tail_diff_vecs(&self.source_locations, source_locations); + for SourceLocation { filepath, line_number } in new_source_locations { + let path = &PathBuf::from(filepath.to_string()); + let line = Line(*line_number as i64); + tracer.register_step(path, line); } } } diff --git a/tooling/tracer/src/tail_diff_vecs.rs b/tooling/tracer/src/tail_diff_vecs.rs new file mode 100644 index 00000000000..24471cd14da --- /dev/null +++ b/tooling/tracer/src/tail_diff_vecs.rs @@ -0,0 +1,40 @@ +/// Produce the "tail difference" of two vectors. +/// +/// Here, this means that the common prefix of the two vectors is computed. The length of that +/// prefix is returned, together with the suffix of the first vector that follows the common +/// prefix, as well as the suffix of the second vector that follows the common prefix. +/// +/// Example: +/// ``` +/// use noir_tracer::tail_diff_vecs::tail_diff_vecs; +/// let a = 1; +/// let b = 2; +/// let c = 3; +/// let d = 4; +/// let e = 5; +/// let f = 6; +/// +/// assert_eq!(tail_diff_vecs(&vec!(a, b, c), &vec!(a, b, e, f)), (2, vec!(&c), vec!(&e, &f))); +// +/// assert_eq!(tail_diff_vecs(&vec!(a, b, c), &vec!(e, f)), (0, vec!(&a, &b, &c), vec!(&e, &f))); +/// +/// assert_eq!(tail_diff_vecs(&vec!(a, b, c), &vec!(a, b)), (2, vec!(&c), vec!())); +/// +/// assert_eq!(tail_diff_vecs(&vec!(a, b, c, d), &vec!(a, b, e)), (2, vec!(&c, &d), vec!(&e))); +/// +/// // Corner cases: +/// assert_eq!(tail_diff_vecs(&vec!(a, b), &vec!(a, b, c)), (2, vec!(), vec!(&c))); +/// assert_eq!(tail_diff_vecs::(&vec!(), &vec!()), (0, vec!(), vec!())); +/// ``` +pub fn tail_diff_vecs<'a, T>(xs: &'a Vec, ys: &'a Vec) -> (usize, Vec<&'a T>, Vec<&'a T>) +where + T: PartialEq + Clone, +{ + let min_len = std::cmp::min(xs.len(), ys.len()); + let first_nomatch = xs.iter().zip(ys.iter()).position(|(x, y)| x != y).unwrap_or(min_len); + + let xs_tail: Vec<&T> = xs[first_nomatch..].iter().collect(); + let ys_tail: Vec<&T> = ys[first_nomatch..].iter().collect(); + + (first_nomatch, xs_tail, ys_tail) +}