Cycle Tracking

When writing a program, it is useful to know how many RISC-V cycles a portion of the program takes to identify potential performance bottlenecks. SP1 provides a way to track the number of cycles spent in a portion of the program.

Tracking Cycles

To track the number of cycles spent in a portion of the program, you can either put println!("cycle-tracker-start: block name") + println!("cycle-tracker-end: block name") statements (block name must be same between start and end) around the portion of your program you want to profile or use the #[sp1_derive::cycle_tracker] macro on a function. An example is shown below:

#![no_main]
sp1_zkvm::entrypoint!(main);

#[sp1_derive::cycle_tracker]
pub fn expensive_function(x: usize) -> usize {
    let mut y = 1;
    for _ in 0..100 {
        y *= x;
        y %= 7919;
    }
    y
}

pub fn main() {
    let mut nums = vec![1, 1];

    // Setup a large vector with Fibonacci-esque numbers.
    println!("cycle-tracker-start: setup");
    for _ in 0..100 {
        let mut c = nums[nums.len() - 1] + nums[nums.len() - 2];
        c %= 7919;
        nums.push(c);
    }
    println!("cycle-tracker-end: setup");

    println!("cycle-tracker-start: main-body");
    for i in 0..2 {
        let result = expensive_function(nums[nums.len() - i - 1]);
        println!("result: {}", result);
    }
    println!("cycle-tracker-end: main-body");
}

Note that to use the macro, you must add the sp1-derive crate to your dependencies for your program.

[dependencies]
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:

$ RUST_LOG=debug 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    
stdout: result: 5561
2024-03-13T02:03:40.568373Z DEBUG execute: │ ┌╴expensive_function    
2024-03-13T02:03:40.568470Z DEBUG execute: │ └╴1,368 cycles    
stdout: result: 2940
2024-03-13T02:03:40.568556Z DEBUG 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

Note that we elegantly handle nested cycle tracking, as you can see above.