chore: add tracing to program compilation + execution (#3811)

# Description

## Problem\*

Resolves <!-- Link to GitHub Issue -->

## Summary\*

This PR adds tracing logs to various operations so we can track what
gets called and how long it takes easily.

## Additional Context



## Documentation\*

Check one:
- [x] No documentation needed.
- [ ] Documentation included in this PR.
- [ ] **[Exceptional Case]** Documentation to be submitted in a separate
PR.

# PR Checklist\*

- [x] I have tested the changes locally.
- [x] I have formatted the changes with [Prettier](https://prettier.io/)
and/or `cargo fmt` on default settings.

acvm-repo/acvm/Cargo.toml

@@ -16,6 +16,7 @@ repository.workspace = true
 num-bigint.workspace = true
 num-traits.workspace = true
 thiserror.workspace = true
+log.workspace = true
 
 acir.workspace = true
 stdlib.workspace = true

acvm-repo/acvm/src/compiler/optimizers/mod.rs

@@ -22,6 +22,8 @@ pub fn optimize(acir: Circuit) -> (Circuit, AcirTransformationMap) {
 
 /// Applies [`ProofSystemCompiler`][crate::ProofSystemCompiler] independent optimizations to a [`Circuit`].
 pub(super) fn optimize_internal(acir: Circuit) -> (Circuit, AcirTransformationMap) {
+    log::trace!("Start circuit optimization");
+
     // General optimizer pass
     let opcodes: Vec<Opcode> = acir
         .opcodes
@@ -52,5 +54,7 @@ pub(super) fn optimize_internal(acir: Circuit) -> (Circuit, AcirTransformationMa
 
     let transformation_map = AcirTransformationMap { acir_opcode_positions };
 
+    log::trace!("Finish circuit optimization");
+
     (acir, transformation_map)
 }

acvm-repo/acvm/src/compiler/transformers/mod.rs

@@ -44,6 +44,8 @@ pub(super) fn transform_internal(
     is_opcode_supported: impl Fn(&Opcode) -> bool,
     acir_opcode_positions: Vec<usize>,
 ) -> Result<(Circuit, AcirTransformationMap), CompileError> {
+    log::trace!("Start circuit transformation");
+
     // Fallback transformer pass
     let (acir, acir_opcode_positions) =
         FallbackTransformer::transform(acir, is_opcode_supported, acir_opcode_positions)?;
@@ -217,5 +219,7 @@ pub(super) fn transform_internal(
     let transformation_map =
         AcirTransformationMap { acir_opcode_positions: new_acir_opcode_positions };
 
+    log::trace!("Finish circuit transformation");
+
     Ok((acir, transformation_map))
 }

compiler/noirc_driver/Cargo.toml

@@ -22,5 +22,6 @@ fm.workspace = true
 serde.workspace = true
 fxhash.workspace = true
 rust-embed = "6.6.0"
+log.workspace = true
 
 aztec_macros = { path = "../../aztec_macros" }

compiler/noirc_driver/src/lib.rs

@@ -147,6 +147,8 @@ pub fn check_crate(
     deny_warnings: bool,
     disable_macros: bool,
 ) -> CompilationResult<()> {
+    log::trace!("Start checking crate");
+
     let macros: Vec<&dyn MacroProcessor> = if disable_macros {
         vec![]
     } else {
@@ -160,6 +162,8 @@ pub fn check_crate(
         diagnostic.in_file(file_id)
     }));
 
+    log::trace!("Finish checking crate");
+
     if has_errors(&errors, deny_warnings) {
         Err(errors)
     } else {
@@ -372,6 +376,7 @@ pub fn compile_no_check(
         force_compile || options.print_acir || options.show_brillig || options.show_ssa;
 
     if !force_compile && hashes_match {
+        log::info!("Program matches existing artifact, returning early");
         return Ok(cached_program.expect("cache must exist for hashes to match"));
     }
     let visibility = program.return_visibility;

compiler/noirc_errors/Cargo.toml

@@ -15,3 +15,4 @@ fm.workspace = true
 chumsky.workspace = true
 serde.workspace = true
 serde_with = "3.2.0"
+log.workspace = true

compiler/noirc_errors/src/debug_info.rs

@@ -39,13 +39,15 @@ impl DebugInfo {
     /// renders the old `OpcodeLocation`s invalid. The AcirTransformationMap is able to map the old `OpcodeLocation` to the new ones.
     /// Note: One old `OpcodeLocation` might have transformed into more than one new `OpcodeLocation`.
     pub fn update_acir(&mut self, update_map: AcirTransformationMap) {
+        log::trace!("Start debug info update");
         let old_locations = mem::take(&mut self.locations);
 
         for (old_opcode_location, source_locations) in old_locations {
             update_map.new_locations(old_opcode_location).for_each(|new_opcode_location| {
                 self.locations.insert(new_opcode_location, source_locations.clone());
             });
         }
+        log::trace!("Finish debug info update");
     }
 
     pub fn opcode_location(&self, loc: &OpcodeLocation) -> Option<Vec<Location>> {

compiler/noirc_evaluator/Cargo.toml

@@ -17,3 +17,4 @@ thiserror.workspace = true
 num-bigint = "0.4"
 im = { version = "15.1", features = ["serde"] }
 serde.workspace = true
+log.workspace = true

compiler/noirc_evaluator/src/ssa.rs

@@ -42,6 +42,7 @@ pub(crate) fn optimize_into_acir(
 ) -> Result<GeneratedAcir, RuntimeError> {
     let abi_distinctness = program.return_distinctness;
 
+    log::trace!("Start SSA generation");
     let ssa_builder = SsaBuilder::new(program, print_ssa_passes)?
         .run_pass(Ssa::defunctionalize, "After Defunctionalization:")
         .run_pass(Ssa::inline_functions, "After Inlining:")
@@ -69,9 +70,15 @@ pub(crate) fn optimize_into_acir(
     let ssa = ssa_builder
         .run_pass(Ssa::fill_internal_slices, "After Fill Internal Slice Dummy Data:")
         .finish();
+    log::trace!("Finish SSA generation");
 
     let last_array_uses = ssa.find_last_array_uses();
-    ssa.into_acir(brillig, abi_distinctness, &last_array_uses)
+
+    log::trace!("Start ACIR generation");
+    let acir = ssa.into_acir(brillig, abi_distinctness, &last_array_uses);
+    log::trace!("Finish ACIR generation");
+
+    acir
 }
 
 /// Compiles the [`Program`] into [`ACIR`][acvm::acir::circuit::Circuit].
@@ -83,6 +90,8 @@ pub fn create_circuit(
     enable_ssa_logging: bool,
     enable_brillig_logging: bool,
 ) -> Result<(Circuit, DebugInfo, Vec<Witness>, Vec<Witness>, Vec<SsaReport>), RuntimeError> {
+    log::trace!("Start circuit generation");
+
     let func_sig = program.main_function_signature.clone();
     let mut generated_acir =
         optimize_into_acir(program, enable_ssa_logging, enable_brillig_logging)?;
@@ -124,6 +133,8 @@ pub fn create_circuit(
     let (optimized_circuit, transformation_map) = acvm::compiler::optimize(circuit);
     debug_info.update_acir(transformation_map);
 
+    log::trace!("Finish circuit generation");
+
     Ok((optimized_circuit, debug_info, input_witnesses, return_witnesses, warnings))
 }
 

compiler/noirc_frontend/Cargo.toml

@@ -22,6 +22,7 @@ serde.workspace = true
 rustc-hash = "1.1.0"
 small-ord-set = "0.1.3"
 regex = "1.9.1"
+log.workspace = true
 
 [dev-dependencies]
 strum = "0.24"

compiler/noirc_frontend/src/monomorphization/mod.rs

@@ -92,6 +92,7 @@ type HirType = crate::Type;
 /// this function. Typically, this is the function named "main" in the source project,
 /// but it can also be, for example, an arbitrary test function for running `nargo test`.
 pub fn monomorphize(main: node_interner::FuncId, interner: &NodeInterner) -> Program {
+    log::trace!("Start monomorphization");
     let mut monomorphizer = Monomorphizer::new(interner);
     let function_sig = monomorphizer.compile_main(main);
 
@@ -106,6 +107,8 @@ pub fn monomorphize(main: node_interner::FuncId, interner: &NodeInterner) -> Pro
 
     let functions = vecmap(monomorphizer.finished_functions, |(_, f)| f);
     let FuncMeta { return_distinctness, return_visibility, .. } = interner.function_meta(&main);
+
+    log::trace!("Finish monomorphization");
     Program::new(
         functions,
         function_sig,

tooling/nargo/Cargo.toml

@@ -24,9 +24,10 @@ iter-extended.workspace = true
 serde.workspace = true
 thiserror.workspace = true
 codespan-reporting.workspace = true
+log.workspace = true
 rayon = "1.8.0"
 
 [dev-dependencies]
 # TODO: This dependency is used to generate unit tests for `get_all_paths_in_dir`
 # TODO: once that method is moved to nargo_cli, we can move this dependency to nargo_cli
-tempfile = "3.2.0"
+tempfile = "3.2.0"

tooling/nargo/src/ops/execute.rs

@@ -13,6 +13,7 @@ pub fn execute_circuit<B: BlackBoxFunctionSolver, F: ForeignCallExecutor>(
     blackbox_solver: &B,
     foreign_call_executor: &mut F,
 ) -> Result<WitnessMap, NargoError> {
+    log::trace!("Start circuit execution");
     let mut acvm = ACVM::new(blackbox_solver, &circuit.opcodes, initial_witness);
 
     loop {
@@ -55,5 +56,7 @@ pub fn execute_circuit<B: BlackBoxFunctionSolver, F: ForeignCallExecutor>(
     }
 
     let solved_witness = acvm.finalize();
+
+    log::trace!("Finish circuit execution");
     Ok(solved_witness)
 }