feat(halo2_proofs): add logging at each level

- `RUST_LOG=info`: the benchmark log is outputted.
- `RUST_LOG=debug`: logs are outputted including squeezed values.
- `RUST_LOG=trace`: VKeyStr and all Proofs are outputted.

halo2_proofs/Cargo.toml

@@ -81,6 +81,7 @@ gumdrop = "0.8"
 proptest = "1"
 rand_core = { version = "0.6", default-features = false, features = ["getrandom"] }
 rand_xorshift = "0.3"
+env_logger = "0.9.0"
 
 [build-dependencies]
 cxx-build = "1.0"

halo2_proofs/examples/shuffle.rs

@@ -18,6 +18,8 @@ use halo2_proofs::{
         Blake2bRead, Blake2bWrite, Challenge255, TranscriptReadBuffer, TranscriptWriterBuffer,
     },
 };
+
+use env_logger;
 use rand_core::{OsRng, RngCore};
 use std::iter;
 
@@ -324,6 +326,8 @@ fn test_prover<C: CurveAffine, const W: usize, const H: usize>(
 }
 
 fn main() {
+    env_logger::init();
+
     const W: usize = 4;
     const H: usize = 32;
     const K: u32 = 8;

halo2_proofs/examples/simple-example.rs

@@ -306,6 +306,8 @@ fn main() {
     use halo2_proofs::dev::MockProver;
     use halo2curves::pasta::Fp;
 
+    env_logger::init();
+
     // ANCHOR: test-circuit
     // The number of rows in our circuit cannot exceed 2^k. Since our example
     // circuit is very small, we can pick a very small value here.

halo2_proofs/src/bn254.rs

@@ -1,3 +1,4 @@
+use log::trace;
 use std::{
     fmt,
     io::{self, Write},
@@ -271,6 +272,7 @@ pub trait TranscriptWriteState<C: CurveAffine, E: EncodedChallenge<C>>:
 pub struct Blake2bWrite<W: Write, C: CurveAffine, E: EncodedChallenge<C>> {
     state: cxx::UniquePtr<ffi::Blake2bWriter>,
     writer: W,
+    proof_idx: usize,
     _marker: PhantomData<(W, C, E)>,
 }
 
@@ -315,12 +317,24 @@ impl<W: Write, C: CurveAffine> TranscriptWrite<C, Challenge255<C>>
     for Blake2bWrite<W, C, Challenge255<C>>
 {
     fn write_point(&mut self, point: C) -> io::Result<()> {
+        trace!(
+            "[Halo2:WriteToProof] Proof[{}]: {:?}",
+            self.proof_idx,
+            point
+        );
+        self.proof_idx += 1;
         self.common_point(point)?;
         let compressed = point.to_bytes();
         self.writer.write_all(compressed.as_ref())
     }
 
     fn write_scalar(&mut self, scalar: C::Scalar) -> io::Result<()> {
+        trace!(
+            "[Halo2:WriteToProof] Proof[{}]: {:?}",
+            self.proof_idx,
+            scalar
+        );
+        self.proof_idx += 1;
         self.common_scalar(scalar)?;
         let data = scalar.to_repr();
         self.writer.write_all(data.as_ref())
@@ -343,6 +357,7 @@ impl<W: Write, C: CurveAffine> TranscriptWriterBuffer<W, C, Challenge255<C>>
         Blake2bWrite {
             state: ffi::new_blake2b_writer(),
             writer: writer,
+            proof_idx: 0,
             _marker: PhantomData,
         }
     }
@@ -357,6 +372,7 @@ impl<W: Write, C: CurveAffine> TranscriptWriterBuffer<W, C, Challenge255<C>>
 pub struct PoseidonWrite<W: Write, C: CurveAffine, E: EncodedChallenge<C>> {
     state: cxx::UniquePtr<ffi::PoseidonWriter>,
     writer: W,
+    proof_idx: usize,
     _marker: PhantomData<(W, C, E)>,
 }
 
@@ -411,12 +427,22 @@ impl<W: Write, C: CurveAffine> TranscriptWrite<C, Challenge255<C>>
     for PoseidonWrite<W, C, Challenge255<C>>
 {
     fn write_point(&mut self, point: C) -> io::Result<()> {
+        trace!(
+            "[Halo2:WriteToProof] Proof[{}]: {:?}",
+            self.proof_idx,
+            point
+        );
         self.common_point(point)?;
         let compressed = point.to_bytes();
         self.writer.write_all(compressed.as_ref())
     }
 
     fn write_scalar(&mut self, scalar: C::Scalar) -> io::Result<()> {
+        trace!(
+            "[Halo2:WriteToProof] Proof[{}]: {:?}",
+            self.proof_idx,
+            scalar
+        );
         self.common_scalar(scalar)?;
         let data = scalar.to_repr();
         self.writer.write_all(data.as_ref())
@@ -429,6 +455,7 @@ impl<W: Write, C: CurveAffine, E: EncodedChallenge<C>> PoseidonWrite<W, C, E> {
         PoseidonWrite {
             state: ffi::new_poseidon_writer(),
             writer,
+            proof_idx: 0,
             _marker: PhantomData,
         }
     }
@@ -452,6 +479,7 @@ impl<W: Write, C: CurveAffine> TranscriptWriteState<C, Challenge255<C>>
 pub struct Sha256Write<W: Write, C: CurveAffine, E: EncodedChallenge<C>> {
     state: cxx::UniquePtr<ffi::Sha256Writer>,
     writer: W,
+    proof_idx: usize,
     _marker: PhantomData<(W, C, E)>,
 }
 
@@ -513,6 +541,11 @@ impl<W: Write, C: CurveAffine> TranscriptWrite<C, Challenge255<C>>
     for Sha256Write<W, C, Challenge255<C>>
 {
     fn write_point(&mut self, point: C) -> io::Result<()> {
+        trace!(
+            "[Halo2:WriteToProof] Proof[{}]: {:?}",
+            self.proof_idx,
+            point
+        );
         self.common_point(point)?;
 
         let coords = point.coordinates();
@@ -531,6 +564,11 @@ impl<W: Write, C: CurveAffine> TranscriptWrite<C, Challenge255<C>>
     }
 
     fn write_scalar(&mut self, scalar: C::Scalar) -> io::Result<()> {
+        trace!(
+            "[Halo2:WriteToProof] Proof[{}]: {:?}",
+            self.proof_idx,
+            scalar
+        );
         self.common_scalar(scalar)?;
         let data = scalar.to_repr();
 
@@ -552,6 +590,7 @@ impl<W: Write, C: CurveAffine, E: EncodedChallenge<C>> Sha256Write<W, C, E> {
         Sha256Write {
             state: ffi::new_sha256_writer(),
             writer,
+            proof_idx: 0,
             _marker: PhantomData,
         }
     }

halo2_proofs/src/plonk.rs

@@ -44,6 +44,7 @@ pub use prover::*;
 pub use verifier::*;
 
 use evaluation::Evaluator;
+use log::{debug, trace};
 use std::io;
 
 /// This is a verifying key which allows for the verification of proofs for a
@@ -136,7 +137,7 @@ where
 
         let permutation = permutation::VerifyingKey::read(reader, &cs.permutation, format)?;
 
-        /* 
+        /*
         // read selectors
         let selectors: Vec<Vec<bool>> = vec![vec![false; 1 << k]; cs.num_selectors]
             .into_iter()
@@ -204,12 +205,17 @@ impl<C: CurveAffine> VerifyingKey<C> {
             .to_state();
 
         let s = format!("{:?}", vk.pinned());
+        trace!("[Halo2:GenVK:VK] VKeyStr: {}", s);
 
         hasher.update(&(s.len() as u64).to_le_bytes());
         hasher.update(s.as_bytes());
 
         // Hash in final Blake2bState
         vk.transcript_repr = C::Scalar::from_bytes_wide(hasher.finalize().as_array());
+        debug!(
+            "[Halo2:GenVK:TranscriptRepr] TranscriptRepr: {:?}",
+            vk.transcript_repr
+        );
 
         vk
     }

halo2_proofs/src/plonk/lookup/prover.rs

@@ -23,6 +23,7 @@ use std::{
     collections::BTreeMap,
     iter,
     ops::{Mul, MulAssign},
+    time::Instant,
 };
 
 #[derive(Debug)]
@@ -81,6 +82,9 @@ impl<F: FieldExt> Argument<F> {
         challenges: &'a [C::Scalar],
         mut rng: R,
         transcript: &mut T,
+        compr_time_total: &mut f64,
+        perm_time_total: &mut f64,
+        com_time_total: &mut f64,
     ) -> Result<Permuted<C>, Error>
     where
         C: CurveAffine<ScalarExt = F>,
@@ -107,12 +111,15 @@ impl<F: FieldExt> Argument<F> {
             compressed_expression
         };
 
+        let compression_time = Instant::now();
         // Get values of input expressions involved in the lookup and compress them
         let compressed_input_expression = compress_expressions(&self.input_expressions);
 
         // Get values of table expressions involved in the lookup and compress them
         let compressed_table_expression = compress_expressions(&self.table_expressions);
+        *compr_time_total += compression_time.elapsed().as_secs_f64();
 
+        let permutation_time = Instant::now();
         // Permute compressed (InputExpression, TableExpression) pair
         let (permuted_input_expression, permuted_table_expression) = permute_expression_pair(
             pk,
@@ -122,6 +129,7 @@ impl<F: FieldExt> Argument<F> {
             &compressed_input_expression,
             &compressed_table_expression,
         )?;
+        *perm_time_total += permutation_time.elapsed().as_secs_f64();
 
         // Closure to construct commitment to vector of values
         let mut commit_values = |values: &Polynomial<C::Scalar, LagrangeCoeff>| {
@@ -131,6 +139,7 @@ impl<F: FieldExt> Argument<F> {
             (poly, blind, commitment)
         };
 
+        let commit_time = Instant::now();
         // Commit to permuted input expression
         let (permuted_input_poly, permuted_input_blind, permuted_input_commitment) =
             commit_values(&permuted_input_expression);
@@ -144,6 +153,7 @@ impl<F: FieldExt> Argument<F> {
 
         // Hash permuted table commitment
         transcript.write_point(permuted_table_commitment)?;
+        *com_time_total += commit_time.elapsed().as_secs_f64();
 
         Ok(Permuted {
             compressed_input_expression,

halo2_proofs/src/plonk/prover.rs

@@ -1,6 +1,7 @@
 use ff::Field;
 use group::Curve;
 use halo2curves::CurveExt;
+use log::{debug, info};
 use rand_core::RngCore;
 use std::collections::BTreeSet;
 use std::env::var;
@@ -414,8 +415,12 @@ pub fn create_proof<
 
             for (index, phase) in meta.challenge_phase.iter().enumerate() {
                 if current_phase == *phase {
-                    let existing =
-                        challenges.insert(index, *transcript.squeeze_challenge_scalar::<()>());
+                    let challenge = transcript.squeeze_challenge_scalar::<()>();
+                    debug!(
+                        "[Halo2:CreateProof:Challenge] {:#?}: {:?}",
+                        index, *challenge
+                    );
+                    let existing = challenges.insert(index, *challenge);
                     assert!(existing.is_none());
                 }
             }
@@ -429,9 +434,16 @@ pub fn create_proof<
         (advice, challenges)
     };
 
+    let theta_start = Instant::now();
+    info!("[Halo2:CreateProof:Theta] Phase has been started...");
     // Sample theta challenge for keeping lookup columns linearly independent
     let theta: ChallengeTheta<_> = transcript.squeeze_challenge_scalar();
+    debug!("[Halo2:CreateProof:Theta] Theta: {:?}", *theta);
 
+    // The 3 variables are used only for benchmark.
+    let mut compr_time_total = 0 as f64;
+    let mut perm_time_total = 0 as f64;
+    let mut com_time_total = 0 as f64;
     let lookups: Vec<Vec<lookup::prover::Permuted<Scheme::Curve>>> = instance
         .iter()
         .zip(advice.iter())
@@ -453,17 +465,32 @@ pub fn create_proof<
                         &challenges,
                         &mut rng,
                         transcript,
+                        &mut compr_time_total,
+                        &mut perm_time_total,
+                        &mut com_time_total,
                     )
                 })
                 .collect()
         })
         .collect::<Result<Vec<_>, _>>()?;
+    info!(
+        "[Halo2:CreateProof:Theta] CompressionTime: {:#?}, Permutationtime: {:#?}, CommitTime: {:#?}",
+        compr_time_total, perm_time_total, com_time_total
+    );
+    info!(
+        "[Halo2:CreateProof:Theta] ThetaTime: {:#?}",
+        theta_start.elapsed()
+    );
 
+    info!("[Halo2:CreateProof:BetaGamma] Phase has been started...");
+    let beta_gamma_start = Instant::now();
     // Sample beta challenge
     let beta: ChallengeBeta<_> = transcript.squeeze_challenge_scalar();
 
     // Sample gamma challenge
     let gamma: ChallengeGamma<_> = transcript.squeeze_challenge_scalar();
+    debug!("[Halo2:CreateProof:BetaGamma] Beta: {:?}", *beta);
+    debug!("[Halo2:CreateProof:BetaGamma] Gamma: {:?}", *gamma);
 
     // Commit to permutations.
     let permutations: Vec<permutation::prover::Committed<Scheme::Curve>> = instance
@@ -498,9 +525,16 @@ pub fn create_proof<
 
     // Commit to the vanishing argument's random polynomial for blinding h(x_3)
     let vanishing = vanishing::Argument::commit(params, domain, &mut rng, transcript)?;
+    info!(
+        "[Halo2:CreateProof:BetaGamma] BetaGammaTime: {:#?}",
+        beta_gamma_start.elapsed()
+    );
 
+    info!("[Halo2:CreateProof:Y] Phase has been started...");
+    let y_start = Instant::now();
     // Obtain challenge for keeping all separate gates linearly independent
     let y: ChallengeY<_> = transcript.squeeze_challenge_scalar();
+    debug!("[Halo2:CreateProof:Y] Y: {:#?}", *y);
 
     // Calculate the advice polys
     let advice: Vec<AdviceSingle<Scheme::Curve, Coeff>> = advice
@@ -520,7 +554,12 @@ pub fn create_proof<
             },
         )
         .collect();
+    info!(
+        "[Halo2:CreateProof:Y] AdvicesTransformedTime: {:#?}",
+        y_start.elapsed()
+    );
 
+    let y_start = Instant::now();
     // Evaluate the h(X) polynomial
     let h_poly = pk.ev.evaluate_h(
         pk,
@@ -543,8 +582,15 @@ pub fn create_proof<
 
     // Construct the vanishing argument's h(X) commitments
     let vanishing = vanishing.construct(params, domain, h_poly, &mut rng, transcript)?;
+    info!(
+        "[Halo2:CreateProof:Y] BuildingHPolyTime: {:#?}",
+        y_start.elapsed()
+    );
 
+    info!("[Halo2:CreateProof:X] Phase has been started...");
+    let x_start = Instant::now();
     let x: ChallengeX<_> = transcript.squeeze_challenge_scalar();
+    debug!("[Halo2:CreateProof:X] X: {:?}", *x);
     let xn = x.pow(&[params.n() as u64, 0, 0, 0]);
 
     if P::QUERY_INSTANCE {
@@ -672,9 +718,17 @@ pub fn create_proof<
         .chain(pk.permutation.open(x))
         // We query the h(X) polynomial at x
         .chain(vanishing.open(x));
+    info!("[Halo2:CreateProof:X] XTime: {:#?}", x_start.elapsed());
 
+    info!("[Halo2:CreateProof:SHPlonk] Phase has been started...");
+    let sh_start = Instant::now();
     let prover = P::new(params);
-    prover
+    let proof = prover
         .create_proof(rng, transcript, instances)
-        .map_err(|_| Error::ConstraintSystemFailure)
+        .map_err(|_| Error::ConstraintSystemFailure);
+    info!(
+        "[Halo2:CreateProof:SHPlonk] SHPlonkTime: {:#?}",
+        sh_start.elapsed()
+    );
+    proof
 }