feat(tracer): Record function calls and returns

test_programs/plonky2_trace/1_mul/expected_trace.json

@@ -3,8 +3,10 @@
   { "Function": { "path_id": 0, "line": -1, "name": "<toplevel>" } },
   { "Call": { "function_id": 0, "args": [] } },
   { "Type": { "kind": 30, "lang_type": "None", "specific_info": { "kind": "None" } } },
-  { "Path": "it-does-not-matter" },
+  { "Path": "<relative-to-this>/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 } },

test_programs/plonky2_trace/2_function_calls/expected_trace.json

@@ -3,22 +3,35 @@
   { "Function": { "path_id": 0, "line": -1, "name": "<toplevel>" } },
   { "Call": { "function_id": 0, "args": [] } },
   { "Type": { "kind": 30, "lang_type": "None", "specific_info": { "kind": "None" } } },
-  { "Path": "it-does-not-matter" },
+  { "Path": "<relative-to-this>/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 } }
 ]

test_programs/plonky2_trace/3_two_files/expected_trace.json

@@ -3,17 +3,26 @@
   { "Function": { "path_id": 0, "line": -1, "name": "<toplevel>" } },
   { "Call": { "function_id": 0, "args": [] } },
   { "Type": { "kind": 30, "lang_type": "None", "specific_info": { "kind": "None" } } },
-  { "Path": "<relative-to-json>/src/main.nr" },
+  { "Path": "<relative-to-this>/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": "<relative-to-json>/src/foo.nr" },
+  { "Path": "<relative-to-this>/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": "<relative-to-json>/src/bar.nr" },
+  { "Path": "<relative-to-this>/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 } }
 ]

tooling/debugger/src/context.rs

@@ -490,7 +490,7 @@ impl<'a, B: BlackBoxFunctionSolver<FieldElement>> DebugContext<'a, B> {
         }
     }
 
-    pub(super) fn get_variables(&self) -> Vec<StackFrame<FieldElement>> {
+    pub fn get_variables(&self) -> Vec<StackFrame<FieldElement>> {
         return self.foreign_call_executor.get_variables();
     }
 

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(())

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,15 +13,14 @@ 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};
 
 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(Error),
 }
 
+#[derive(Clone, Debug, PartialEq)]
+struct StackFrame {
+    function_name: String,
+}
+
 pub struct TracingContext<'a, B: BlackBoxFunctionSolver<FieldElement>> {
     debug_context: DebugContext<'a, B>,
     /// The source location at the current moment of tracing.
     source_locations: Vec<SourceLocation>,
+    /// The stack trace at the current moment; last call is last in the vector.
+    stack_trace: Vec<StackFrame>,
 }
 
 impl<'a, B: BlackBoxFunctionSolver<FieldElement>> TracingContext<'a, B> {
@@ -69,7 +79,7 @@ impl<'a, B: BlackBoxFunctionSolver<FieldElement>> 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<FieldElement>> 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<StackFrame> {
+        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<SourceLocation>) {
-        // 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);
         }
     }
 }

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::<usize>(&vec!(), &vec!()), (0, vec!(), vec!()));
+/// ```
+pub fn tail_diff_vecs<'a, T>(xs: &'a Vec<T>, ys: &'a Vec<T>) -> (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)
+}