From 06ba20c1b7a72fe42801616512f61e0b454e0652 Mon Sep 17 00:00:00 2001 From: Tom French <15848336+TomAFrench@users.noreply.github.com> Date: Sat, 4 Jan 2025 00:01:39 +0000 Subject: [PATCH] chore: use logs for benchmarking (#6911) Co-authored-by: Maxim Vezenov --- .github/workflows/reports.yml | 19 ++++++------- Cargo.lock | 14 +++++++++ Cargo.toml | 2 +- test_programs/compilation_report.sh | 38 ++++++++++++++++--------- test_programs/execution_report.sh | 38 ++++++++++++++++--------- test_programs/parse_time.sh | 21 ++++++++++++++ tooling/nargo/src/lib.rs | 1 + tooling/nargo/src/ops/check.rs | 1 + tooling/nargo_cli/Cargo.toml | 1 + tooling/nargo_cli/src/cli/fs/program.rs | 1 + tooling/nargo_cli/src/cli/mod.rs | 1 + tooling/nargo_cli/src/main.rs | 30 +++++++++---------- 12 files changed, 114 insertions(+), 53 deletions(-) create mode 100755 test_programs/parse_time.sh diff --git a/.github/workflows/reports.yml b/.github/workflows/reports.yml index 803d4e1edfb..9ab66c4c16e 100644 --- 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,7 +346,9 @@ 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 @@ -360,7 +356,9 @@ 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 1 - name: Generate execution report without averages @@ -368,6 +366,7 @@ jobs: 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 @@ -375,6 +374,7 @@ jobs: 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 index 5bcf2cbf662..eb6d4327faf 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3044,6 +3044,7 @@ dependencies = [ "tokio-util", "toml", "tower", + "tracing", "tracing-appender", "tracing-subscriber", ] @@ -5297,6 +5298,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.18" @@ -5307,12 +5318,15 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 9d061b9800d..73937667c14 100644 --- 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 index 360eecd2849..df15ef00008 100755 --- 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 index 073871e60f8..b929c367f7d 100755 --- 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 new file mode 100755 index 00000000000..2ff5c259cd2 --- /dev/null +++ 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 \ No newline at end of file diff --git a/tooling/nargo/src/lib.rs b/tooling/nargo/src/lib.rs index de032ca55ae..30f25356e41 100644 --- 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 index 707353ccdad..f22def8bd91 100644 --- 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 index 1e41cea2d81..742c397a0d3 100644 --- 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 index 0b30d23db2b..87783e4573a 100644 --- 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, T: ?Sized + serde::Serialize>( circuit_path } +#[tracing::instrument(level = "trace", skip_all)] pub(crate) fn read_program_from_file>( circuit_path: P, ) -> Result { diff --git a/tooling/nargo_cli/src/cli/mod.rs b/tooling/nargo_cli/src/cli/mod.rs index cc72092daa1..43e3de9c6d0 100644 --- 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 index a407d467ced..3ea167b7ffa 100644 --- 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(); + } +}