From 6af4d845e92037718ef9d443a3ca2d479c1a908b Mon Sep 17 00:00:00 2001 From: zkfriendly Date: Wed, 16 Sep 2026 22:00:42 +0200 Subject: [PATCH 1/2] clean --- README.md | 2 -- 1 file changed, 2 deletions(-) diff --git a/README.md b/README.md index c747a14..df5954a 100644 --- a/README.md +++ b/README.md @@ -78,8 +78,6 @@ The workspace contains library crates under `crates/` and the `bitz-cli` package ## Acknowledgments -We thank the authors and maintainers of the projects that support this implementation: - - **[Flock](https://github.com/succinctlabs/flock) and Ligerito.** We use Ligerito through Flock's `flock-core` for our internal binary-field PCS. - **[Spongefish](https://github.com/arkworks-rs/spongefish).** We use Spongefish for Fiat–Shamir transcripts, challenge generation, and message encoding. - **[Nethermind's crypto-primitives](https://github.com/NethermindEth/crypto-primitives).** We use its field traits and procedural macros throughout our arithmetic and polynomial code. From 47bd827a106a6125f1baaedcb7f3676e6b648493 Mon Sep 17 00:00:00 2001 From: zkfriendly Date: Wed, 16 Sep 2026 22:09:48 +0200 Subject: [PATCH 2/2] add tracing spans in cli --- Cargo.lock | 120 ++++++++++ Cargo.toml | 2 + crates/gkr/Cargo.toml | 1 + crates/gkr/src/lib.rs | 3 + crates/pcs/Cargo.toml | 1 + crates/pcs/src/commitment.rs | 1 + crates/pcs/src/ligerito.rs | 2 + crates/pcs/src/opening.rs | 29 ++- crates/pcs/src/sumcheck.rs | 2 + crates/prover/Cargo.toml | 1 + crates/prover/src/fold.rs | 1 + crates/prover/src/prove.rs | 2 + crates/prover/src/reduce.rs | 2 + crates/spartan/Cargo.toml | 1 + crates/spartan/src/matrix.rs | 2 + crates/spartan/src/piop.rs | 8 +- crates/spartan/src/sumcheck.rs | 3 + crates/verifier/Cargo.toml | 1 + crates/verifier/src/fold.rs | 1 + crates/verifier/src/reduce.rs | 1 + crates/verifier/src/verify.rs | 2 + tooling/cli/Cargo.toml | 2 + tooling/cli/src/benchmark.rs | 8 + tooling/cli/src/cmd/circuit_e2e.rs | 14 +- tooling/cli/src/cmd/mod.rs | 4 + tooling/cli/src/end_to_end.rs | 5 + tooling/cli/src/main.rs | 19 +- tooling/cli/src/span_stats.rs | 350 +++++++++++++++++++++++++++++ 28 files changed, 574 insertions(+), 14 deletions(-) create mode 100644 tooling/cli/src/span_stats.rs diff --git a/Cargo.lock b/Cargo.lock index 7dc9416..082feb8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -13,6 +13,15 @@ dependencies = [ "cpufeatures 0.3.0", ] +[[package]] +name = "aho-corasick" +version = "1.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c982642fa9e8606056828ee9a8505737230110bb1099153c79efe865c59d12ba" +dependencies = [ + "memchr", +] + [[package]] name = "anstyle" version = "1.0.14" @@ -225,6 +234,8 @@ dependencies = [ "sha2 0.10.9", "spartan", "thiserror", + "tracing", + "tracing-subscriber", "transcript", "verifier", ] @@ -744,6 +755,7 @@ dependencies = [ "poly", "proptest", "rayon", + "tracing", "transcript", ] @@ -818,6 +830,12 @@ dependencies = [ "cpufeatures 0.3.0", ] +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "libc" version = "0.2.189" @@ -839,12 +857,36 @@ dependencies = [ "scopeguard", ] +[[package]] +name = "log" +version = "0.4.34" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f9f8bd3e56ce4dfc153cf470fffbfa98c7620958b312ca5c3a4b8d5181fd13c6" + +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "memchr" version = "2.8.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cf8baf1c55e62ffcace7a9f06f4bd9cd3f0c4beb022d3b367256b91b87513d98" +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys", +] + [[package]] name = "num-bigint" version = "0.4.8" @@ -1078,6 +1120,7 @@ dependencies = [ "flock-core", "num-traits", "proptest", + "tracing", "transcript", ] @@ -1148,6 +1191,7 @@ dependencies = [ "pcs", "poly", "rand 0.10.2", + "tracing", "transcript", ] @@ -1311,6 +1355,17 @@ dependencies = [ "crossbeam-utils", ] +[[package]] +name = "regex-automata" +version = "0.4.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ad8553b9b26413251cbf30e620595c7a41b3887f03da04579c0e6b0d6a06b4b2" +dependencies = [ + "aho-corasick", + "memchr", + "regex-syntax", +] + [[package]] name = "regex-lite" version = "0.1.9" @@ -1466,12 +1521,27 @@ dependencies = [ "keccak", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "2.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f8fadd59c855ef2080decdef8ff161eb6661b86933c9d82e5ba29dc602a55aba" +[[package]] +name = "smallvec" +version = "1.16.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba467056f1b547ed52077911161fc86985becbc60e8e1857c8a144dab0def891" + [[package]] name = "spartan" version = "0.1.0" @@ -1487,6 +1557,7 @@ dependencies = [ "rand_pcg 0.9.0", "rayon", "sha2 0.10.9", + "tracing", "transcript", ] @@ -1607,6 +1678,15 @@ dependencies = [ "syn 3.0.4", ] +[[package]] +name = "thread_local" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070" +dependencies = [ + "cfg-if", +] + [[package]] name = "toml" version = "0.8.23" @@ -1675,6 +1755,39 @@ name = "tracing-core" version = "0.1.36" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" +dependencies = [ + "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] [[package]] name = "trait-set" @@ -1713,6 +1826,12 @@ version = "1.0.24" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e6e4313cd5fcd3dad5cafa179702e2b244f760991f45397d14d4ebf38247da75" +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "verifier" version = "0.1.0" @@ -1723,6 +1842,7 @@ dependencies = [ "num-traits", "pcs", "poly", + "tracing", "transcript", ] diff --git a/Cargo.toml b/Cargo.toml index cb3e792..3fd5589 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -43,6 +43,8 @@ rand_pcg = "0.10" rayon = "1.10" spongefish = "0.7.4" thiserror = "2.0" +tracing = "0.1" +tracing-subscriber = { version = "0.3", features = ["env-filter"] } diff --git a/crates/gkr/Cargo.toml b/crates/gkr/Cargo.toml index cc6009a..7781751 100644 --- a/crates/gkr/Cargo.toml +++ b/crates/gkr/Cargo.toml @@ -8,6 +8,7 @@ license.workspace = true [dependencies] field = { path = "../field", features = ["spongefish"] } transcript = {path ="../transcript"} +tracing = { workspace = true } poly = { path = "../poly" } num-traits = { workspace = true } rayon = { workspace = true } diff --git a/crates/gkr/src/lib.rs b/crates/gkr/src/lib.rs index beed6eb..4a7f961 100644 --- a/crates/gkr/src/lib.rs +++ b/crates/gkr/src/lib.rs @@ -12,6 +12,7 @@ type Point = VecDeque; /// Proves the layer-by-layer sumcheck reduction from a claim at `point` /// (an evaluation point on the output layer) down to a claim on the leaves. // TODO #[must_use], requires changing the test suite +#[tracing::instrument(name = "Prove GKR", skip_all)] pub fn gpgkr_prove( ps: &mut ProverState, point: &[F128], @@ -188,6 +189,7 @@ impl SuffixTable { const PARALLEL_MIN_LANES: usize = 1 << 12; #[must_use] +#[tracing::instrument(name = "Verify GKR", skip_all)] pub fn gpgkr_verify( vs: &mut VerifierState, mut claim: Field, @@ -280,6 +282,7 @@ impl GrandProductCircuit { // Returns the final evaluation and the witnesses of the intermediate layers // Can't consume the input as the circuit is necessary for the initialisation of fiat shamir // TODO: replace with leaf lookups and add multithreading + #[tracing::instrument(name = "Evaluate grand-product circuit", level = "debug", skip_all)] pub fn batched_eval(&self, groups: usize) -> (Vec, LayerWitnesses) { // +1 to deal with the possible case that the leafs are empty. Given that otherwise the constructor padded it to a power of two, and ilog rounds it down, it becomes a noop let mut witnesses = Vec::with_capacity((self.leafs.len() + 1).ilog2() as usize); diff --git a/crates/pcs/Cargo.toml b/crates/pcs/Cargo.toml index 7983997..ad2b2f8 100644 --- a/crates/pcs/Cargo.toml +++ b/crates/pcs/Cargo.toml @@ -12,6 +12,7 @@ common = { workspace = true } field = { workspace = true, features = ["spongefish"] } flock-core = { workspace = true } transcript = { workspace = true } +tracing = { workspace = true } num-traits = { workspace = true } [dev-dependencies] diff --git a/crates/pcs/src/commitment.rs b/crates/pcs/src/commitment.rs index 9060866..0b17b5c 100644 --- a/crates/pcs/src/commitment.rs +++ b/crates/pcs/src/commitment.rs @@ -83,6 +83,7 @@ impl Pcs { } /// Commits to the exact configured number of packed field elements. + #[tracing::instrument(name = "Commit witness", skip_all)] pub fn commit(&self, packed_witness: &[F128]) -> Result<(Root, ProverData), CommitError> { // 1. Input Validation if packed_witness.len() != self.packed_len() { diff --git a/crates/pcs/src/ligerito.rs b/crates/pcs/src/ligerito.rs index 9cc6bdc..e2abc5f 100644 --- a/crates/pcs/src/ligerito.rs +++ b/crates/pcs/src/ligerito.rs @@ -106,6 +106,7 @@ impl<'a> ReducedProver<'a> { } /// Proves one reduced claim and writes the completed opening proof. + #[tracing::instrument(name = "Prove Ligerito", skip_all)] pub(crate) fn prove( self, claim: ReducedClaim, @@ -276,6 +277,7 @@ pub(crate) fn read_proof( Ok(proof) } +#[tracing::instrument(name = "Verify Ligerito", skip_all)] pub(crate) fn verify_succinct( pcs: &Pcs, commitment: &Root, diff --git a/crates/pcs/src/opening.rs b/crates/pcs/src/opening.rs index 904dc68..f268332 100644 --- a/crates/pcs/src/opening.rs +++ b/crates/pcs/src/opening.rs @@ -82,6 +82,7 @@ impl From for VerifyError { } } +#[tracing::instrument(name = "Prove PCS opening", skip_all)] pub(crate) fn prove( pcs: &Pcs, data: &ProverData, @@ -121,6 +122,7 @@ pub(crate) fn prove( } } +#[tracing::instrument(name = "Verify PCS opening", skip_all)] pub(crate) fn verify( pcs: &Pcs, commitment: &Root, @@ -176,10 +178,14 @@ fn prove_mle( target: F128, transcript: &mut ProverState, ) -> Result<(), ProveError> { - let prepared_claims = ring_switch.prepare_claims(as_flock_f128s(prover.witness()), target)?; - write_claims(transcript, &prepared_claims.claims); - let batching_point = sample_challenges(transcript); - let dense_reduction = prepared_claims.reduce_dense(&batching_point); + let dense_reduction = { + let _span = tracing::info_span!("Ring switch").entered(); + let prepared_claims = + ring_switch.prepare_claims(as_flock_f128s(prover.witness()), target)?; + write_claims(transcript, &prepared_claims.claims); + let batching_point = sample_challenges(transcript); + prepared_claims.reduce_dense(&batching_point) + }; prover.prove(dense_reduction, transcript) } @@ -192,12 +198,15 @@ fn verify_mle( transcript: &mut VerifierState<'_>, ) -> Result<(), VerifyError> { let proof = ligerito::read_proof(pcs, commitment, transcript)?; - let claims = read_claims(transcript)?; - if !ring_switch.target_matches(&claims, target) { - return Err(VerifyError::VerificationFailed); - } - let batching_point = sample_challenges(transcript); - let reduction = ring_switch.reduce_succinct(&claims, &batching_point); + let reduction = { + let _span = tracing::info_span!("Verify ring switch").entered(); + let claims = read_claims(transcript)?; + if !ring_switch.target_matches(&claims, target) { + return Err(VerifyError::VerificationFailed); + } + let batching_point = sample_challenges(transcript); + ring_switch.reduce_succinct(&claims, &batching_point) + }; ligerito::verify_succinct( pcs, commitment, diff --git a/crates/pcs/src/sumcheck.rs b/crates/pcs/src/sumcheck.rs index 63d6c28..c8f6c6d 100644 --- a/crates/pcs/src/sumcheck.rs +++ b/crates/pcs/src/sumcheck.rs @@ -30,6 +30,7 @@ pub(super) struct MleClaim { } /// Proves the reduction using a temporary dense table of witness evaluations. +#[tracing::instrument(name = "Prove inner-product sumcheck", skip_all)] pub(super) fn prove( claim: &LinearClaim, packed_witness: &[F128], @@ -81,6 +82,7 @@ pub(super) fn prove( } /// Verifies sumcheck and returns a witness claim that still requires the final PCS opening. +#[tracing::instrument(name = "Verify inner-product sumcheck", skip_all)] pub(super) fn verify( claim: &LinearClaim, transcript: &mut VerifierState<'_>, diff --git a/crates/prover/Cargo.toml b/crates/prover/Cargo.toml index cd9bb0c..2fcc654 100644 --- a/crates/prover/Cargo.toml +++ b/crates/prover/Cargo.toml @@ -14,6 +14,7 @@ common = { workspace = true } field = { workspace = true, features = ["spongefish"] } pcs = { workspace = true } transcript = { workspace = true } +tracing = { workspace = true } gkr = {workspace = true} num-traits = {workspace = true} poly = {workspace= true} diff --git a/crates/prover/src/fold.rs b/crates/prover/src/fold.rs index c0a39a2..8c272fe 100644 --- a/crates/prover/src/fold.rs +++ b/crates/prover/src/fold.rs @@ -31,6 +31,7 @@ impl BitZProver { /// Each fold is one record. The count is not itself absorbed, which is safe /// only because it derives from the configured shape; the wire profile is /// where a length-delimited vector record would belong. + #[tracing::instrument(name = "Fold columns", skip_all)] pub fn send_fold( &self, claim: &LinearClaim>, diff --git a/crates/prover/src/prove.rs b/crates/prover/src/prove.rs index 57e71ac..87c6270 100644 --- a/crates/prover/src/prove.rs +++ b/crates/prover/src/prove.rs @@ -49,6 +49,7 @@ impl BitZProver { /// /// The witness arrives owned because the opening consumes it. The transcript /// arrives carrying the caller's events; this appends and hands it back. + #[tracing::instrument(name = "Prove BitZ", skip_all)] pub fn prove( &self, claim: &LinearClaim>, @@ -88,6 +89,7 @@ impl BitZProver { /// /// Initialize the transcript with the session, instance, and enclosing public inputs. /// This method binds the inputs listed in [`VirtualStatement`]. + #[tracing::instrument(name = "Prove virtual BitZ", skip_all)] pub fn prove_virtual( &self, statement: &VirtualStatement<'_, Q, impl VirtualMap>, diff --git a/crates/prover/src/reduce.rs b/crates/prover/src/reduce.rs index 8bf1ef5..985c9f2 100644 --- a/crates/prover/src/reduce.rs +++ b/crates/prover/src/reduce.rs @@ -13,6 +13,7 @@ use poly::eq_table; use transcript::ProverState; #[inline(never)] +#[tracing::instrument(name = "Build grand-product circuit", level = "debug", skip_all)] fn init_circuit(table: &BitTable, fold: &Fold) -> GrandProductCircuit { let columns = table.shape().columns(); let dim = columns * table.shape().rows(); @@ -50,6 +51,7 @@ fn init_circuit(table: &BitTable, fold: &Fold) -> GrandProductCircuit { } /// Reduces the grand-product circuit to a factored claim on the committed bits. +#[tracing::instrument(name = "Reduce grand products", skip_all)] pub fn gkr_reduce( transcript: &mut ProverState, fold: &Fold, diff --git a/crates/spartan/Cargo.toml b/crates/spartan/Cargo.toml index 31ffab3..f482123 100644 --- a/crates/spartan/Cargo.toml +++ b/crates/spartan/Cargo.toml @@ -15,6 +15,7 @@ poly = { path = "../poly" } rayon = { workspace = true } sha2 = "0.10" transcript = { path = "../transcript" } +tracing = { workspace = true } [dev-dependencies] divan = { workspace = true } diff --git a/crates/spartan/src/matrix.rs b/crates/spartan/src/matrix.rs index 59b7ac0..17e97f6 100644 --- a/crates/spartan/src/matrix.rs +++ b/crates/spartan/src/matrix.rs @@ -241,6 +241,7 @@ where /// `D(j) = sum_i eq(i,r_x) (A[i,j] + rho B[i,j] + rho^2 C[i,j])` /// /// as a dense table over the column domain, one column chunk per task. + #[tracing::instrument(name = "Bind Spartan matrices", skip_all)] pub fn bind_and_batch( &self, row_point: &[F], @@ -262,6 +263,7 @@ where /// /// This deliberately does not call [`Self::bind_and_batch`], keeping the /// verifier path independent from the prover's dense-table construction. + #[tracing::instrument(name = "Evaluate Spartan matrices", level = "debug", skip_all)] pub fn evaluate_batched( &self, row_point: &[F], diff --git a/crates/spartan/src/piop.rs b/crates/spartan/src/piop.rs index d619a11..4a48641 100644 --- a/crates/spartan/src/piop.rs +++ b/crates/spartan/src/piop.rs @@ -63,6 +63,7 @@ impl From for SpartanError { /// When a protocol supports more than one choice of `F`, its transcript /// session or instance must bind that choice so proofs from different fields /// occupy distinct Fiat--Shamir domains. +#[tracing::instrument(name = "Prove Spartan", skip_all)] pub fn prove_spartan_piop( transcript: &mut ProverState, matrices: &PreparedConstraintMatrices, @@ -115,6 +116,7 @@ where /// Verifies both sumchecks and returns their terminal scaled assignment claim /// `D(r_y) * h(r_y) = final_claim`. +#[tracing::instrument(name = "Verify Spartan", skip_all)] pub fn verify_spartan_proof( transcript: &mut VerifierState<'_>, matrices: &PreparedConstraintMatrices, @@ -135,10 +137,12 @@ where let rho = transcript.squeeze::(); let inner_initial_claim = outer.az_mle_claim + rho * outer.bz_mle_claim + rho * rho * outer.cz_mle_claim; - let (column_point, final_claim) = + let (column_point, final_claim) = { + let _span = tracing::info_span!("Verify inner sumcheck").entered(); proof .inner - .verify(transcript, inner_initial_claim, num_column_vars)?; + .verify(transcript, inner_initial_claim, num_column_vars)? + }; let matrix_evaluation = matrices.evaluate_batched(&outer.eval_points, rho, &column_point)?; Ok(ScaledMleEvaluationClaim::new( diff --git a/crates/spartan/src/sumcheck.rs b/crates/spartan/src/sumcheck.rs index 2b082ca..1704ddd 100644 --- a/crates/spartan/src/sumcheck.rs +++ b/crates/spartan/src/sumcheck.rs @@ -220,6 +220,7 @@ where F: ConstField + Copy + Encoding<[u8]> + TranscriptChallenge, { /// Verifies the outer reduction and its terminal R1CS identity. + #[tracing::instrument(name = "Verify outer sumcheck", skip_all)] pub fn verify( &self, transcript: &mut VerifierState<'_>, @@ -251,6 +252,7 @@ where /// When a protocol supports more than one choice of `F`, its transcript /// session or instance must bind that choice so proofs from different fields /// occupy distinct Fiat–Shamir domains. +#[tracing::instrument(name = "Prove outer sumcheck", skip_all)] pub fn prove_outer_sumcheck( transcript: &mut ProverState, initial_claim: F, @@ -443,6 +445,7 @@ impl R1csProductTableBuffers { /// When a protocol supports more than one choice of `F`, its transcript /// session or instance must bind that choice so proofs from different fields /// occupy distinct Fiat–Shamir domains. +#[tracing::instrument(name = "Prove inner sumcheck", skip_all)] pub fn prove_inner_sumcheck( transcript: &mut ProverState, initial_claim: F, diff --git a/crates/verifier/Cargo.toml b/crates/verifier/Cargo.toml index 7613cf5..976ce74 100644 --- a/crates/verifier/Cargo.toml +++ b/crates/verifier/Cargo.toml @@ -14,6 +14,7 @@ common = { workspace = true } field = { workspace = true, features = ["spongefish"] } pcs = { workspace = true } transcript = { workspace = true } +tracing = { workspace = true } gkr = {workspace = true} poly = {workspace = true} num-traits = {workspace=true} diff --git a/crates/verifier/src/fold.rs b/crates/verifier/src/fold.rs index 96b3da0..4c23e0b 100644 --- a/crates/verifier/src/fold.rs +++ b/crates/verifier/src/fold.rs @@ -33,6 +33,7 @@ impl BitZVerifier { /// then is the challenge drawn. Reading a record absorbs it, so the folds are /// in the sponge before either check; what the ordering protects is the /// challenge, which must not be reachable until both have passed. + #[tracing::instrument(name = "Verify column folds", skip_all)] pub fn receive_fold( &self, claim: &LinearClaim>, diff --git a/crates/verifier/src/reduce.rs b/crates/verifier/src/reduce.rs index 73de898..d0e7577 100644 --- a/crates/verifier/src/reduce.rs +++ b/crates/verifier/src/reduce.rs @@ -20,6 +20,7 @@ pub enum ReduceError { Claim(ClaimError), } +#[tracing::instrument(name = "Verify grand-product reduction", skip_all)] pub(crate) fn gkr_reduce( transcript: &mut VerifierState, fold: &Fold, diff --git a/crates/verifier/src/verify.rs b/crates/verifier/src/verify.rs index 022f1af..e90f277 100644 --- a/crates/verifier/src/verify.rs +++ b/crates/verifier/src/verify.rs @@ -35,6 +35,7 @@ impl BitZVerifier { /// Start the transcript with the prover's session, instance, and public-input events. /// This method binds the inputs in [`VirtualStatement`], transposes the reduced /// claim, verifies the PCS opening, and rejects trailing proof or hint bytes. + #[tracing::instrument(name = "Verify virtual BitZ", skip_all)] pub fn verify_virtual( &self, statement: &VirtualStatement<'_, Q, impl VirtualMap>, @@ -69,6 +70,7 @@ impl BitZVerifier { /// /// `pcs` must be the scheme the commitment was made under. The transcript /// arrives carrying the caller's events; this appends and consumes it. + #[tracing::instrument(name = "Verify BitZ", skip_all)] pub fn verify( &self, claim: &LinearClaim>, diff --git a/tooling/cli/Cargo.toml b/tooling/cli/Cargo.toml index cb26d0a..a60dc2d 100644 --- a/tooling/cli/Cargo.toml +++ b/tooling/cli/Cargo.toml @@ -22,6 +22,8 @@ prover.workspace = true spartan.workspace = true thiserror.workspace = true transcript.workspace = true +tracing.workspace = true +tracing-subscriber.workspace = true verifier.workspace = true [dev-dependencies] diff --git a/tooling/cli/src/benchmark.rs b/tooling/cli/src/benchmark.rs index a997c1e..e5bbc09 100644 --- a/tooling/cli/src/benchmark.rs +++ b/tooling/cli/src/benchmark.rs @@ -23,6 +23,14 @@ pub fn run(statement: S, inputs: &[bool]) -> Result CircuitProofSystem { + #[tracing::instrument(name = "setup", skip_all)] pub fn new(statement: S) -> Result { let mut constraints = ConstraintGenerator::new(statement.input_bits()); let inputs: Vec<_> = (0..statement.input_bits()) @@ -164,6 +165,7 @@ impl CircuitProofSystem { } } + #[tracing::instrument(name = "witness", skip_all)] pub fn witness(&self, inputs: &[bool]) -> Result { if inputs.len() != self.statement.input_bits() { return Err(Error::Input("wrong witness input length")); @@ -199,6 +201,7 @@ impl CircuitProofSystem { }) } + #[tracing::instrument(name = "commit", skip_all)] pub fn commit(&self, witness: &Witness) -> Result { self.pcs .commit(&witness.committed) @@ -206,6 +209,7 @@ impl CircuitProofSystem { .map_err(Error::Commit) } + #[tracing::instrument(name = "prove", skip_all, fields(opening_path = ?self.opening_path))] pub fn prove(&self, witness: Witness, data: &ProverData) -> Result { let root = data.root(); let mut transcript = build_prover(SESSION, self.statement.domain()); @@ -258,6 +262,7 @@ impl CircuitProofSystem { }) } + #[tracing::instrument(name = "verify", skip_all)] pub fn verify(&self, proof: &Proof) -> Result<(), Error> { let mut transcript = build_verifier(SESSION, self.statement.domain(), &proof.opening); self.bind(&mut transcript, proof.root); diff --git a/tooling/cli/src/main.rs b/tooling/cli/src/main.rs index f09f75a..ae52d2d 100644 --- a/tooling/cli/src/main.rs +++ b/tooling/cli/src/main.rs @@ -1,8 +1,25 @@ mod cmd; +mod span_stats; -use {self::cmd::Command, anyhow::Result}; +use { + self::cmd::Command, + anyhow::{Context, Result}, + std::io::IsTerminal, + tracing_subscriber::{EnvFilter, layer::SubscriberExt, util::SubscriberInitExt}, +}; fn main() -> Result<()> { let args = argh::from_env::(); + if !args.quiet { + let filter = EnvFilter::builder() + .with_default_directive(tracing::Level::INFO.into()) + .from_env() + .context("invalid RUST_LOG filter")?; + let ansi = std::io::stderr().is_terminal() && std::env::var_os("NO_COLOR").is_none(); + tracing_subscriber::registry() + .with(filter) + .with(span_stats::SpanStats::new(std::io::stderr, ansi)) + .try_init()?; + } args.run() } diff --git a/tooling/cli/src/span_stats.rs b/tooling/cli/src/span_stats.rs new file mode 100644 index 0000000..dd11701 --- /dev/null +++ b/tooling/cli/src/span_stats.rs @@ -0,0 +1,350 @@ +// Only the CLI binary installs this layer. + +use std::{ + fmt::{self, Write as _}, + io::Write as _, + time::Instant, +}; +use tracing::{ + Event, Subscriber, + field::{Field, Visit}, + span::{Attributes, Id, Record}, +}; +use tracing_subscriber::{Layer, fmt::MakeWriter, layer::Context, registry::LookupSpan}; + +struct Data { + depth: usize, + started: Instant, + updates: String, +} + +struct Fields<'a>(&'a mut String); + +impl Visit for Fields<'_> { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + if field.name() == "message" { + let _ = write!(self.0, " {value:?}"); + } else { + let _ = write!(self.0, " {}={value:?}", field.name()); + } + } +} + +pub struct SpanStats { + writer: W, + ansi: bool, +} + +impl SpanStats { + pub fn new(writer: W, ansi: bool) -> Self { + Self { writer, ansi } + } + + fn dim(&self) -> &str { + if self.ansi { "\x1b[2m" } else { "" } + } + + fn reset(&self) -> &str { + if self.ansi { "\x1b[0m" } else { "" } + } +} + +impl Layer for SpanStats +where + S: Subscriber + for<'a> LookupSpan<'a>, + W: for<'a> MakeWriter<'a> + 'static, +{ + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let Some(span) = ctx.span(id) else { + return; + }; + // A filtered ancestor can exist without data from this layer. + let depth = span.parent().map_or(0, |parent| { + parent + .scope() + .find_map(|ancestor| { + ancestor + .extensions() + .get::() + .map(|data| data.depth + 1) + }) + .unwrap_or(0) + }); + span.extensions_mut().insert(Data { + depth, + started: Instant::now(), + updates: String::new(), + }); + let mut line = branch(depth, '╮'); + let _ = write!( + line, + "{}{}::{}{}", + self.dim(), + span.metadata().target(), + self.reset(), + span.metadata().name(), + ); + attrs.record(&mut Fields(&mut line)); + // A closed stderr pipe must not interrupt proof generation. + let _ = writeln!(self.writer.make_writer(), "{line}"); + } + + fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) { + if let Some(span) = ctx.span(id) + && let Some(data) = span.extensions_mut().get_mut::() + { + values.record(&mut Fields(&mut data.updates)); + } + } + + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + let mut line = String::new(); + // Respect explicit parents as well as the thread's current span. + if let Some(scope) = ctx.event_scope(event) { + for span in scope { + if let Some(data) = span.extensions().get::() { + line.push_str(&"│ ".repeat(data.depth + 1)); + let _ = write!( + line, + "{}{:.2?}{} ", + self.dim(), + data.started.elapsed(), + self.reset(), + ); + break; + } + } + } + let color = if self.ansi { + match *event.metadata().level() { + tracing::Level::ERROR => "\x1b[1;31m", + tracing::Level::WARN => "\x1b[1;33m", + tracing::Level::INFO => "\x1b[1;32m", + _ => self.dim(), + } + } else { + "" + }; + let _ = write!(line, "{color}{}{}", event.metadata().level(), self.reset()); + event.record(&mut Fields(&mut line)); + let _ = writeln!(self.writer.make_writer(), "{line}"); + } + + fn on_close(&self, id: Id, ctx: Context<'_, S>) { + let Some(span) = ctx.span(&id) else { + return; + }; + let extensions = span.extensions(); + let Some(data) = extensions.get::() else { + return; + }; + let mut line = branch(data.depth, '╯'); + let _ = write!( + line, + "{}{}:{} {:.2?}{} duration{}{}", + self.dim(), + span.metadata().name(), + self.reset(), + data.started.elapsed(), + self.dim(), + self.reset(), + data.updates, + ); + let _ = writeln!(self.writer.make_writer(), "{line}"); + } +} + +fn branch(depth: usize, marker: char) -> String { + let mut line = String::new(); + if depth > 0 { + line.push_str(&"│ ".repeat(depth - 1)); + line.push_str("├─"); + } + let _ = write!(line, "{marker} "); + line +} + +#[cfg(test)] +mod tests { + use std::{ + io, + sync::{Arc, Mutex}, + }; + + use tracing_subscriber::{filter::filter_fn, prelude::*}; + + use super::*; + + #[derive(Clone, Default)] + struct Buffer(Arc>>); + + impl io::Write for Buffer { + fn write(&mut self, bytes: &[u8]) -> io::Result { + self.0.lock().unwrap().extend_from_slice(bytes); + Ok(bytes.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + impl<'a> MakeWriter<'a> for Buffer { + type Writer = Self; + + fn make_writer(&'a self) -> Self::Writer { + self.clone() + } + } + + impl Buffer { + fn text(&self) -> String { + String::from_utf8(self.0.lock().unwrap().clone()).unwrap() + } + } + + fn capture(action: impl FnOnce()) -> String { + let buffer = Buffer::default(); + let subscriber = tracing_subscriber::registry().with(SpanStats::new(buffer.clone(), false)); + tracing::subscriber::with_default(subscriber, action); + buffer.text() + } + + #[test] + fn nested_spans_include_fields_events_and_durations_without_ansi() { + let output = capture(|| { + let root = tracing::info_span!(target: "test", "prove", size = 8); + let _root = root.enter(); + let child = + tracing::info_span!(target: "test", "commit", count = tracing::field::Empty); + let _child = child.enter(); + child.record("count", 3_u64); + tracing::info!(proof_bytes = 42, "proof ready"); + }); + let lines: Vec<_> = output.lines().collect(); + + assert_eq!(lines.len(), 5, "{output}"); + assert_eq!(lines[0], "╮ test::prove size=8"); + assert_eq!(lines[1], "├─╮ test::commit"); + assert!(lines[2].starts_with("│ │ "), "{output}"); + assert!( + lines[2].contains("INFO proof ready proof_bytes=42"), + "{output}" + ); + assert!(lines[3].starts_with("├─╯ commit: "), "{output}"); + assert!(lines[3].ends_with(" duration count=3"), "{output}"); + assert!(lines[4].starts_with("╯ prove: "), "{output}"); + for line in &lines[3..] { + let duration = line.split_once(": ").unwrap().1.split(' ').next().unwrap(); + assert!( + duration.starts_with(|ch: char| ch.is_ascii_digit()), + "{output}" + ); + assert!(duration.ends_with('s'), "{output}"); + } + assert!(!output.contains('\x1b'), "{output}"); + } + + #[test] + fn events_follow_explicit_parents_and_explicit_roots() { + let output = capture(|| { + let root = tracing::info_span!(target: "test", "root"); + let _root = root.enter(); + let child = tracing::info_span!(target: "test", "child"); + let _child = child.enter(); + tracing::info!(parent: &root, "parent event"); + tracing::info!(parent: None, "root event"); + tracing::info!("current event"); + }); + let parent = output + .lines() + .find(|line| line.ends_with("parent event")) + .unwrap(); + let root = output + .lines() + .find(|line| line.ends_with("root event")) + .unwrap(); + let current = output + .lines() + .find(|line| line.ends_with("current event")) + .unwrap(); + + assert!(parent.starts_with("│ "), "{output}"); + assert!(!parent.starts_with("│ │ "), "{output}"); + assert_eq!(root, "INFO root event"); + assert!(current.starts_with("│ │ "), "{output}"); + } + + #[test] + fn filtered_ancestors_do_not_add_tree_depth() { + // Keep filtered spans in the registry, as another output layer can do. + struct KeepSpans; + impl Layer for KeepSpans {} + + let buffer = Buffer::default(); + let subscriber = tracing_subscriber::registry().with(KeepSpans).with( + SpanStats::new(buffer.clone(), false) + .with_filter(filter_fn(|metadata| metadata.name() != "hidden")), + ); + tracing::subscriber::with_default(subscriber, || { + let root = tracing::info_span!(target: "test", "visible"); + let _root = root.enter(); + let hidden = tracing::info_span!(target: "test", "hidden"); + let _hidden = hidden.enter(); + let child = tracing::info_span!(target: "test", "child"); + let _child = child.enter(); + tracing::info!(parent: &hidden, "filtered parent event"); + }); + tracing::subscriber::with_default( + tracing_subscriber::registry().with(KeepSpans).with( + SpanStats::new(buffer.clone(), false) + .with_filter(filter_fn(|metadata| metadata.name() != "hidden")), + ), + || { + let hidden = tracing::info_span!(target: "test", "hidden"); + let _hidden = hidden.enter(); + let _child = tracing::info_span!(target: "test", "orphan"); + }, + ); + let output = buffer.text(); + + assert!(!output.contains("hidden"), "{output}"); + assert!( + output.lines().any(|line| line == "├─╮ test::child"), + "{output}" + ); + assert!( + output.lines().any(|line| line == "╮ test::orphan"), + "{output}" + ); + let event = output + .lines() + .find(|line| line.ends_with("filtered parent event")) + .unwrap(); + // Context hides this explicit parent. Do not attach the event to the active child. + assert_eq!(event, "INFO filtered parent event"); + } + + #[test] + fn writer_errors_do_not_interrupt_spans_or_events() { + struct BrokenWriter; + + impl io::Write for BrokenWriter { + fn write(&mut self, _: &[u8]) -> io::Result { + Err(io::ErrorKind::BrokenPipe.into()) + } + + fn flush(&mut self) -> io::Result<()> { + Err(io::ErrorKind::BrokenPipe.into()) + } + } + + let subscriber = + tracing_subscriber::registry().with(SpanStats::new(|| BrokenWriter, false)); + tracing::subscriber::with_default(subscriber, || { + let span = tracing::info_span!("proof"); + let _entered = span.enter(); + tracing::warn!("event survives writer failure"); + }); + } +}