Standardize logging with tracing crate + implement micro-benchmarki…

…ng (#627)

* initial commit

* attempt to remove log

* chore: Refactor logging remnants to tracing

- Removed `log` as a workspace dependency and replaced it with `tracing` throughout the project,
- Updated clippy linting configuration in `.cargo/config`.
- Adapted from `log` crate's `info` module to `tracing` crate's `info` module in `lurk-metrics/src/data.rs`

* chore: clippy

* fix: adjust test_basic_functionality

* chore: fmt

* cargo fmt

* remove pretty_env_logger

* deduplicate sha test

* remove dbg!

* add env_filter to restore old behavior

* cargo fmt

* address comments

* clippy

---------

Co-authored-by: François Garillot <francois@garillot.net>

.cargo/config

@@ -8,6 +8,7 @@ xclippy = [
     "-Wclippy::all",
     "-Wclippy::match_same_arms",
     "-Wclippy::cast_lossless",
+    "-Wclippy::dbg_macro",
     "-Wclippy::disallowed_methods",
     "-Wclippy::derive_partial_eq_without_eq",
     "-Wclippy::filter_map_next",

Cargo.toml

@@ -21,6 +21,7 @@ bellpepper-core = { workspace = true }
 bellperson = { workspace = true }
 bincode = { workspace = true }
 blstrs = { workspace = true }
+camino = { workspace = true }
 clap = { workspace = true, features = ["derive"] }
 config = "0.13.3"
 dashmap = "5.5.0"
@@ -29,7 +30,6 @@ generic-array = "0.14.7"
 hex = { version = "0.4.3", features = ["serde"] }
 indexmap = { version = "1.9.3", features = ["rayon"] }
 itertools = "0.9"
-log = { workspace = true }
 lurk-macros = { path = "lurk-macros" }
 lurk-metrics = { path = "lurk-metrics" }
 metrics = { workspace = true }
@@ -45,7 +45,6 @@ once_cell = { workspace = true }
 pairing = { workspace = true }
 pasta_curves = { workspace = true, features = ["repr-c", "serde"] }
 peekmore = "1.3.0"
-pretty_env_logger = { workspace = true }
 rand = { workspace = true }
 rand_core = { version = "0.6.4", default-features = false }
 rand_xorshift = "0.3.0"
@@ -58,7 +57,6 @@ serde_repr = "0.1.14"
 tap = "1.0.1"
 stable_deref_trait = "1.2.0"
 thiserror = { workspace = true }
-camino = { workspace = true }
 abomonation = { workspace = true}
 abomonation_derive = { git = "https://github.com/lurk-lab/abomonation_derive.git" }
 crossbeam = "0.8.2"
@@ -67,6 +65,9 @@ circom-scotia = { git = "https://github.com/lurk-lab/circom-scotia", branch = "d
 sha2 = { version = "0.10.2" }
 reqwest = { version = "0.11.18", features = ["stream", "blocking"] }
 ansi_term = "0.12.1"
+tracing = { workspace = true }
+tracing-texray = { workspace = true }
+tracing-subscriber = { workspace = true, features = ["env-filter"] }
 
 [target.'cfg(not(target_arch = "wasm32"))'.dependencies]
 memmap = { version = "0.5.10", package = "memmap2" }
@@ -83,22 +84,10 @@ rustyline = { version = "11.0", features = ["derive"], default-features = false
 
 [features]
 default = []
-opencl = [
-	"neptune/opencl",
-	"bellperson/opencl",
-	"nova/opencl"
-]
-cuda = [
-	"neptune/cuda",
-	"bellperson/cuda",
-	"nova/cuda"
-]
+opencl = ["neptune/opencl", "bellperson/opencl", "nova/opencl"]
+cuda = ["neptune/cuda", "bellperson/cuda", "nova/cuda"]
 # compile without ISA extensions
-portable = [
-	"blstrs/portable",
-	"pasta-msm/portable",
-	"nova/portable"
-]
+portable = ["blstrs/portable", "pasta-msm/portable", "nova/portable"]
 flamegraph = ["pprof/flamegraph", "pprof/criterion"]
 
 [dev-dependencies]
@@ -136,15 +125,13 @@ bincode = "1.3.3"
 blstrs = { git = "https://github.com/lurk-lab/blstrs", branch = "dev" }
 clap = "4.3.17"
 ff = "0.13"
-log = "0.4.19"
 metrics = "0.21.1"
 neptune = { git = "https://github.com/lurk-lab/neptune", branch = "dev" }
 nova = { git = "https://github.com/lurk-lab/arecibo", branch = "dev", package = "nova-snark" }
 once_cell = "1.18.0"
 pairing = { version = "0.23" }
 pasta_curves = { git = "https://github.com/lurk-lab/pasta_curves", branch = "dev" }
 pasta-msm = { git = "https://github.com/lurk-lab/pasta-msm", branch = "dev" }
-pretty_env_logger = "0.4"
 proptest = "1.2.0"
 proptest-derive = "0.3.0"
 rand = "0.8"
@@ -153,6 +140,9 @@ serde_json = { version = "1.0" }
 tempfile = "3.6.0"
 camino = "1.1.6"
 thiserror = "1.0.44"
+tracing = "0.1.37"
+tracing-texray = "0.2.0"
+tracing-subscriber = "0.3.17"
 
 [[bin]]
 name = "lurk"

benches/fibonacci.rs

@@ -23,6 +23,7 @@ use lurk::{
 };
 
 const PUBLIC_PARAMS_PATH: &str = "/var/tmp/lurk_benches/public_params";
+
 fn fib<F: LurkField>(store: &mut Store<F>, state: Rc<RefCell<State>>, _a: u64) -> Ptr<F> {
     let program = r#"
 (letrec ((next (lambda (a b) (next b (+ a b))))
@@ -109,7 +110,7 @@ fn fibo_prove<M: measurement::Measurement>(
 }
 
 fn fibonacci_prove(c: &mut Criterion) {
-    let _ = dbg!(&*lurk::config::CONFIG);
+    tracing::debug!("{:?}", &*lurk::config::CONFIG);
     let reduction_counts = vec![100, 600, 700, 800, 900];
     let batch_sizes = vec![100, 200];
     let mut group: BenchmarkGroup<'_, _> = c.benchmark_group("Prove");

clutch/Cargo.toml

@@ -11,14 +11,17 @@ repository = "https://github.com/lurk-lab/lurk-rs"
 [dependencies]
 anyhow = { workspace = true }
 blstrs =  { workspace = true }
+camino = { workspace = true }
 clap = { workspace = true }
 fcomm = { path = "../fcomm" }
 ff = "0.13"
 lurk = { path = "../" }
 pasta_curves = { workspace = true, features = ["repr-c", "serde"] }
-pretty_env_logger = "0.4"
 serde = { workspace = true, features = ["derive"] }
-camino = { workspace = true }
+tracing = { workspace = true }
+tracing-texray = { workspace = true }
+tracing-subscriber = { workspace = true }
+
 
 [dev-dependencies]
 assert_cmd = "2.0.12"

clutch/src/main.rs

@@ -6,9 +6,14 @@ use lurk::eval::lang::{Coproc, Lang};
 use lurk::field::LanguageField;
 use lurk::repl::repl_cli;
 use pasta_curves::pallas;
+use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry};
 
 fn main() -> Result<()> {
-    pretty_env_logger::init();
+    let subscriber = Registry::default()
+        // TODO: correctly filter log level with `clap_verbosity_flag`
+        .with(fmt::layer().pretty())
+        .with(EnvFilter::from_default_env());
+    tracing::subscriber::set_global_default(subscriber).unwrap();
 
     let default_field = LanguageField::Pallas;
     let field = if let Ok(lurk_field) = std::env::var("LURK_FIELD") {

examples/circom.rs

@@ -110,7 +110,6 @@ fn main() {
     );
 
     let coproc_expr = format!("{}", sym_str);
-    dbg!(coproc_expr.clone());
 
     let expr = format!("({coproc_expr})");
     let ptr = store.read(&expr).unwrap();

examples/sha256.rs

@@ -11,22 +11,24 @@ use lurk::eval::{empty_sym_env, lang::Lang};
 use lurk::field::LurkField;
 use lurk::proof::{nova::NovaProver, Prover};
 use lurk::ptr::Ptr;
-use lurk::public_parameters::with_public_params;
+use lurk::public_parameters::{public_params, public_params_default_dir};
 use lurk::state::user_sym;
 use lurk::store::Store;
 use lurk_macros::Coproc;
 
-use bellpepper::gadgets::multipack::pack_bits;
-use bellpepper::gadgets::sha256::sha256;
-use bellpepper_core::boolean::{AllocatedBit, Boolean};
-use bellpepper_core::num::AllocatedNum;
-use bellpepper_core::{ConstraintSystem, SynthesisError};
+use bellperson::gadgets::boolean::{AllocatedBit, Boolean};
+use bellperson::gadgets::multipack::pack_bits;
+use bellperson::gadgets::num::AllocatedNum;
+use bellperson::gadgets::sha256::sha256;
+use bellperson::{ConstraintSystem, SynthesisError};
 
 use pasta_curves::pallas::Scalar as Fr;
 use serde::{Deserialize, Serialize};
 use sha2::{Digest, Sha256};
+use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry};
+use tracing_texray::TeXRayLayer;
 
-const REDUCTION_COUNT: usize = 100;
+const REDUCTION_COUNT: usize = 10;
 
 #[derive(Clone, Debug, Serialize, Deserialize)]
 pub(crate) struct Sha256Coprocessor<F: LurkField> {
@@ -152,8 +154,17 @@ enum Sha256Coproc<F: LurkField> {
 
 /// Run the example in this file with
 /// `cargo run --release --example sha256 1 f5a5fd42d16a20302798ef6ed309979b43003d2320d9f0e8ea9831a92759fb4b false`
+///
+/// To see the `texray` outputs, run with
+/// `
+/// `RUST_LOG=info cargo run --release --example sha256 1 f5a5fd42d16a20302798ef6ed309979b43003d2320d9f0e8ea9831a92759fb4b false`
 fn main() {
-    pretty_env_logger::init();
+    let subscriber = Registry::default()
+        .with(fmt::layer().pretty())
+        .with(EnvFilter::from_default_env())
+        .with(TeXRayLayer::new());
+    tracing::subscriber::set_global_default(subscriber).unwrap();
+
     let args: Vec<String> = env::args().collect();
 
     let num_of_64_bytes = args[1].parse::<usize>().unwrap();
@@ -177,48 +188,55 @@ fn main() {
         store,
         vec![(cproc_sym, Sha256Coprocessor::new(input_size, u).into())],
     );
-    let lang_rc = Arc::new(lang.clone());
 
     let cproc_call = store.list(&[cproc_sym_ptr]);
 
-    let nova_prover = NovaProver::<Fr, Sha256Coproc<Fr>>::new(REDUCTION_COUNT, lang);
+    let nova_prover = NovaProver::<Fr, Sha256Coproc<Fr>>::new(REDUCTION_COUNT, lang.clone());
+    let lang_rc = Arc::new(lang);
 
-    println!("Setting up public parameters (rc = {REDUCTION_COUNT})...");
+    println!("Setting up public parameters...");
 
     let pp_start = Instant::now();
+    let pp = public_params::<_, Sha256Coproc<Fr>>(
+        REDUCTION_COUNT,
+        true,
+        lang_rc.clone(),
+        &public_params_default_dir(),
+    )
+    .unwrap();
+    let pp_end = pp_start.elapsed();
 
-    // see the documentation on `with_public_params`
-    with_public_params(REDUCTION_COUNT, lang_rc.clone(), |pp| {
-        let pp_end = pp_start.elapsed();
-        println!("Public parameters took {:?}", pp_end);
+    println!("Public parameters took {:?}", pp_end);
 
-        if setup_only {
-            return;
-        }
+    if setup_only {
+        return;
+    }
+
+    println!("Beginning proof step...");
 
-        println!("Beginning proof step...");
-        let proof_start = Instant::now();
-        let (proof, z0, zi, num_steps) = nova_prover
-            .evaluate_and_prove(pp, cproc_call, empty_sym_env(store), store, 10000, lang_rc)
-            .unwrap();
-        let proof_end = proof_start.elapsed();
+    let proof_start = Instant::now();
+    let (proof, z0, zi, num_steps) = tracing_texray::examine(tracing::info_span!("prog_start"))
+        .in_scope(|| {
+            nova_prover
+                .evaluate_and_prove(&pp, cproc_call, empty_sym_env(store), store, 10000, lang_rc)
+                .unwrap()
+        });
+    let proof_end = proof_start.elapsed();
 
-        println!("Proofs took {:?}", proof_end);
+    println!("Proofs took {:?}", proof_end);
 
-        println!("Verifying proof...");
+    println!("Verifying proof...");
 
-        let verify_start = Instant::now();
-        let res = proof.verify(pp, num_steps, &z0, &zi).unwrap();
-        let verify_end = verify_start.elapsed();
+    let verify_start = Instant::now();
+    let res = proof.verify(&pp, num_steps, &z0, &zi).unwrap();
+    let verify_end = verify_start.elapsed();
 
-        println!("Verify took {:?}", verify_end);
+    println!("Verify took {:?}", verify_end);
 
-        if res {
-            println!(
-                "Congratulations! You proved and verified a SHA256 hash calculation in {:?} time!",
-                pp_end + proof_end + verify_end
-            );
-        }
-    })
-    .unwrap();
+    if res {
+        println!(
+            "Congratulations! You proved and verified a SHA256 hash calculation in {:?} time!",
+            pp_end + proof_end + verify_end
+        );
+    }
 }

fcomm/Cargo.toml

@@ -18,25 +18,26 @@ base64 = { workspace = true }
 bellpepper-core = { workspace = true }
 bincode = { workspace = true }
 blstrs = { workspace = true }
+camino = { workspace = true }
 clap = { workspace = true, features = ["derive"] }
 clap-verbosity-flag = "2.0"
 ff = { workspace = true }
 hex = { version = "0.4.3", features = ["serde"] }
-log = { workspace = true }
 lurk = { path = "../", package = "lurk" }
 lurk-macros = { path = "../lurk-macros" }
 nova = { workspace = true }
 once_cell = { workspace = true }
 pairing = { workspace = true }
 pasta_curves = { workspace = true, features = ["repr-c", "serde"] }
-pretty_env_logger = { workspace = true }
 proptest = { workspace = true }
 proptest-derive = { workspace = true }
 rand = { workspace = true }
 serde = { workspace = true, features = ["derive"] }
 serde_json = { workspace = true }
 thiserror = { workspace = true }
-camino = { workspace = true }
+tracing = { workspace = true }
+tracing-texray = { workspace = true }
+tracing-subscriber = { workspace = true, features = ["env-filter"] }
 
 [dev-dependencies]
 assert_cmd = "2.0.12"

fcomm/src/bin/fcomm.rs

@@ -1,5 +1,4 @@
 use abomonation::Abomonation;
-use log::info;
 use lurk::lurk_sym_ptr;
 use lurk::proof::nova::{CurveCycleEquipped, G1, G2};
 use nova::traits::Group;
@@ -9,6 +8,8 @@ use std::fs::read_to_string;
 use std::io;
 use std::path::{Path, PathBuf};
 use std::sync::Arc;
+use tracing::info;
+use tracing_subscriber::{fmt, prelude::*, EnvFilter, Registry};
 
 use hex::FromHex;
 use serde::de::DeserializeOwned;
@@ -520,9 +521,11 @@ where
 fn main() {
     let cli = Cli::parse();
 
-    pretty_env_logger::formatted_builder()
-        .filter_level(cli.verbose.log_level_filter())
-        .init();
+    let subscriber = Registry::default()
+        // TODO: correctly filter log level with `clap_verbosity_flag`
+        .with(fmt::layer().pretty())
+        .with(EnvFilter::from_default_env());
+    tracing::subscriber::set_global_default(subscriber).unwrap();
 
     // TODO: make this properly configurable, e.g. allowing coprocessors
     let lang = Lang::new();

fcomm/src/lib.rs

@@ -1,8 +1,8 @@
 use ::nova::traits::Group;
 use abomonation::Abomonation;
-use log::info;
 use std::convert::TryFrom;
 use std::sync::Arc;
+use tracing::info;
 
 #[cfg(not(target_arch = "wasm32"))]
 use proptest::prelude::*;

lurk-metrics/Cargo.toml

@@ -10,10 +10,9 @@ repository = "https://github.com/lurk-lab/lurk-rs"
 [dependencies]
 metrics = { workspace = true }
 once_cell = { workspace = true }
-log = { workspace = true }
 hdrhistogram = { version = "7.5.2", default-features = false }
-
+tracing = { workspace = true }
 
 [dev-dependencies]
-expect-test = "1"
-testing_logger = "0.1.1"
+regex = { version = "1.9.4", features = ["unicode-case"] }
+tracing-test = { version = "0.2", features = ["no-env-filter"] }

lurk-metrics/src/data.rs

@@ -1,8 +1,8 @@
 use std::collections::HashMap;
 use std::fmt::{self, Display, Formatter};
 
-use log::info;
 use metrics::Key;
+use tracing::info;
 
 pub const METRICS_TARGET_NAME: &str = "lurk::metrics";