Add measurement logs (#493)

<!-- Reviewable:start -->
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/starkware-libs/stwo/493)
<!-- Reviewable:end -->

Cargo.toml

@@ -13,10 +13,13 @@ itertools = "0.12.0"
 num-traits = "0.2.17"
 thiserror = "1.0.56"
 bytemuck = { version = "1.14.3", features = ["derive"] }
+tracing = "0.1.40"
 
 [dev-dependencies]
 criterion = { version = "0.5.1", features = ["html_reports"] }
 rand = { version = "0.8.5", features = ["small_rng"] }
+tracing-subscriber = "0.3.18"
+test-log = { version = "0.2.15", features = ["trace"] }
 
 [lib]
 bench = false

avx_benchmark.sh

@@ -0,0 +1,3 @@
+RUST_LOG_SPAN_EVENTS=enter,close RUST_LOG=info RUST_BACKTRACE=1 \
+    RUSTFLAGS="-C target-cpu=native -C target-feature=+avx512f -C opt-level=2" \
+    cargo test test_avx_wide_fib_prove -- --nocapture

src/core/air/accumulation.rs

@@ -4,6 +4,7 @@
 //!   f(p) = sum_i alpha^{N-1-i} u_i(P).
 
 use itertools::Itertools;
+use tracing::{span, Level};
 
 use crate::core::backend::{Backend, CPUBackend};
 use crate::core::fields::m31::BaseField;
@@ -114,6 +115,7 @@ impl<B: Backend> DomainEvaluationAccumulator<B> {
             0,
             "not all random coefficients were used"
         );
+        let _span = span!(Level::INFO, "Constraints interpolation").entered();
         let mut res_coeffs = SecureColumn::<B>::zeros(1 << self.log_size());
         let res_log_size = self.log_size();
 

src/core/commitment_scheme/prover.rs

@@ -1,6 +1,7 @@
 use std::collections::BTreeMap;
 
 use itertools::Itertools;
+use tracing::{span, Level};
 
 use super::super::channel::Blake2sChannel;
 use super::super::circle::CirclePoint;
@@ -147,6 +148,7 @@ impl<B: Backend + MerkleOps<MerkleHasher>> CommitmentTreeProver<B> {
         log_blowup_factor: u32,
         channel: &mut ProofChannel,
     ) -> Self {
+        let span = span!(Level::INFO, "Commitment evaluation").entered();
         let evaluations = polynomials
             .iter()
             .map(|poly| {
@@ -156,6 +158,9 @@ impl<B: Backend + MerkleOps<MerkleHasher>> CommitmentTreeProver<B> {
             })
             .collect_vec();
 
+        span.exit();
+
+        let _span = span!(Level::INFO, "Commitment merkle").entered();
         let tree = MerkleProver::commit(evaluations.iter().map(|eval| &eval.values).collect());
         channel.mix_digest(tree.root());
 

src/core/commitment_scheme/quotients.rs

@@ -3,6 +3,7 @@ use std::collections::BTreeMap;
 use std::iter::zip;
 
 use itertools::{izip, multiunzip, Itertools};
+use tracing::{span, Level};
 
 use crate::core::backend::cpu::quotients::{accumulate_row_quotients, quotient_constants};
 use crate::core::circle::CirclePoint;
@@ -76,6 +77,7 @@ pub fn compute_fri_quotients<B: QuotientOps>(
     samples: &[Vec<PointSample>],
     random_coeff: SecureField,
 ) -> Vec<SecureEvaluation<B>> {
+    let _span = span!(Level::INFO, "Compute FRI quotients").entered();
     zip(columns, samples)
         .sorted_by_key(|(c, _)| Reverse(c.domain.log_size()))
         .group_by(|(c, _)| c.domain.log_size())

src/core/fri.rs

@@ -7,6 +7,7 @@ use std::ops::RangeInclusive;
 use itertools::Itertools;
 use num_traits::Zero;
 use thiserror::Error;
+use tracing::{span, Level};
 
 use super::backend::CPUBackend;
 use super::channel::Channel;
@@ -149,6 +150,7 @@ impl<B: FriOps + MerkleOps<H>, H: MerkleHasher> FriProver<B, H> {
         columns: &[SecureEvaluation<B>],
         twiddles: &TwiddleTree<B>,
     ) -> Self {
+        let _span = span!(Level::INFO, "FRI commitment").entered();
         assert!(!columns.is_empty(), "no columns");
         assert!(columns.is_sorted_by_key(|e| Reverse(e.len())), "not sorted");
         assert!(columns.iter().all(|e| e.domain.is_canonic()), "not canonic");

src/core/proof_of_work.rs

@@ -1,4 +1,5 @@
 use thiserror::Error;
+use tracing::{span, Level};
 
 use super::channel::Blake2sChannel;
 use crate::commitment_scheme::blake2_hash::{Blake2sHash, Blake2sHasher};
@@ -22,6 +23,7 @@ impl ProofOfWork {
     }
 
     pub fn prove(&self, channel: &mut Blake2sChannel) -> ProofOfWorkProof {
+        let _span = span!(Level::INFO, "Proof of work").entered();
         let seed = channel.get_digest().as_ref().to_vec();
         let proof = self.grind(seed);
         channel.mix_nonce(proof.nonce);