From 291a937e8a9cec41a5d73feee86390d34e576d3c Mon Sep 17 00:00:00 2001 From: Ratan Kaliani Date: Fri, 10 May 2024 14:48:17 -0700 Subject: [PATCH 1/2] feat: cycle tracker info --- core/src/syscall/write.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/src/syscall/write.rs b/core/src/syscall/write.rs index 2db198b081..3c68ea7fc6 100644 --- a/core/src/syscall/write.rs +++ b/core/src/syscall/write.rs @@ -48,7 +48,7 @@ impl Syscall for SyscallWrite { let (start, depth) = rt.cycle_tracker.remove(fn_name).unwrap_or((0, 0)); // Leftpad by 2 spaces for each depth. let padding = (0..depth).map(|_| "│ ").collect::(); - log::debug!( + log::info!( "{}└╴{} cycles", padding, num_to_comma_separated(rt.state.global_clk - start as u64) From 8f089917c2239c161dafd01f6a6dac811bae2eaa Mon Sep 17 00:00:00 2001 From: Ratan Kaliani Date: Fri, 10 May 2024 14:49:26 -0700 Subject: [PATCH 2/2] docs: book --- book/writing-programs/cycle-tracking.md | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/book/writing-programs/cycle-tracking.md b/book/writing-programs/cycle-tracking.md index a9bdbcfd57..953feff808 100644 --- a/book/writing-programs/cycle-tracking.md +++ b/book/writing-programs/cycle-tracking.md @@ -17,25 +17,25 @@ Note that to use the macro, you must add the `sp1-derive` crate to your dependen sp1-derive = { git = "https://github.com/succinctlabs/sp1.git" } ``` -In the script for proof generation, setup the logger with `utils::setup_logger()` and run the script with `RUST_LOG=debug cargo run --release`. You should see the following output: +In the script for proof generation, setup the logger with `utils::setup_logger()` and run the script with `RUST_LOG=info cargo run --release`. You should see the following output: ``` -$ RUST_LOG=debug cargo run --release +$ RUST_LOG=info cargo run --release Finished release [optimized] target(s) in 0.21s Running `target/release/cycle-tracking-script` 2024-03-13T02:03:40.567500Z INFO execute: loading memory image 2024-03-13T02:03:40.567751Z INFO execute: starting execution 2024-03-13T02:03:40.567760Z INFO execute: clk = 0 pc = 0x2013b8 -2024-03-13T02:03:40.567822Z DEBUG execute: ┌╴setup -2024-03-13T02:03:40.568095Z DEBUG execute: └╴4,398 cycles -2024-03-13T02:03:40.568122Z DEBUG execute: ┌╴main-body -2024-03-13T02:03:40.568149Z DEBUG execute: │ ┌╴expensive_function -2024-03-13T02:03:40.568250Z DEBUG execute: │ └╴1,368 cycles +2024-03-13T02:03:40.567822Z INFO execute: ┌╴setup +2024-03-13T02:03:40.568095Z INFO execute: └╴4,398 cycles +2024-03-13T02:03:40.568122Z INFO execute: ┌╴main-body +2024-03-13T02:03:40.568149Z INFO execute: │ ┌╴expensive_function +2024-03-13T02:03:40.568250Z INFO execute: │ └╴1,368 cycles stdout: result: 5561 -2024-03-13T02:03:40.568373Z DEBUG execute: │ ┌╴expensive_function -2024-03-13T02:03:40.568470Z DEBUG execute: │ └╴1,368 cycles +2024-03-13T02:03:40.568373Z INFO execute: │ ┌╴expensive_function +2024-03-13T02:03:40.568470Z INFO execute: │ └╴1,368 cycles stdout: result: 2940 -2024-03-13T02:03:40.568556Z DEBUG execute: └╴5,766 cycles +2024-03-13T02:03:40.568556Z INFO execute: └╴5,766 cycles 2024-03-13T02:03:40.568566Z INFO execute: finished execution clk = 11127 pc = 0x0 2024-03-13T02:03:40.569251Z INFO execute: close time.busy=1.78ms time.idle=21.1µs ```