From b8c7078810e174ba2385f467467afd16bd211d16 Mon Sep 17 00:00:00 2001
From: Tom French <15848336+TomAFrench@users.noreply.github.com>
Date: Wed, 20 Dec 2023 18:33:34 +0000
Subject: [PATCH] chore: improve tracing of compiler execution (#3893)

# Description

## Problem\*

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

## Summary\*

This PR adds more comprehensive tracing through the compiler as well as
allowing us to monitor how long proving/verification takes.

## Additional Context



## Documentation\*

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

# PR Checklist\*

- [ ] I have tested the changes locally.
- [ ] I have formatted the changes with [Prettier](https://prettier.io/)
and/or `cargo fmt` on default settings.
---
 acvm-repo/acvm/src/compiler/optimizers/mod.rs                | 5 +++++
 compiler/noirc_driver/src/lib.rs                             | 1 +
 compiler/noirc_evaluator/src/ssa.rs                          | 2 +-
 compiler/noirc_evaluator/src/ssa/opt/array_use.rs            | 1 +
 compiler/noirc_evaluator/src/ssa/opt/assert_constant.rs      | 1 +
 compiler/noirc_evaluator/src/ssa/opt/constant_folding.rs     | 1 +
 compiler/noirc_evaluator/src/ssa/opt/defunctionalize.rs      | 1 +
 compiler/noirc_evaluator/src/ssa/opt/die.rs                  | 1 +
 compiler/noirc_evaluator/src/ssa/opt/fill_internal_slices.rs | 1 +
 compiler/noirc_evaluator/src/ssa/opt/flatten_cfg.rs          | 1 +
 compiler/noirc_evaluator/src/ssa/opt/inlining.rs             | 1 +
 compiler/noirc_evaluator/src/ssa/opt/mem2reg.rs              | 1 +
 compiler/noirc_evaluator/src/ssa/opt/simplify_cfg.rs         | 1 +
 compiler/noirc_evaluator/src/ssa/opt/unrolling.rs            | 1 +
 tooling/backend_interface/src/cli/write_vk.rs                | 1 +
 tooling/backend_interface/src/proof_system.rs                | 2 ++
 16 files changed, 21 insertions(+), 1 deletion(-)

diff --git a/acvm-repo/acvm/src/compiler/optimizers/mod.rs b/acvm-repo/acvm/src/compiler/optimizers/mod.rs
index 952bec2f7af..923756580b3 100644
--- a/acvm-repo/acvm/src/compiler/optimizers/mod.rs
+++ b/acvm-repo/acvm/src/compiler/optimizers/mod.rs
@@ -6,6 +6,7 @@ mod unused_memory;
 
 pub(crate) use general::GeneralOptimizer;
 pub(crate) use redundant_range::RangeOptimizer;
+use tracing::info;
 
 use self::unused_memory::UnusedMemoryOptimizer;
 
@@ -25,6 +26,8 @@ pub fn optimize(acir: Circuit) -> (Circuit, AcirTransformationMap) {
 /// Applies [`ProofSystemCompiler`][crate::ProofSystemCompiler] independent optimizations to a [`Circuit`].
 #[tracing::instrument(level = "trace", name = "optimize_acir" skip(acir))]
 pub(super) fn optimize_internal(acir: Circuit) -> (Circuit, Vec<usize>) {
+    info!("Number of opcodes before: {}", acir.opcodes.len());
+
     // General optimizer pass
     let opcodes: Vec<Opcode> = acir
         .opcodes
@@ -53,5 +56,7 @@ pub(super) fn optimize_internal(acir: Circuit) -> (Circuit, Vec<usize>) {
     let (acir, acir_opcode_positions) =
         range_optimizer.replace_redundant_ranges(acir_opcode_positions);
 
+    info!("Number of opcodes after: {}", acir.opcodes.len());
+
     (acir, acir_opcode_positions)
 }
diff --git a/compiler/noirc_driver/src/lib.rs b/compiler/noirc_driver/src/lib.rs
index 3908d16e01d..7136580b770 100644
--- a/compiler/noirc_driver/src/lib.rs
+++ b/compiler/noirc_driver/src/lib.rs
@@ -375,6 +375,7 @@ fn compile_contract_inner(
 /// Compile the current crate using `main_function` as the entrypoint.
 ///
 /// This function assumes [`check_crate`] is called beforehand.
+#[tracing::instrument(level = "trace", skip_all, fields(function_name = context.function_name(&main_function)))]
 pub fn compile_no_check(
     context: &Context,
     options: &CompileOptions,
diff --git a/compiler/noirc_evaluator/src/ssa.rs b/compiler/noirc_evaluator/src/ssa.rs
index 3c814c04eb2..deffe84baea 100644
--- a/compiler/noirc_evaluator/src/ssa.rs
+++ b/compiler/noirc_evaluator/src/ssa.rs
@@ -83,7 +83,7 @@ pub(crate) fn optimize_into_acir(
 ///
 /// The output ACIR is is backend-agnostic and so must go through a transformation pass before usage in proof generation.
 #[allow(clippy::type_complexity)]
-#[tracing::instrument(level = "trace", skip(program))]
+#[tracing::instrument(level = "trace", skip_all)]
 pub fn create_circuit(
     program: Program,
     enable_ssa_logging: bool,
diff --git a/compiler/noirc_evaluator/src/ssa/opt/array_use.rs b/compiler/noirc_evaluator/src/ssa/opt/array_use.rs
index cfa97cee551..0bb8b0112b6 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/array_use.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/array_use.rs
@@ -14,6 +14,7 @@ impl Ssa {
     /// Map arrays with the last instruction that uses it
     /// For this we simply process all the instructions in execution order
     /// and update the map whenever there is a match
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn find_last_array_uses(&self) -> HashMap<ValueId, InstructionId> {
         let mut array_use = HashMap::default();
         for func in self.functions.values() {
diff --git a/compiler/noirc_evaluator/src/ssa/opt/assert_constant.rs b/compiler/noirc_evaluator/src/ssa/opt/assert_constant.rs
index cd3a509a62e..a3608f89612 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/assert_constant.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/assert_constant.rs
@@ -21,6 +21,7 @@ impl Ssa {
     /// seen by loop unrolling. Furthermore, this pass cannot be a part of loop unrolling
     /// since we must go through every instruction to find all references to `assert_constant`
     /// while loop unrolling only touches blocks with loops in them.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn evaluate_assert_constant(mut self) -> Result<Ssa, RuntimeError> {
         for function in self.functions.values_mut() {
             for block in function.reachable_blocks() {
diff --git a/compiler/noirc_evaluator/src/ssa/opt/constant_folding.rs b/compiler/noirc_evaluator/src/ssa/opt/constant_folding.rs
index f48e6f2a129..e944d7d99d8 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/constant_folding.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/constant_folding.rs
@@ -40,6 +40,7 @@ impl Ssa {
     /// Performs constant folding on each instruction.
     ///
     /// See [`constant_folding`][self] module for more information.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn fold_constants(mut self) -> Ssa {
         for function in self.functions.values_mut() {
             constant_fold(function);
diff --git a/compiler/noirc_evaluator/src/ssa/opt/defunctionalize.rs b/compiler/noirc_evaluator/src/ssa/opt/defunctionalize.rs
index 62b335be1e2..b7f154397a6 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/defunctionalize.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/defunctionalize.rs
@@ -52,6 +52,7 @@ struct DefunctionalizationContext {
 }
 
 impl Ssa {
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn defunctionalize(mut self) -> Ssa {
         // Find all functions used as value that share the same signature
         let variants = find_variants(&self);
diff --git a/compiler/noirc_evaluator/src/ssa/opt/die.rs b/compiler/noirc_evaluator/src/ssa/opt/die.rs
index 492e96dc08c..029adb10054 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/die.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/die.rs
@@ -17,6 +17,7 @@ use crate::ssa::{
 impl Ssa {
     /// Performs Dead Instruction Elimination (DIE) to remove any instructions with
     /// unused results.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn dead_instruction_elimination(mut self) -> Ssa {
         for function in self.functions.values_mut() {
             dead_instruction_elimination(function);
diff --git a/compiler/noirc_evaluator/src/ssa/opt/fill_internal_slices.rs b/compiler/noirc_evaluator/src/ssa/opt/fill_internal_slices.rs
index f5e9598114c..5ee8e42fe3a 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/fill_internal_slices.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/fill_internal_slices.rs
@@ -60,6 +60,7 @@ use acvm::FieldElement;
 use fxhash::FxHashMap as HashMap;
 
 impl Ssa {
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn fill_internal_slices(mut self) -> Ssa {
         for function in self.functions.values_mut() {
             // This pass is only necessary for generating ACIR and thus we should not
diff --git a/compiler/noirc_evaluator/src/ssa/opt/flatten_cfg.rs b/compiler/noirc_evaluator/src/ssa/opt/flatten_cfg.rs
index f0ad610948c..0e7bfff7b6b 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/flatten_cfg.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/flatten_cfg.rs
@@ -163,6 +163,7 @@ impl Ssa {
     /// This pass will modify any instructions with side effects in particular, often multiplying
     /// them by jump conditions to maintain correctness even when all branches of a jmpif are inlined.
     /// For more information, see the module-level comment at the top of this file.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn flatten_cfg(mut self) -> Ssa {
         flatten_function_cfg(self.main_mut());
         self
diff --git a/compiler/noirc_evaluator/src/ssa/opt/inlining.rs b/compiler/noirc_evaluator/src/ssa/opt/inlining.rs
index b4f12b2f897..776f22b2877 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/inlining.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/inlining.rs
@@ -36,6 +36,7 @@ impl Ssa {
     /// changes. This is because if the function's id later becomes known by a later
     /// pass, we would need to re-run all of inlining anyway to inline it, so we might
     /// as well save the work for later instead of performing it twice.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn inline_functions(mut self) -> Ssa {
         self.functions = btree_map(get_entry_point_functions(&self), |entry_point| {
             let new_function = InlineContext::new(&self, entry_point).inline_all(&self);
diff --git a/compiler/noirc_evaluator/src/ssa/opt/mem2reg.rs b/compiler/noirc_evaluator/src/ssa/opt/mem2reg.rs
index ce205c8d883..0a49ca4ecca 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/mem2reg.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/mem2reg.rs
@@ -86,6 +86,7 @@ use self::block::{Block, Expression};
 impl Ssa {
     /// Attempts to remove any load instructions that recover values that are already available in
     /// scope, and attempts to remove stores that are subsequently redundant.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn mem2reg(mut self) -> Ssa {
         for function in self.functions.values_mut() {
             let mut context = PerFunctionContext::new(function);
diff --git a/compiler/noirc_evaluator/src/ssa/opt/simplify_cfg.rs b/compiler/noirc_evaluator/src/ssa/opt/simplify_cfg.rs
index d491afc3d26..a31def8fd98 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/simplify_cfg.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/simplify_cfg.rs
@@ -29,6 +29,7 @@ impl Ssa {
     ///    only 1 successor then (2) also will be applied.
     ///
     /// Currently, 1 and 4 are unimplemented.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn simplify_cfg(mut self) -> Self {
         for function in self.functions.values_mut() {
             simplify_function(function);
diff --git a/compiler/noirc_evaluator/src/ssa/opt/unrolling.rs b/compiler/noirc_evaluator/src/ssa/opt/unrolling.rs
index 50c2f5b1524..2fe9ea13cec 100644
--- a/compiler/noirc_evaluator/src/ssa/opt/unrolling.rs
+++ b/compiler/noirc_evaluator/src/ssa/opt/unrolling.rs
@@ -36,6 +36,7 @@ use fxhash::FxHashMap as HashMap;
 impl Ssa {
     /// Unroll all loops in each SSA function.
     /// If any loop cannot be unrolled, it is left as-is or in a partially unrolled state.
+    #[tracing::instrument(level = "trace", skip(self))]
     pub(crate) fn unroll_loops(mut self) -> Result<Ssa, RuntimeError> {
         for function in self.functions.values_mut() {
             // Loop unrolling in brillig can lead to a code explosion currently. This can
diff --git a/tooling/backend_interface/src/cli/write_vk.rs b/tooling/backend_interface/src/cli/write_vk.rs
index 8d4aa9cc7e3..da9fc04cbef 100644
--- a/tooling/backend_interface/src/cli/write_vk.rs
+++ b/tooling/backend_interface/src/cli/write_vk.rs
@@ -12,6 +12,7 @@ pub(crate) struct WriteVkCommand {
 }
 
 impl WriteVkCommand {
+    #[tracing::instrument(level = "trace", name = "vk_generation", skip_all)]
     pub(crate) fn run(self, binary_path: &Path) -> Result<(), BackendError> {
         let mut command = std::process::Command::new(binary_path);
 
diff --git a/tooling/backend_interface/src/proof_system.rs b/tooling/backend_interface/src/proof_system.rs
index 6eee7c890c8..595cd7e2020 100644
--- a/tooling/backend_interface/src/proof_system.rs
+++ b/tooling/backend_interface/src/proof_system.rs
@@ -50,6 +50,7 @@ impl Backend {
         }
     }
 
+    #[tracing::instrument(level = "trace", skip_all)]
     pub fn prove(
         &self,
         circuit: &Circuit,
@@ -90,6 +91,7 @@ impl Backend {
         Ok(proof)
     }
 
+    #[tracing::instrument(level = "trace", skip_all)]
     pub fn verify(
         &self,
         proof: &[u8],