write a macro to print time elapsed; use instrument on tracing

[cliff0412]

like this:

($name:expr, $block:block) => {{ use std::time::Instant;

let start = Instant::now();
let result = $block; // Execute the code block
let duration = start.elapsed();

println!("Time elapsed for {}: {:?}", $name, duration);

result // Return the result of the block

}}; }

[doutv]

We can use tracing crate https://docs.rs/tracing/0.1.40/tracing/index.html

[doutv]

Example output in Plonky3 with tracing crate:

INFO     generate Keccak trace [ 166ms | 100.00% ]
INFO     prove [ 1.20s | 0.94% / 100.00% ]
INFO     ┝━ infer log of constraint degree [ 5.64ms | 0.47% ]
INFO     ┝━ commit to trace data [ 550ms | 27.08% / 45.93% ]
INFO     │  ┕━ coset_lde_batch [ 225ms | 18.85% ] dims: 2633x32768
INFO     ┝━ compute quotient polynomial [ 434ms | 36.26% ]
INFO     ┝━ commit to quotient poly chunks [ 29.4ms | 1.63% / 2.46% ]
INFO     │  ┝━ coset_lde_batch [ 4.96ms | 0.41% ] dims: 4x32768
INFO     │  ┕━ coset_lde_batch [ 4.95ms | 0.41% ] dims: 4x32768
INFO     ┕━ open [ 167ms | 0.01% / 13.95% ]
INFO        ┝━ compute_inverse_denominators [ 8.13ms | 0.68% ]
INFO        ┝━ reduce matrix quotient [ 70.9ms | 0.01% / 5.92% ] dims: 2633x65536
INFO        │  ┝━ compute opened values with Lagrange interpolation [ 53.6ms | 4.48% ]
INFO        │  ┕━ reduce rows [ 17.1ms | 1.43% ]
INFO        ┝━ reduce matrix quotient [ 65.2ms | 0.01% / 5.45% ] dims: 2633x65536
INFO        │  ┝━ compute opened values with Lagrange interpolation [ 47.3ms | 3.96% ]
INFO        │  ┕━ reduce rows [ 17.8ms | 1.49% ]
INFO        ┝━ reduce matrix quotient [ 3.41ms | 0.00% / 0.28% ] dims: 4x65536
INFO        │  ┝━ compute opened values with Lagrange interpolation [ 2.59ms | 0.22% ]
INFO        │  ┕━ reduce rows [ 820µs | 0.07% ]
INFO        ┝━ reduce matrix quotient [ 3.32ms | 0.00% / 0.28% ] dims: 4x65536
INFO        │  ┝━ compute opened values with Lagrange interpolation [ 2.68ms | 0.22% ]
INFO        │  ┕━ reduce rows [ 638µs | 0.05% ]
INFO        ┕━ FRI prover [ 15.8ms | 0.01% / 1.32% ]
INFO           ┝━ commit phase [ 13.7ms | 1.14% ]
INFO           ┝━ grind for proof-of-work witness [ 903µs | 0.08% ]
INFO           ┕━ query phase [ 1.14ms | 0.10% ]
INFO     verify [ 183ms | 97.00% / 100.00% ]
INFO     ┕━ infer log of constraint degree [ 5.51ms | 3.00% ]