Skip to content

Commit

Permalink
feat: profiling
Browse files Browse the repository at this point in the history
  • Loading branch information
nhtyy committed Nov 22, 2024
1 parent 87cab0f commit 832b7aa
Show file tree
Hide file tree
Showing 13 changed files with 497 additions and 550 deletions.
44 changes: 43 additions & 1 deletion Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

74 changes: 17 additions & 57 deletions book/writing-programs/cycle-tracking.md
Original file line number Diff line number Diff line change
Expand Up @@ -56,69 +56,29 @@ fn main() {

This will log the cycle count for `block name` and include it in the `ExecutionReport` in the `cycle_tracker` map.

## Tracking Cycles with Tracing
### Profiling the ZKVM

The `cycle-tracker` annotation is a convenient way to track cycles for specific sections of code. However, sometimes it can also be useful to track what functions are taking the most cycles across the entire program, without having to annotate every function individually.
Profiling the VM is a good way to get an understanding of what is bottlenecking your program, note only one program may be profiled at a time.

First, we need to generate a trace file of the program counter at each cycle while the program is executing. This can be done by simply setting the `TRACE_FILE` environment variable with the path of the file you want to write the trace to. For example, you can run the following command in the `script` directory for any example program:

```bash
TRACE_FILE=trace.log RUST_LOG=info cargo run --release
To profile a program, you have to setup a script to execute the program, many examples can be found in the repo, such as this ['fibonacci'](https://github.com/succinctlabs/sp1/blob/12f212e386ae4c2da30cf6a61a7d87615d56bdac/examples/fibonacci/script/src/main.rs#L22) script.
Once you have your script it should contain the following code:
```rs
// Execute the program using the `ProverClient.execute` method, without generating a proof.
let (_, report) = client.execute(ELF, stdin.clone()).run().unwrap();
```

When the `TRACE_FILE` environment variable is set, as SP1's RISC-V runtime is executing, it will write a log of the program counter to the file specified by `TRACE_FILE`.
The data captured by the profiler can be quite large, you can set the sample rate using the `TRACE_SAMPLE_RATE` env var.
To enable profiling, set the `TRACE_FILE` env var to the path where you want the profile to be saved.

Next, we can use the `cargo prove` CLI with the `trace` command to analyze the trace file and generate a table of instruction counts. This can be done with the following command:
A larger sample rate will give you a smaller profile, it is the number of instructions in between each sample.

```bash
cargo prove trace --elf <path_to_program_elf> --trace <path_to_trace_file>
The full command to profile should look something like this
```sh
TRACE_FILE=output.json TRACE_SAMPLE_RATE=100 cargo run ...
```

The `trace` command will generate a table of instruction counts, sorted by the number of cycles spent in each function. The output will look something like this:

```
[00:00:00] [########################################] 17053/17053 (0s)
Total instructions in trace: 17053
Instruction counts considering call graph
+----------------------------------------+-------------------+
| Function Name | Instruction Count |
| __start | 17045 |
| main | 12492 |
| sp1_zkvm::syscalls::halt::syscall_halt | 4445 |
| sha2::sha256::compress256 | 4072 |
| sp1_lib::io::commit | 258 |
| sp1_lib::io::SyscallWriter::write | 255 |
| syscall_write | 195 |
| memcpy | 176 |
| memset | 109 |
| sp1_lib::io::read_vec | 71 |
| __rust_alloc | 29 |
| sp1_zkvm::heap::SimpleAlloc::alloc | 22 |
| syscall_hint_len | 3 |
| syscall_hint_read | 2 |
+----------------------------------------+-------------------+
Instruction counts ignoring call graph
+----------------------------------------+-------------------+
| Function Name | Instruction Count |
| main | 12075 |
| sha2::sha256::compress256 | 4073 |
| sp1_zkvm::syscalls::halt::syscall_halt | 219 |
| memcpy | 180 |
| syscall_write | 123 |
| memset | 111 |
| sp1_lib::io::commit | 88 |
| sp1_lib::io::SyscallWriter::write | 60 |
| __start | 45 |
| sp1_lib::io::read_vec | 35 |
| sp1_zkvm::heap::SimpleAlloc::alloc | 23 |
| anonymous | 7 |
| __rust_alloc | 7 |
| syscall_hint_len | 4 |
| syscall_hint_read | 3 |
+----------------------------------------+-------------------+
To view these profiles, we recommend [Samply](https://github.com/mstange/samply).
```sh
cargo install --locked samply
samply load output.json
```
2 changes: 1 addition & 1 deletion crates/cli/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -43,4 +43,4 @@ regex = "1.5.4"
prettytable-rs = "0.10"
textwrap = "0.16.0"
ctrlc = "3.4.2"
cargo_metadata = "0.18.1"
cargo_metadata = "0.18.1"
4 changes: 1 addition & 3 deletions crates/cli/src/bin/cargo-prove.rs
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@ use clap::{Parser, Subcommand};
use sp1_cli::{
commands::{
build::BuildCmd, build_toolchain::BuildToolchainCmd,
install_toolchain::InstallToolchainCmd, new::NewCmd, trace::TraceCmd, vkey::VkeyCmd,
install_toolchain::InstallToolchainCmd, new::NewCmd, vkey::VkeyCmd,
},
SP1_VERSION_MESSAGE,
};
Expand All @@ -27,7 +27,6 @@ pub enum ProveCliCommands {
Build(BuildCmd),
BuildToolchain(BuildToolchainCmd),
InstallToolchain(InstallToolchainCmd),
Trace(TraceCmd),
Vkey(VkeyCmd),
}

Expand All @@ -39,7 +38,6 @@ fn main() -> Result<()> {
ProveCliCommands::Build(cmd) => cmd.run(),
ProveCliCommands::BuildToolchain(cmd) => cmd.run(),
ProveCliCommands::InstallToolchain(cmd) => cmd.run(),
ProveCliCommands::Trace(cmd) => cmd.run(),
ProveCliCommands::Vkey(cmd) => cmd.run(),
}
}
1 change: 0 additions & 1 deletion crates/cli/src/commands/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -2,5 +2,4 @@ pub mod build;
pub mod build_toolchain;
pub mod install_toolchain;
pub mod new;
pub mod trace;
pub mod vkey;
Loading

0 comments on commit 832b7aa

Please sign in to comment.