From 9081ae7337e8f0c6554f03c2cd49b367f4968835 Mon Sep 17 00:00:00 2001 From: Daniel Lubarov Date: Mon, 26 Jul 2021 16:21:14 -0700 Subject: [PATCH] Reduce noise in FRI logging (#129) * Reduce noise in FRI logging Previously, all logs related to gate counts were at the `Debug` log level. This PR gives us more flexibility to adjust the log levels of particular scopes. In particular, our circuit checks 40 FRI queries, and we log a bunch of steps for each query, creating a lot of noise. With this change, we log just a single FRI query at the `Debug` level, and demote others to the `Trace` level. With `RUST_LOG=debug`, our logs now look like ``` [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] 17631 gates to root [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | 8 gates to observe proof and generates challenges [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | 4150 gates to evaluate the vanishing polynomial at our challenge point, zeta. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | 3184 gates to evaluate gate constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 227 gates to evaluate InterpolationGate { num_points: 4, _phantom: PhantomData } constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 867 gates to evaluate GMiMCGate { ... } constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 576 gates to evaluate BaseSumGate { num_limbs: 63 } + Base: 2 constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 78 gates to evaluate ArithmeticExtensionGate constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 288 gates to evaluate BaseSumGate { num_limbs: 31 } + Base: 2 constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 115 gates to evaluate InsertionGate { vec_size: 3, _phantom: PhantomData } constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 26 gates to evaluate BaseSumGate { num_limbs: 2 } + Base: 2 constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 633 gates to evaluate ReducingGate { num_coeffs: 21 } constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 4 gates to evaluate ConstantGate constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 11 gates to evaluate PublicInputGate constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 2 gates to evaluate NoopGate constraints [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | 16 gates to check vanishing and quotient polynomials. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | 13336 gates to verify FRI proof [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | 6 gates to recover the random betas used in the FRI reductions. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | 4 gates to check PoW [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | 104 gates to precompute reduced evaluations [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | 330 gates to verify one (of 40) query rounds [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 95 gates to check FRI initial proof [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | | 22 gates to verify 0'th initial Merkle proof [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | | 33 gates to verify 1'th initial Merkle proof [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | | 20 gates to verify 2'th initial Merkle proof [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | | 20 gates to verify 3'th initial Merkle proof [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 34 gates to compute x from its index [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 32 gates to combine initial oracles [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 17 gates to verify FRI round Merkle proof. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 10 gates to infer evaluation using interpolation [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 15 gates to verify FRI round Merkle proof. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 10 gates to infer evaluation using interpolation [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 13 gates to verify FRI round Merkle proof. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 10 gates to infer evaluation using interpolation [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 11 gates to verify FRI round Merkle proof. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 10 gates to infer evaluation using interpolation [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 9 gates to verify FRI round Merkle proof. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 10 gates to infer evaluation using interpolation [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 7 gates to verify FRI round Merkle proof. [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 10 gates to infer final evaluation using interpolation [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | | 8 gates to evaluate final polynomial ``` This bit corresponds to the single FRI query being shown: ``` [2021-07-26T21:07:45Z DEBUG plonky2::context_tree] | | 330 gates to verify one (of 40) query rounds ``` * Minor cleanup * Address feedback --- src/circuit_builder.rs | 4 ++-- src/context_tree.rs | 28 +++++++++++++++++----- src/fri/recursive_verifier.rs | 45 +++++++++++++++++++++++------------ src/polynomial/commitment.rs | 4 ++-- src/recursive_verifier.rs | 8 +++---- src/vanishing_poly.rs | 6 ++--- 6 files changed, 63 insertions(+), 32 deletions(-) diff --git a/src/circuit_builder.rs b/src/circuit_builder.rs index 5d286a46..57f5b7ac 100644 --- a/src/circuit_builder.rs +++ b/src/circuit_builder.rs @@ -301,8 +301,8 @@ impl, const D: usize> CircuitBuilder { self.targets_to_constants.get(&target).cloned() } - pub fn push_context(&mut self, ctx: &str) { - self.context_log.push(ctx, self.num_gates()); + pub fn push_context(&mut self, level: log::Level, ctx: &str) { + self.context_log.push(ctx, level, self.num_gates()); } pub fn pop_context(&mut self) { diff --git a/src/context_tree.rs b/src/context_tree.rs index 6482f71d..7ec5214c 100644 --- a/src/context_tree.rs +++ b/src/context_tree.rs @@ -1,9 +1,11 @@ -use log::debug; +use log::{log, Level}; /// The hierarchy of contexts, and the gate count contributed by each one. Useful for debugging. pub(crate) struct ContextTree { /// The name of this scope. name: String, + /// The level at which to log this scope and its children. + level: log::Level, /// The gate count when this scope was created. enter_gate_count: usize, /// The gate count when this scope was destroyed, or None if it has not yet been destroyed. @@ -16,6 +18,7 @@ impl ContextTree { pub fn new() -> Self { Self { name: "root".to_string(), + level: Level::Debug, enter_gate_count: 0, exit_gate_count: None, children: vec![], @@ -43,18 +46,22 @@ impl ContextTree { } } - pub fn push(&mut self, ctx: &str, current_gate_count: usize) { + pub fn push(&mut self, ctx: &str, mut level: log::Level, current_gate_count: usize) { assert!(self.is_open()); + // We don't want a scope's log level to be stronger than that of its parent. + level = level.max(self.level); + if let Some(last_child) = self.children.last_mut() { if last_child.is_open() { - last_child.push(ctx, current_gate_count); + last_child.push(ctx, level, current_gate_count); return; } } self.children.push(ContextTree { name: ctx.to_string(), + level, enter_gate_count: current_gate_count, exit_gate_count: None, children: vec![], @@ -83,6 +90,7 @@ impl ContextTree { pub fn filter(&self, current_gate_count: usize, min_delta: usize) -> Self { Self { name: self.name.clone(), + level: self.level, enter_gate_count: self.enter_gate_count, exit_gate_count: self.exit_gate_count, children: self @@ -100,7 +108,8 @@ impl ContextTree { fn print_helper(&self, current_gate_count: usize, depth: usize) { let prefix = "| ".repeat(depth); - debug!( + log!( + self.level, "{}{} gates to {}", prefix, self.gate_count_delta(current_gate_count), @@ -114,9 +123,16 @@ impl ContextTree { /// Creates a named scope; useful for debugging. #[macro_export] -macro_rules! context { +macro_rules! with_context { + ($builder:expr, $level:expr, $ctx:expr, $exp:expr) => {{ + $builder.push_context($level, $ctx); + let res = $exp; + $builder.pop_context(); + res + }}; + // If no context is specified, default to Debug. ($builder:expr, $ctx:expr, $exp:expr) => {{ - $builder.push_context($ctx); + $builder.push_context(log::Level::Debug, $ctx); let res = $exp; $builder.pop_context(); res diff --git a/src/fri/recursive_verifier.rs b/src/fri/recursive_verifier.rs index ed4d3750..0c256ae8 100644 --- a/src/fri/recursive_verifier.rs +++ b/src/fri/recursive_verifier.rs @@ -1,6 +1,5 @@ use crate::circuit_builder::CircuitBuilder; use crate::circuit_data::CommonCircuitData; -use crate::context; use crate::field::extension_field::target::{flatten_target, ExtensionTarget}; use crate::field::extension_field::Extendable; use crate::field::field::Field; @@ -13,6 +12,7 @@ use crate::proof::{ use crate::target::Target; use crate::util::reducing::ReducingFactorTarget; use crate::util::{log2_strict, reverse_index_bits_in_place}; +use crate::with_context; impl, const D: usize> CircuitBuilder { /// Computes P'(x^arity) from {P(x*g^i)}_(i=0..arity), where g is a `arity`-th root of unity @@ -93,7 +93,7 @@ impl, const D: usize> CircuitBuilder { // Size of the LDE domain. let n = proof.final_poly.len() << (total_arities + config.rate_bits); - let betas = context!( + let betas = with_context!( self, "recover the random betas used in the FRI reductions.", proof @@ -107,7 +107,7 @@ impl, const D: usize> CircuitBuilder { ); challenger.observe_extension_elements(&proof.final_poly.0); - context!( + with_context!( self, "check PoW", self.fri_verify_proof_of_work(proof, challenger, &config.fri_config) @@ -124,12 +124,27 @@ impl, const D: usize> CircuitBuilder { "Number of reductions should be non-zero." ); - let precomputed_reduced_evals = - PrecomputedReducedEvalsTarget::from_os_and_alpha(os, alpha, self); + let precomputed_reduced_evals = with_context!( + self, + "precompute reduced evaluations", + PrecomputedReducedEvalsTarget::from_os_and_alpha(os, alpha, self) + ); + for (i, round_proof) in proof.query_round_proofs.iter().enumerate() { - context!( + // To minimize noise in our logs, we will only record a context for a single FRI query. + // The very first query will have some extra gates due to constants being registered, so + // the second query is a better representative. + let level = if i == 1 { + log::Level::Debug + } else { + log::Level::Trace + }; + + let num_queries = proof.query_round_proofs.len(); + with_context!( self, - &format!("verify {}'th FRI query", i), + level, + &format!("verify one (of {}) query rounds", num_queries), self.fri_verifier_query_round( zeta, alpha, @@ -158,7 +173,7 @@ impl, const D: usize> CircuitBuilder { .zip(initial_merkle_roots) .enumerate() { - context!( + with_context!( self, &format!("verify {}'th initial Merkle proof", i), self.verify_merkle_proof(evals.clone(), x_index_bits, root, merkle_proof) @@ -256,7 +271,7 @@ impl, const D: usize> CircuitBuilder { let x_index = challenger.get_challenge(self); let mut x_index_bits = self.low_bits(x_index, n_log, 64); let mut domain_size = n; - context!( + with_context!( self, "check FRI initial proof", self.fri_verify_initial_proof( @@ -268,7 +283,7 @@ impl, const D: usize> CircuitBuilder { let mut old_x_index_bits = Vec::new(); // `subgroup_x` is `subgroup[x_index]`, i.e., the actual field element in the domain. - let mut subgroup_x = context!(self, "compute x from its index", { + let mut subgroup_x = with_context!(self, "compute x from its index", { let g = self.constant(F::MULTIPLICATIVE_GROUP_GENERATOR); let phi = self.constant(F::primitive_root_of_unity(n_log)); @@ -280,7 +295,7 @@ impl, const D: usize> CircuitBuilder { for (i, &arity_bits) in config.reduction_arity_bits.iter().enumerate() { let next_domain_size = domain_size >> arity_bits; let e_x = if i == 0 { - context!( + with_context!( self, "combine initial oracles", self.fri_combine_initial( @@ -295,7 +310,7 @@ impl, const D: usize> CircuitBuilder { } else { let last_evals = &evaluations[i - 1]; // Infer P(y) from {P(x)}_{x^arity=y}. - context!( + with_context!( self, "infer evaluation using interpolation", self.compute_evaluation( @@ -313,7 +328,7 @@ impl, const D: usize> CircuitBuilder { old_x_index_bits = x_index_bits; let low_x_index = self.le_sum(old_x_index_bits.iter()); evals = self.insert(low_x_index, e_x, evals); - context!( + with_context!( self, "verify FRI round Merkle proof.", self.verify_merkle_proof( @@ -335,7 +350,7 @@ impl, const D: usize> CircuitBuilder { let last_evals = evaluations.last().unwrap(); let final_arity_bits = *config.reduction_arity_bits.last().unwrap(); - let purported_eval = context!( + let purported_eval = with_context!( self, "infer final evaluation using interpolation", self.compute_evaluation( @@ -350,7 +365,7 @@ impl, const D: usize> CircuitBuilder { // Final check of FRI. After all the reductions, we check that the final polynomial is equal // to the one sent by the prover. - let eval = context!( + let eval = with_context!( self, "evaluate final polynomial", proof.final_poly.eval_scalar(self, subgroup_x) diff --git a/src/polynomial/commitment.rs b/src/polynomial/commitment.rs index a2c9001b..a307ba2c 100644 --- a/src/polynomial/commitment.rs +++ b/src/polynomial/commitment.rs @@ -4,7 +4,6 @@ use serde::{Deserialize, Serialize}; use crate::circuit_builder::CircuitBuilder; use crate::circuit_data::CommonCircuitData; -use crate::context; use crate::field::extension_field::target::ExtensionTarget; use crate::field::extension_field::Extendable; use crate::field::field::Field; @@ -17,6 +16,7 @@ use crate::proof::{FriProof, FriProofTarget, Hash, HashTarget, OpeningSet, Openi use crate::timed; use crate::util::reducing::ReducingFactor; use crate::util::{log2_ceil, log2_strict, reverse_bits, reverse_index_bits_in_place, transpose}; +use crate::with_context; /// Two (~64 bit) field elements gives ~128 bit security. pub const SALT_SIZE: usize = 2; @@ -283,7 +283,7 @@ impl OpeningProofTarget { let alpha = challenger.get_extension_challenge(builder); - context!( + with_context!( builder, "verify FRI proof", builder.verify_fri_proof( diff --git a/src/recursive_verifier.rs b/src/recursive_verifier.rs index ef6b8cff..9e96be60 100644 --- a/src/recursive_verifier.rs +++ b/src/recursive_verifier.rs @@ -1,12 +1,12 @@ use crate::circuit_builder::CircuitBuilder; use crate::circuit_data::{CircuitConfig, CommonCircuitData, VerifierCircuitTarget}; -use crate::context; use crate::field::extension_field::Extendable; use crate::plonk_challenger::RecursiveChallenger; use crate::proof::{HashTarget, ProofWithPublicInputsTarget}; use crate::util::reducing::ReducingFactorTarget; use crate::vanishing_poly::eval_vanishing_poly_recursively; use crate::vars::EvaluationTargets; +use crate::with_context; const MIN_WIRES: usize = 120; // TODO: Double check. const MIN_ROUTED_WIRES: usize = 28; // TODO: Double check. @@ -35,7 +35,7 @@ impl, const D: usize> CircuitBuilder { let mut challenger = RecursiveChallenger::new(self); let (betas, gammas, alphas, zeta) = - context!(self, "observe proof and generates challenges", { + with_context!(self, "observe proof and generates challenges", { // Observe the instance. let digest = HashTarget::from_vec( self.constants(&inner_common_data.circuit_digest.elements), @@ -69,7 +69,7 @@ impl, const D: usize> CircuitBuilder { let partial_products = &proof.openings.partial_products; let zeta_pow_deg = self.exp_power_of_2_extension(zeta, inner_common_data.degree_bits); - let vanishing_polys_zeta = context!( + let vanishing_polys_zeta = with_context!( self, "evaluate the vanishing polynomial at our challenge point, zeta.", eval_vanishing_poly_recursively( @@ -88,7 +88,7 @@ impl, const D: usize> CircuitBuilder { ) ); - context!(self, "check vanishing and quotient polynomials.", { + with_context!(self, "check vanishing and quotient polynomials.", { let quotient_polys_zeta = &proof.openings.quotient_polys; let mut scale = ReducingFactorTarget::new(zeta_pow_deg); let z_h_zeta = self.sub_extension(zeta_pow_deg, one); diff --git a/src/vanishing_poly.rs b/src/vanishing_poly.rs index e3e4284c..6101a9fb 100644 --- a/src/vanishing_poly.rs +++ b/src/vanishing_poly.rs @@ -1,6 +1,5 @@ use crate::circuit_builder::CircuitBuilder; use crate::circuit_data::CommonCircuitData; -use crate::context; use crate::field::extension_field::target::ExtensionTarget; use crate::field::extension_field::Extendable; use crate::field::field::Field; @@ -11,6 +10,7 @@ use crate::target::Target; use crate::util::partial_products::{check_partial_products, check_partial_products_recursively}; use crate::util::reducing::ReducingFactorTarget; use crate::vars::{EvaluationTargets, EvaluationVars, EvaluationVarsBase}; +use crate::with_context; /// Evaluate the vanishing polynomial at `x`. In this context, the vanishing polynomial is a random /// linear combination of gate constraints, plus some other terms relating to the permutation @@ -236,7 +236,7 @@ pub fn evaluate_gate_constraints_recursively, const D: usize>( ) -> Vec> { let mut constraints = vec![builder.zero_extension(); num_gate_constraints]; for gate in gates { - let gate_constraints = context!( + let gate_constraints = with_context!( builder, &format!("evaluate {} constraints", gate.gate.0.id()), gate.gate @@ -270,7 +270,7 @@ pub(crate) fn eval_vanishing_poly_recursively, const D: usize>( let max_degree = common_data.quotient_degree_factor; let (num_prods, final_num_prod) = common_data.num_partial_products; - let constraint_terms = context!( + let constraint_terms = with_context!( builder, "evaluate gate constraints", evaluate_gate_constraints_recursively(