Powers of Tau Tracing (#43)

* feat(cli/groth16-utils): add tracing

* feat(powersoftau): add tracing to contribute

* feat(powersoftau): add tracing to verify

bls-snark-setup/src/cli/mod.rs

@@ -1,7 +1,7 @@
 use gumdrop::Options;
 
-mod new;
 pub use new::{empty_circuit, new, NewOpts};
+mod new;
 
 mod contribute;
 pub use contribute::{contribute, ContributeOpts};

powersoftau/Cargo.toml

@@ -23,6 +23,8 @@ rayon = "1.3.0"
 # used for the CLIs
 gumdrop = "0.7.0"
 hex-literal = "0.1.4"
+tracing = "0.1.13"
+tracing-subscriber = "0.2.3"
 
 [dev-dependencies]
 criterion = "0.3"
@@ -31,4 +33,4 @@ test-helpers = { path = "../test-helpers" }
 
 [[bench]]
 name = "accumulator"
-harness = false
+harness = false

powersoftau/src/bin/powersoftau.rs

@@ -7,12 +7,21 @@ use snark_utils::{beacon_randomness, get_rng, user_system_randomness};
 
 use std::process;
 use std::time::Instant;
+use tracing_subscriber::{
+    filter::EnvFilter,
+    fmt::{time::ChronoUtc, Subscriber},
+};
 use zexe_algebra::{Bls12_377, Bls12_381, PairingEngine as Engine, SW6};
 
 #[macro_use]
 extern crate hex_literal;
 
 fn main() {
+    Subscriber::builder()
+        .with_timer(ChronoUtc::rfc3339())
+        .with_env_filter(EnvFilter::from_default_env())
+        .init();
+
     let opts: PowersOfTauOpts = PowersOfTauOpts::parse_args_default_or_exit();
 
     match opts.curve_kind {

powersoftau/src/bin/prepare_phase2.rs

@@ -12,6 +12,10 @@ use zexe_algebra::{Bls12_377, Bls12_381, PairingEngine, SW6};
 use std::fs::OpenOptions;
 
 use memmap::*;
+use tracing_subscriber::{
+    filter::EnvFilter,
+    fmt::{time::ChronoUtc, Subscriber},
+};
 
 #[derive(Debug, Options, Clone)]
 struct PreparePhase2Opts {
@@ -42,6 +46,11 @@ struct PreparePhase2Opts {
 }
 
 fn main() -> Result<()> {
+    Subscriber::builder()
+        .with_timer(ChronoUtc::rfc3339())
+        .with_env_filter(EnvFilter::from_default_env())
+        .init();
+
     let opts = PreparePhase2Opts::parse_args_default_or_exit();
 
     let now = Instant::now();

powersoftau/src/raw/raw_accumulator.rs

@@ -9,6 +9,7 @@ use snark_utils::{BatchDeserializer, BatchSerializer, Deserializer, Serializer};
 use zexe_algebra::{AffineCurve, PairingEngine, ProjectiveCurve, Zero};
 
 use itertools::{Itertools, MinMaxResult};
+use tracing::{debug, info, span, trace, Level};
 
 /// Mutable buffer, compression
 type Output<'a> = (&'a mut [u8], UseCompression);
@@ -72,6 +73,8 @@ pub fn init<'a, E: PairingEngine>(
     parameters: &'a CeremonyParams<E>,
     compressed: UseCompression,
 ) {
+    let span = span!(Level::TRACE, "initialize");
+    let _enter = span.enter();
     let (tau_g1, tau_g2, alpha_g1, beta_g1, beta_g2) = split_mut(output, parameters, compressed);
     let g1_one = &E::G1Affine::prime_subgroup_generator();
     let g2_one = &E::G2Affine::prime_subgroup_generator();
@@ -102,6 +105,7 @@ pub fn init<'a, E: PairingEngine>(
                 .expect("could not initialize the Beta G2 element")
         });
     });
+    info!("Accumulator has been initialized");
 }
 
 /// Given a public key and the accumulator's digest, it hashes each G1 element
