Implementation of Tracing logger (#241)

* refactor: change logger to tracing * feat: implement tree-like logger * refactor: remove trace lines, add more info to info messages * feat: enable tracing_forest as an option
facebook · Feb 5, 2024 · 250c7a7 · 250c7a7
1 parent 08c31cb
commit 250c7a7
Show file tree

Hide file tree

Showing 22 changed files with 429 additions and 461 deletions.
diff --git a/examples/Cargo.toml b/examples/Cargo.toml
@@ -23,17 +23,18 @@ doc = false
 [features]
 concurrent = ["winterfell/concurrent", "std"]
 default = ["std"]
-std = ["hex/std", "winterfell/std", "core-utils/std", "rand-utils"]
+std = ["core-utils/std", "hex/std", "rand-utils", "winterfell/std"]
 
 [dependencies]
-winterfell = { version="0.7", path = "../winterfell", default-features = false }
+blake3 = { version = "1.5", default-features = false }
 core-utils = { version = "0.7", path = "../utils/core", package = "winter-utils", default-features = false }
-rand-utils = { version = "0.7", path = "../utils/rand", package = "winter-rand-utils", optional = true }
 hex = { version = "0.4", optional = true }
-log = { version = "0.4", default-features = false }
-blake3 = { version = "1.5", default-features = false }
-env_logger = { version = "0.10", default-features = false }
+rand-utils = { version = "0.7", path = "../utils/rand", package = "winter-rand-utils", optional = true }
 structopt = { version = "0.3", default-features = false }
+tracing = { version = "0.1", default-features = false }
+tracing-subscriber = { version = "0.3", features = ["std", "env-filter"] }
+tracing-forest = { version = "0.1", features = ["ansi", "smallvec"], optional = true }
+winterfell = { version="0.7", path = "../winterfell", default-features = false }
 
 [dev-dependencies]
 criterion = "0.5"

diff --git a/examples/src/fibonacci/fib2/mod.rs b/examples/src/fibonacci/fib2/mod.rs
@@ -6,8 +6,8 @@
 use super::utils::compute_fib_term;
 use crate::{Blake3_192, Blake3_256, Example, ExampleOptions, HashFunction, Sha3_256};
 use core::marker::PhantomData;
-use log::debug;
 use std::time::Instant;
+use tracing::{field, info_span};
 use winterfell::{
     crypto::{DefaultRandomCoin, ElementHasher},
     math::{fields::f128::BaseElement, FieldElement},
@@ -65,7 +65,7 @@ impl<H: ElementHasher> FibExample<H> {
         // compute Fibonacci sequence
         let now = Instant::now();
         let result = compute_fib_term(sequence_length);
-        debug!(
+        println!(
             "Computed Fibonacci sequence up to {}th term in {} ms",
             sequence_length,
             now.elapsed().as_millis()
@@ -88,27 +88,22 @@ where
     H: ElementHasher<BaseField = BaseElement>,
 {
     fn prove(&self) -> StarkProof {
-        debug!(
-            "Generating proof for computing Fibonacci sequence (2 terms per step) up to {}th term\n\
-            ---------------------",
+        println!(
+            "Generating proof for computing Fibonacci sequence (2 terms per step) up to {}th term",
             self.sequence_length
         );
 
         // create a prover
         let prover = FibProver::<H>::new(self.options.clone());
 
         // generate execution trace
-        let now = Instant::now();
-        let trace = prover.build_trace(self.sequence_length);
-
-        let trace_width = trace.width();
-        let trace_length = trace.length();
-        debug!(
-            "Generated execution trace of {} registers and 2^{} steps in {} ms",
-            trace_width,
-            trace_length.ilog2(),
-            now.elapsed().as_millis()
-        );
+        let trace =
+            info_span!("generate_execution_trace", num_cols = TRACE_WIDTH, steps = field::Empty)
+                .in_scope(|| {
+                    let trace = prover.build_trace(self.sequence_length);
+                    tracing::Span::current().record("steps", trace.length());
+                    trace
+                });
 
         // generate the proof
         prover.prove(trace).unwrap()

diff --git a/examples/src/fibonacci/fib8/mod.rs b/examples/src/fibonacci/fib8/mod.rs
@@ -6,8 +6,8 @@
 use super::utils::compute_fib_term;
 use crate::{Blake3_192, Blake3_256, Example, ExampleOptions, HashFunction, Sha3_256};
 use core::marker::PhantomData;
-use log::debug;
 use std::time::Instant;
+use tracing::{field, info_span};
 use winterfell::{
     crypto::{DefaultRandomCoin, ElementHasher},
     math::{fields::f128::BaseElement, FieldElement},
@@ -65,7 +65,7 @@ impl<H: ElementHasher> Fib8Example<H> {
         // compute Fibonacci sequence
         let now = Instant::now();
         let result = compute_fib_term(sequence_length);
-        debug!(
+        println!(
             "Computed Fibonacci sequence up to {}th term in {} ms",
             sequence_length,
             now.elapsed().as_millis()
@@ -88,26 +88,22 @@ where
     H: ElementHasher<BaseField = BaseElement>,
 {
     fn prove(&self) -> StarkProof {
-        debug!(
-            "Generating proof for computing Fibonacci sequence (8 terms per step) up to {}th term\n\
-            ---------------------",
+        println!(
+            "Generating proof for computing Fibonacci sequence (8 terms per step) up to {}th term",
             self.sequence_length
         );
 
         // create a prover
         let prover = Fib8Prover::<H>::new(self.options.clone());
 
         // generate execution trace
-        let now = Instant::now();
-        let trace = prover.build_trace(self.sequence_length);
-        let trace_width = trace.width();
-        let trace_length = trace.length();
-        debug!(
-            "Generated execution trace of {} registers and 2^{} steps in {} ms",
-            trace_width,
-            trace_length.ilog2(),
-            now.elapsed().as_millis()
-        );
+        let trace =
+            info_span!("generate_execution_trace", num_cols = TRACE_WIDTH, steps = field::Empty)
+                .in_scope(|| {
+                    let trace = prover.build_trace(self.sequence_length);
+                    tracing::Span::current().record("steps", trace.length());
+                    trace
+                });
 
         // generate the proof
         prover.prove(trace).unwrap()

diff --git a/examples/src/fibonacci/fib_small/mod.rs b/examples/src/fibonacci/fib_small/mod.rs
@@ -6,8 +6,8 @@
 use super::utils::compute_fib_term;
 use crate::{Example, ExampleOptions, HashFunction};
 use core::marker::PhantomData;
-use log::debug;
 use std::time::Instant;
+use tracing::{field, info_span};
 use winterfell::{
     crypto::{DefaultRandomCoin, ElementHasher},
     math::{fields::f64::BaseElement, FieldElement},
@@ -80,7 +80,7 @@ impl<H: ElementHasher> FibExample<H> {
         // compute Fibonacci sequence
         let now = Instant::now();
         let result = compute_fib_term::<BaseElement>(sequence_length);
-        debug!(
+        println!(
             "Computed Fibonacci sequence up to {}th term in {} ms",
             sequence_length,
             now.elapsed().as_millis()
@@ -103,27 +103,22 @@ where
     H: ElementHasher<BaseField = BaseElement>,
 {
     fn prove(&self) -> StarkProof {
-        debug!(
-            "Generating proof for computing Fibonacci sequence (2 terms per step) up to {}th term\n\
-            ---------------------",
+        println!(
+            "Generating proof for computing Fibonacci sequence (2 terms per step) up to {}th term",
             self.sequence_length
         );
 
         // create a prover
         let prover = FibSmallProver::<H>::new(self.options.clone());
 
         // generate execution trace
-        let now = Instant::now();
-        let trace = prover.build_trace(self.sequence_length);
-
-        let trace_width = trace.width();
-        let trace_length = trace.length();
-        debug!(
-            "Generated execution trace of {} registers and 2^{} steps in {} ms",
-            trace_width,
-            trace_length.ilog2(),
-            now.elapsed().as_millis()
-        );
+        let trace =
+            info_span!("generate_execution_trace", num_cols = TRACE_WIDTH, steps = field::Empty)
+                .in_scope(|| {
+                    let trace = prover.build_trace(self.sequence_length);
+                    tracing::Span::current().record("steps", trace.length());
+                    trace
+                });
 
         // generate the proof
         prover.prove(trace).unwrap()
@@ -132,6 +127,7 @@ where
     fn verify(&self, proof: StarkProof) -> Result<(), VerifierError> {
         let acceptable_options =
             winterfell::AcceptableOptions::OptionSet(vec![proof.options().clone()]);
+
         winterfell::verify::<FibSmall, H, DefaultRandomCoin<H>>(
             proof,
             self.result,

diff --git a/examples/src/fibonacci/mulfib2/air.rs b/examples/src/fibonacci/mulfib2/air.rs
@@ -3,6 +3,7 @@
 // This source code is licensed under the MIT license found in the
 // LICENSE file in the root directory of this source tree.
 
+use super::TRACE_WIDTH;
 use crate::utils::are_equal;
 use winterfell::{
     math::{fields::f128::BaseElement, FieldElement},
@@ -13,8 +14,6 @@ use winterfell::{
 // FIBONACCI AIR
 // ================================================================================================
 
-const TRACE_WIDTH: usize = 2;
-
 pub struct MulFib2Air {
     context: AirContext<BaseElement>,
     result: BaseElement,

diff --git a/examples/src/fibonacci/mulfib2/mod.rs b/examples/src/fibonacci/mulfib2/mod.rs
@@ -6,8 +6,8 @@
 use super::utils::compute_mulfib_term;
 use crate::{Blake3_192, Blake3_256, Example, ExampleOptions, HashFunction, Sha3_256};
 use core::marker::PhantomData;
-use log::debug;
 use std::time::Instant;
+use tracing::{field, info_span};
 use winterfell::{
     crypto::{DefaultRandomCoin, ElementHasher},
     math::{fields::f128::BaseElement, FieldElement},
@@ -23,6 +23,11 @@ use prover::MulFib2Prover;
 #[cfg(test)]
 mod tests;
 
+// CONSTANTS
+// ================================================================================================
+
+const TRACE_WIDTH: usize = 2;
+
 // FIBONACCI EXAMPLE
 // ================================================================================================
 
@@ -59,7 +64,7 @@ impl<H: ElementHasher> MulFib2Example<H> {
         // compute Fibonacci sequence
         let now = Instant::now();
         let result = compute_mulfib_term(sequence_length);
-        debug!(
+        println!(
             "Computed multiplicative Fibonacci sequence up to {}th term in {} ms",
             sequence_length,
             now.elapsed().as_millis()
@@ -83,26 +88,22 @@ where
 {
     fn prove(&self) -> StarkProof {
         let sequence_length = self.sequence_length;
-        debug!(
-            "Generating proof for computing multiplicative Fibonacci sequence (8 terms per step) up to {}th term\n\
-            ---------------------",
+        println!(
+            "Generating proof for computing multiplicative Fibonacci sequence (2 terms per step) up to {}th term",
             sequence_length
         );
 
         // create a prover
         let prover = MulFib2Prover::<H>::new(self.options.clone());
 
         // generate execution trace
-        let now = Instant::now();
-        let trace = prover.build_trace(sequence_length);
-        let trace_width = trace.width();
-        let trace_length = trace.length();
-        debug!(
-            "Generated execution trace of {} registers and 2^{} steps in {} ms",
-            trace_width,
-            trace_length.ilog2(),
-            now.elapsed().as_millis()
-        );
+        let trace =
+            info_span!("generate_execution_trace", num_cols = TRACE_WIDTH, steps = field::Empty)
+                .in_scope(|| {
+                    let trace = prover.build_trace(sequence_length);
+                    tracing::Span::current().record("steps", trace.length());
+                    trace
+                });
 
         // generate the proof
         prover.prove(trace).unwrap()

diff --git a/examples/src/fibonacci/mulfib8/air.rs b/examples/src/fibonacci/mulfib8/air.rs
@@ -3,6 +3,7 @@
 // This source code is licensed under the MIT license found in the
 // LICENSE file in the root directory of this source tree.
 
+use super::TRACE_WIDTH;
 use crate::utils::are_equal;
 use winterfell::{
     math::{fields::f128::BaseElement, FieldElement},
@@ -13,8 +14,6 @@ use winterfell::{
 // FIBONACCI AIR
 // ================================================================================================
 
-const TRACE_WIDTH: usize = 8;
-
 pub struct MulFib8Air {
     context: AirContext<BaseElement>,
     result: BaseElement,

diff --git a/examples/src/fibonacci/mulfib8/mod.rs b/examples/src/fibonacci/mulfib8/mod.rs
@@ -6,8 +6,8 @@
 use super::utils::compute_mulfib_term;
 use crate::{Blake3_192, Blake3_256, Example, ExampleOptions, HashFunction, Sha3_256};
 use core::marker::PhantomData;
-use log::debug;
 use std::time::Instant;
+use tracing::{field, info_span};
 use winterfell::{
     crypto::{DefaultRandomCoin, ElementHasher},
     math::{fields::f128::BaseElement, FieldElement},
@@ -23,6 +23,11 @@ use prover::MulFib8Prover;
 #[cfg(test)]
 mod tests;
 
+// CONSTANTS
+// ================================================================================================
+
+const TRACE_WIDTH: usize = 8;
+
 // FIBONACCI EXAMPLE
 // ================================================================================================
 
@@ -60,7 +65,7 @@ impl<H: ElementHasher> MulFib8Example<H> {
         // compute Fibonacci sequence
         let now = Instant::now();
         let result = compute_mulfib_term(sequence_length);
-        debug!(
+        println!(
             "Computed multiplicative Fibonacci sequence up to {}th term in {} ms",
             sequence_length,
             now.elapsed().as_millis()
@@ -84,26 +89,22 @@ where
 {
     fn prove(&self) -> StarkProof {
         let sequence_length = self.sequence_length;
-        debug!(
-            "Generating proof for computing multiplicative Fibonacci sequence (2 terms per step) up to {}th term\n\
-            ---------------------",
+        println!(
+            "Generating proof for computing multiplicative Fibonacci sequence (8 terms per step) up to {}th term",
             sequence_length
         );
 
         // create a prover
         let prover = MulFib8Prover::<H>::new(self.options.clone());
 
         // generate execution trace
-        let now = Instant::now();
-        let trace = prover.build_trace(sequence_length);
-        let trace_width = trace.width();
-        let trace_length = trace.length();
-        debug!(
-            "Generated execution trace of {} registers and 2^{} steps in {} ms",
-            trace_width,
-            trace_length.ilog2(),
-            now.elapsed().as_millis()
-        );
+        let trace =
+            info_span!("generate_execution_trace", num_cols = TRACE_WIDTH, steps = field::Empty)
+                .in_scope(|| {
+                    let trace = prover.build_trace(sequence_length);
+                    tracing::Span::current().record("steps", trace.length());
+                    trace
+                });
 
         // generate the proof
         prover.prove(trace).unwrap()