chore: use logs for benchmarking (#6911)

Co-authored-by: Maxim Vezenov <[email protected]>
noir-lang · Jan 4, 2025 · 06ba20c · 06ba20c
1 parent a7781a7
commit 06ba20c
Show file tree

Hide file tree

Showing 12 changed files with 114 additions and 53 deletions.
diff --git a/.github/workflows/reports.yml b/.github/workflows/reports.yml
@@ -300,7 +300,6 @@ jobs:
       matrix:
         include:
           - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-contracts, is_library: true }
-          - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/parity-root, take_average: true }
           - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/private-kernel-inner, take_average: true }
           - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/private-kernel-tail, take_average: true  }
           - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/private-kernel-reset, take_average: true }
@@ -331,13 +330,8 @@ jobs:
           path: scripts
           sparse-checkout: |
             test_programs/compilation_report.sh
-          sparse-checkout-cone-mode: false
-
-      - uses: actions/checkout@v4
-        with:
-          path: scripts
-          sparse-checkout: |
             test_programs/execution_report.sh
+            test_programs/parse_time.sh
           sparse-checkout-cone-mode: false
 
       - name: Checkout
@@ -352,29 +346,35 @@ jobs:
         if: ${{ !matrix.project.take_average }}
         run: |
           mv /home/runner/work/noir/noir/scripts/test_programs/compilation_report.sh ./compilation_report.sh
-          chmod +x ./compilation_report.sh
+          touch parse_time.sh
+          chmod +x parse_time.sh
+          cp /home/runner/work/noir/noir/scripts/test_programs/parse_time.sh ./parse_time.sh
           ./compilation_report.sh 1
 
       - name: Generate compilation report with averages
         working-directory: ./test-repo/${{ matrix.project.path }}
         if: ${{ matrix.project.take_average }}
         run: |
           mv /home/runner/work/noir/noir/scripts/test_programs/compilation_report.sh ./compilation_report.sh
-          chmod +x ./compilation_report.sh
+          touch parse_time.sh
+          chmod +x parse_time.sh
+          cp /home/runner/work/noir/noir/scripts/test_programs/parse_time.sh ./parse_time.sh
           ./compilation_report.sh 1 1
       
       - name: Generate execution report without averages
         working-directory: ./test-repo/${{ matrix.project.path }}
         if: ${{ !matrix.project.is_library && !matrix.project.take_average }}
         run: |
           mv /home/runner/work/noir/noir/scripts/test_programs/execution_report.sh ./execution_report.sh
+          mv /home/runner/work/noir/noir/scripts/test_programs/parse_time.sh ./parse_time.sh
           ./execution_report.sh 1
 
       - name: Generate execution report with averages
         working-directory: ./test-repo/${{ matrix.project.path }}
         if: ${{ !matrix.project.is_library && matrix.project.take_average }}
         run: |
           mv /home/runner/work/noir/noir/scripts/test_programs/execution_report.sh ./execution_report.sh
+          mv /home/runner/work/noir/noir/scripts/test_programs/parse_time.sh ./parse_time.sh
           ./execution_report.sh 1 1
 
       - name: Move compilation report
@@ -466,7 +466,6 @@ jobs:
         include:
           # TODO: Bring this report back under a flag. The `noir-contracts` report takes just under 30 minutes.
           # - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-contracts }
-          - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/parity-root }
           - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/private-kernel-inner }
           - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/private-kernel-reset }
           - project: { repo: AztecProtocol/aztec-packages, path: noir-projects/noir-protocol-circuits/crates/private-kernel-tail }

diff --git a/Cargo.lock b/Cargo.lock
diff --git a/Cargo.toml b/Cargo.toml
@@ -163,7 +163,7 @@ tokio = "1.42"
 im = { version = "15.1", features = ["serde"] }
 tracing = "0.1.40"
 tracing-web = "0.1.3"
-tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
+tracing-subscriber = { version = "0.3.18", features = ["env-filter", "json"] }
 rust-embed = "6.6.0"
 
 [profile.dev]

diff --git a/test_programs/compilation_report.sh b/test_programs/compilation_report.sh
@@ -1,6 +1,7 @@
 #!/usr/bin/env bash
 set -e
 
+PARSE_TIME=$(realpath "$(dirname "$0")/parse_time.sh")
 current_dir=$(pwd)
 base_path="$current_dir/execution_success"
 
@@ -46,23 +47,34 @@ for dir in ${tests_to_profile[@]}; do
     fi
 
     for ((i = 1; i <= NUM_RUNS; i++)); do
-      COMPILE_TIME=$((time nargo compile --force --silence-warnings) 2>&1 | grep real | grep -oE '[0-9]+m[0-9]+.[0-9]+s')
-      # Convert time to seconds and add to total time
-      TOTAL_TIME=$(echo "$TOTAL_TIME + $(echo $COMPILE_TIME | sed -E 's/([0-9]+)m([0-9.]+)s/\1 * 60 + \2/' | bc)" | bc)
+      NOIR_LOG=trace NARGO_LOG_DIR=./tmp nargo compile --force --silence-warnings
     done
 
-    AVG_TIME=$(echo "$TOTAL_TIME / $NUM_RUNS" | bc -l)
-    # Keep only last three decimal points
-    AVG_TIME=$(awk '{printf "%.3f\n", $1}' <<< "$AVG_TIME")
-
-    echo -e " {\n    \"artifact_name\":\"$PACKAGE_NAME\",\n    \"time\":\""$AVG_TIME"s\"" >> $current_dir/compilation_report.json
-    
-    if (($ITER == $NUM_ARTIFACTS)); then
-        echo "}" >> $current_dir/compilation_report.json
-    else 
-        echo "}, " >> $current_dir/compilation_report.json
+    TIMES=($(jq -r '. | select(.target == "nargo::cli" and .fields.message == "close") | .fields."time.busy"' ./tmp/*))
+
+    AVG_TIME=$(awk -v RS=" " -v parse_time="$PARSE_TIME"  '
+        {
+            # Times are formatted annoyingly so we need to parse it.
+            parse_time" "$1 | getline current_time
+            close(parse_time" "$1)
+            sum += current_time;
+            n++;
+        }
+        END {   
+            if (n > 0)
+                printf "%.3f\n", sum / n
+            else
+                printf "%.3f\n", 0
+        }' <<<"${TIMES[@]}")
+
+    jq -rc "{artifact_name: \"$PACKAGE_NAME\", time: \""$AVG_TIME"s\"}" --null-input >> $current_dir/compilation_report.json
+
+    if (($ITER != $NUM_ARTIFACTS)); then
+        echo "," >> $current_dir/compilation_report.json
     fi
 
+    rm -rf ./tmp
+
     ITER=$(( $ITER + 1 ))
 done
 

diff --git a/test_programs/execution_report.sh b/test_programs/execution_report.sh
@@ -1,6 +1,7 @@
 #!/usr/bin/env bash
 set -e
 
+PARSE_TIME=$(realpath "$(dirname "$0")/parse_time.sh")
 current_dir=$(pwd)
 base_path="$current_dir/execution_success"
 
@@ -53,23 +54,34 @@ for dir in ${tests_to_profile[@]}; do
     fi
 
     for ((i = 1; i <= NUM_RUNS; i++)); do
-      EXECUTION_TIME=$((time nargo execute --silence-warnings) 2>&1 | grep real | grep -oE '[0-9]+m[0-9]+.[0-9]+s')
-      # Convert to seconds and add to total time
-      TOTAL_TIME=$(echo "$TOTAL_TIME + $(echo $EXECUTION_TIME | sed -E 's/([0-9]+)m([0-9.]+)s/\1 * 60 + \2/' | bc)" | bc)
+      NOIR_LOG=trace NARGO_LOG_DIR=./tmp nargo execute --silence-warnings
     done
 
-    AVG_TIME=$(echo "$TOTAL_TIME / $NUM_RUNS" | bc -l)
-    # Keep only last three decimal points
-    AVG_TIME=$(awk '{printf "%.3f\n", $1}' <<< "$AVG_TIME")
-
-    echo -e " {\n    \"artifact_name\":\"$PACKAGE_NAME\",\n    \"time\":\""$AVG_TIME"s\"" >> $current_dir/execution_report.json
-    
-    if (($ITER == $NUM_ARTIFACTS)); then
-        echo "}" >> $current_dir/execution_report.json
-    else 
-        echo "}, " >> $current_dir/execution_report.json
+    TIMES=($(jq -r '. | select(.target == "nargo::ops::execute" and .fields.message == "close") | .fields."time.busy"' ./tmp/*))
+
+    AVG_TIME=$(awk -v RS=" " -v parse_time="$PARSE_TIME"  '
+        {
+            # Times are formatted annoyingly so we need to parse it.
+            parse_time" "$1 | getline current_time
+            close(parse_time" "$1)
+            sum += current_time;
+            n++;
+        }
+        END {   
+            if (n > 0)
+                printf "%.3f\n", sum / n
+            else
+                printf "%.3f\n", 0
+        }' <<<"${TIMES[@]}")
+
+    jq -rc "{artifact_name: \"$PACKAGE_NAME\", time: \""$AVG_TIME"s\"}" --null-input >> $current_dir/execution_report.json
+
+    if (($ITER != $NUM_ARTIFACTS)); then
+        echo "," >> $current_dir/execution_report.json
     fi
 
+    rm -rf ./tmp
+
     ITER=$(( $ITER + 1 ))
 done
 

diff --git a/test_programs/parse_time.sh b/test_programs/parse_time.sh
@@ -0,0 +1,21 @@
+#!/usr/bin/env bash
+set -e
+
+# This script accepts a string representing the time spent within a span as outputted by `tracing`
+# and standardizes it to be in terms of seconds as `tracing` will report different units depending on the duration.
+
+DIGITS='([0-9]+(\.[0-9]+)?)'
+MICROSECONDS_REGEX=^${DIGITS}µs$
+MILLISECONDS_REGEX=^${DIGITS}ms$
+SECONDS_REGEX=^${DIGITS}s$
+
+if [[ $1 =~ $MICROSECONDS_REGEX ]]; then
+  echo ${BASH_REMATCH[1]} 1000000 | awk '{printf "%.3f\n", $1/$2}'
+elif [[ $1 =~ $MILLISECONDS_REGEX ]]; then
+  echo ${BASH_REMATCH[1]} 1000 | awk '{printf "%.3f\n", $1/$2}'
+elif [[ $1 =~ $SECONDS_REGEX ]]; then
+  echo ${BASH_REMATCH[1]} | awk '{printf "%.3f\n", $1}'
+else 
+  echo "Could not parse time: unrecognized format" 1>&2
+  exit 1
+fi
diff --git a/tooling/nargo/src/lib.rs b/tooling/nargo/src/lib.rs
@@ -172,6 +172,7 @@ pub fn parse_all(file_manager: &FileManager) -> ParsedFiles {
         .collect()
 }
 
+#[tracing::instrument(level = "trace", skip_all)]
 pub fn prepare_package<'file_manager, 'parsed_files>(
     file_manager: &'file_manager FileManager,
     parsed_files: &'parsed_files ParsedFiles,

diff --git a/tooling/nargo/src/ops/check.rs b/tooling/nargo/src/ops/check.rs
@@ -3,6 +3,7 @@ use noirc_driver::{CompiledProgram, ErrorsAndWarnings};
 use noirc_errors::{CustomDiagnostic, FileDiagnostic};
 
 /// Run each function through a circuit simulator to check that they are solvable.
+#[tracing::instrument(level = "trace", skip_all)]
 pub fn check_program(compiled_program: &CompiledProgram) -> Result<(), ErrorsAndWarnings> {
     for (i, circuit) in compiled_program.program.functions.iter().enumerate() {
         let mut simulator = CircuitSimulator::default();

diff --git a/tooling/nargo_cli/Cargo.toml b/tooling/nargo_cli/Cargo.toml
@@ -71,6 +71,7 @@ notify-debouncer-full = "0.3.1"
 termion = "3.0.0"
 
 # Logs
+tracing.workspace = true
 tracing-subscriber.workspace = true
 tracing-appender = "0.2.3"
 clap_complete = "4.5.36"

diff --git a/tooling/nargo_cli/src/cli/fs/program.rs b/tooling/nargo_cli/src/cli/fs/program.rs
@@ -36,6 +36,7 @@ fn save_build_artifact_to_file<P: AsRef<Path>, T: ?Sized + serde::Serialize>(
     circuit_path
 }
 
+#[tracing::instrument(level = "trace", skip_all)]
 pub(crate) fn read_program_from_file<P: AsRef<Path>>(
     circuit_path: P,
 ) -> Result<ProgramArtifact, FilesystemError> {

diff --git a/tooling/nargo_cli/src/cli/mod.rs b/tooling/nargo_cli/src/cli/mod.rs
@@ -116,6 +116,7 @@ enum NargoCommand {
 }
 
 #[cfg(not(feature = "codegen-docs"))]
+#[tracing::instrument(level = "trace")]
 pub(crate) fn start_cli() -> eyre::Result<()> {
     let NargoCli { command, mut config } = NargoCli::parse();
 

diff --git a/tooling/nargo_cli/src/main.rs b/tooling/nargo_cli/src/main.rs
@@ -20,22 +20,7 @@ use tracing_subscriber::{fmt::format::FmtSpan, EnvFilter};
 const PANIC_MESSAGE: &str = "This is a bug. We may have already fixed this in newer versions of Nargo so try searching for similar issues at https://github.com/noir-lang/noir/issues/.\nIf there isn't an open issue for this bug, consider opening one at https://github.com/noir-lang/noir/issues/new?labels=bug&template=bug_report.yml";
 
 fn main() {
-    // Setup tracing
-    if let Ok(log_dir) = env::var("NARGO_LOG_DIR") {
-        let debug_file = rolling::daily(log_dir, "nargo-log");
-        tracing_subscriber::fmt()
-            .with_span_events(FmtSpan::ENTER | FmtSpan::CLOSE)
-            .with_writer(debug_file)
-            .with_ansi(false)
-            .with_env_filter(EnvFilter::from_default_env())
-            .init();
-    } else {
-        tracing_subscriber::fmt()
-            .with_span_events(FmtSpan::ENTER | FmtSpan::CLOSE)
-            .with_ansi(true)
-            .with_env_filter(EnvFilter::from_env("NOIR_LOG"))
-            .init();
-    }
+    setup_tracing();
 
     // Register a panic hook to display more readable panic messages to end-users
     let (panic_hook, _) =
@@ -47,3 +32,16 @@ fn main() {
         std::process::exit(1);
     }
 }
+
+fn setup_tracing() {
+    let subscriber = tracing_subscriber::fmt()
+        .with_span_events(FmtSpan::ENTER | FmtSpan::CLOSE)
+        .with_env_filter(EnvFilter::from_env("NOIR_LOG"));
+
+    if let Ok(log_dir) = env::var("NARGO_LOG_DIR") {
+        let debug_file = rolling::daily(log_dir, "nargo-log");
+        subscriber.with_writer(debug_file).with_ansi(false).json().init();
+    } else {
+        subscriber.with_ansi(true).init();
+    }
+}