@@ -172,6 +176,11 @@ pub fn verify<E: PairingEngine>(
     digest: &[u8],
     parameters: &CeremonyParams<E>,
 ) -> Result<()> {
+    let span = span!(Level::TRACE, "verify");
+    let _enter = span.enter();
+
+    info!("starting...");
+
     // Ensure the key ratios are correctly produced
     let [tau_g2_s, alpha_g2_s, beta_g2_s] = compute_g2_s_key(&key, &digest)?;
     // put in tuple form for convenience
@@ -187,6 +196,7 @@ pub fn verify<E: PairingEngine>(
     for (a, b, err) in check_ratios {
         check_same_ratio::<E>(a, b, err)?;
     }
+    debug!("key ratios were correctly produced");
 
     // Split the buffers
     // todo: check that in_tau_g2 is actually not required
@@ -240,12 +250,19 @@ pub fn verify<E: PairingEngine>(
         (g1_check, g2_check)
     };
 
+    debug!("initial elements were computed correctly");
+
     // preallocate 2 vectors per batch
     // Ensure that the pairs are created correctly (we do this in chunks!)
     // load `batch_size` chunks on each iteration and perform the transformation
     iter_chunk(&parameters, |start, end| {
+        debug!("verifying chunk from {} to {}", start, end);
+        let span = span!(Level::TRACE, "batch", start, end);
+        let _enter = span.enter();
         rayon::scope(|t| {
+            let _enter = span.enter();
             t.spawn(|_| {
+                let _enter = span.enter();
                 let mut g1 = vec![E::G1Affine::zero(); parameters.batch_size];
                 check_power_ratios::<E>(
                     (tau_g1, compressed_output),
@@ -254,6 +271,7 @@ pub fn verify<E: PairingEngine>(
                     &g2_check,
                 )
                 .expect("could not check ratios for Tau G1");
+                trace!("Tau G1 verification successful");
             });
 
             if start < parameters.powers_length {
@@ -267,7 +285,9 @@ pub fn verify<E: PairingEngine>(
                 };
 
                 rayon::scope(|t| {
+                    let _enter = span.enter();
                     t.spawn(|_| {
+                        let _enter = span.enter();
                         let mut g2 = vec![E::G2Affine::zero(); parameters.batch_size];
                         check_power_ratios_g2::<E>(
                             (tau_g2, compressed_output),
@@ -276,9 +296,11 @@ pub fn verify<E: PairingEngine>(
                             &g1_check,
                         )
                         .expect("could not check ratios for Tau G2");
+                        trace!("Tau G2 verification successful");
                     });
 
                     t.spawn(|_| {
+                        let _enter = span.enter();
                         let mut g1 = vec![E::G1Affine::zero(); parameters.batch_size];
                         check_power_ratios::<E>(
                             (alpha_g1, compressed_output),
@@ -287,9 +309,11 @@ pub fn verify<E: PairingEngine>(
                             &g2_check,
                         )
                         .expect("could not check ratios for Alpha G1");
+                        trace!("Alpha G1 verification successful");
                     });
 
                     t.spawn(|_| {
+                        let _enter = span.enter();
                         let mut g1 = vec![E::G1Affine::zero(); parameters.batch_size];
                         check_power_ratios::<E>(
                             (beta_g1, compressed_output),
@@ -298,13 +322,19 @@ pub fn verify<E: PairingEngine>(
                             &g2_check,
                         )
                         .expect("could not check ratios for Beta G1");
+                        trace!("Beta G1 verification successful");
                     });
                 });
             }
         });
 
+        debug!("chunk verification successful");
+
         Ok(())
-    })
+    })?;
+
+    info!("verification complete");
+    Ok(())
 }
 
 /// Serializes all the provided elements to the output buffer
@@ -421,6 +451,11 @@ pub fn contribute<E: PairingEngine>(
     key: &PrivateKey<E>,
     parameters: &CeremonyParams<E>,
 ) -> Result<()> {
+    let span = span!(Level::TRACE, "contribute");
+    let _enter = span.enter();
+
+    info!("starting...");
+
     let (input, compressed_input) = (input.0, input.1);
     let (output, compressed_output) = (output.0, output.1);
     // get an immutable reference to the input chunks
@@ -443,24 +478,33 @@ pub fn contribute<E: PairingEngine>(
 
     // load `batch_size` chunks on each iteration and perform the transformation
     iter_chunk(&parameters, |start, end| {
+        debug!("contributing to chunk from {} to {}", start, end);
+        let span = span!(Level::TRACE, "batch", start, end);
+        let _enter = span.enter();
         rayon::scope(|t| {
+            let _enter = span.enter();
             t.spawn(|_| {
+                let _enter = span.enter();
                 // generate powers from `start` to `end` (e.g. [0,4) then [4, 8) etc.)
                 let powers = generate_powers_of_tau::<E>(&key.tau, start, end);
+                trace!("generated powers of tau");
 
                 // raise each element from the input buffer to the powers of tau
                 // and write the updated value (without allocating) to the
                 // output buffer
                 rayon::scope(|t| {
+                    let _enter = span.enter();
                     t.spawn(|_| {
+                        let _enter = span.enter();
                         apply_powers::<E::G1Affine>(
                             (tau_g1, compressed_output),
                             (in_tau_g1, compressed_input),
                             (start, end),
                             &powers,
                             None,
                         )
-                        .expect("could not apply powers of tau to the TauG1 elements")
+                        .expect("could not apply powers of tau to the TauG1 elements");
+                        trace!("applied powers to Tau G1 elements");
                     });
                     if start < parameters.powers_length {
                         // if the `end` would be out of bounds, then just process until
@@ -473,44 +517,56 @@ pub fn contribute<E: PairingEngine>(
                         };
 
                         rayon::scope(|t| {
+                            let _enter = span.enter();
                             t.spawn(|_| {
+                                let _enter = span.enter();
                                 apply_powers::<E::G2Affine>(
                                     (tau_g2, compressed_output),
                                     (in_tau_g2, compressed_input),
                                     (start, end),
                                     &powers,
                                     None,
                                 )
-                                .expect("could not apply powers of tau to the TauG2 elements")
+                                .expect("could not apply powers of tau to the TauG2 elements");
+                                trace!("applied powers to Tau G2 elements");
                             });
                             t.spawn(|_| {
+                                let _enter = span.enter();
                                 apply_powers::<E::G1Affine>(
                                     (alpha_g1, compressed_output),
                                     (in_alpha_g1, compressed_input),
                                     (start, end),
                                     &powers,
                                     Some(&key.alpha),
                                 )
-                                .expect("could not apply powers of tau to the AlphaG1 elements")
+                                .expect("could not apply powers of tau to the AlphaG1 elements");
+                                trace!("applied powers to Alpha G1 elements");
                             });
                             t.spawn(|_| {
+                                let _enter = span.enter();
                                 apply_powers::<E::G1Affine>(
                                     (beta_g1, compressed_output),
                                     (in_beta_g1, compressed_input),
                                     (start, end),
                                     &powers,
                                     Some(&key.beta),
                                 )
-                                .expect("could not apply powers of tau to the BetaG1 elements")
+                                .expect("could not apply powers of tau to the BetaG1 elements");
+                                trace!("applied powers to Beta G1 elements");
                             });
                         });
                     }
                 });
             });
         });
 
+        debug!("chunk contribution successful");
         Ok(())
-    })
+    })?;
+
+    info!("done");
+
+    Ok(())
 }
 
 /// Takes a compressed input buffer and decompresses it

snark-utils/Cargo.toml

@@ -21,6 +21,7 @@ crossbeam = "0.7.3"
 num_cpus = "1.12.0"
 blake2 = "0.8.1"
 zexe_r1cs_core = { package = "r1cs-core", git = "https://github.com/scipr-lab/zexe", version = "0.1.0" }
+tracing = "0.1.13"
 
 [dev-dependencies]
 criterion = "0.3.1"
@@ -37,4 +38,4 @@ harness = false
 
 [features]
 default = []
-parallel = ["rayon", "zexe_algebra/parallel", "zexe_fft/parallel"]
+parallel = ["rayon", "zexe_algebra/parallel", "zexe_fft/parallel"]