Feat: Vm Profiling

book/writing-programs/cycle-tracking.md

@@ -56,69 +56,48 @@ 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 a ZKVM program 
 
-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 a zkVM program produces a profile ([example link](https://share.firefox.dev/3Om1pzz)) which makes it easy to examine program performance and see exactly where exactly VM cycles are being spent without needing to modify the program at all.
 
-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:
+To profile a program, you simply need to:
+1. Enable the profiling feature for `sp1-sdk` in `script/Cargo.toml`
+2. Set the env variable `TRACE_FILE=trace.json` and then call `ProverClient::execute()` in your script.
 
-```bash
-TRACE_FILE=trace.log RUST_LOG=info cargo run --release
-```
+If you're executing a larger program (>100M cycles), you should set `TRACE_SAMPLE_RATE` to reduce the size of the trace file. A sample rate of `1000` means that 1 in every 1000 VM cycles is sampled. By default, every cycle is sampled.
 
-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`.
+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.
 
-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:
+Once you have your script it should look like the following: 
+```rs 
+    // Execute the program using the `ProverClient.execute` method, without generating a proof.
+    let (_, report) = client.execute(ELF, stdin.clone()).run().unwrap();
+```
 
-```bash
-cargo prove trace --elf <path_to_program_elf> --trace <path_to_trace_file>
+As well you must enable the profiling feature on the SDK:
+```toml
+    sp1-sdk = { version = "3.0.0", features = ["profiling"] }
 ```
 
-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:
+The `TRACE_FILE` env var tells the executor where to save the profile, and the `TRACE_SAMPLE_RATE` env var tells the executor how often to sample the program.
+A larger sample rate will give you a smaller profile, it is the number of instructions in between each sample.
 
+The full command to profile should look something like this
+```sh
+    TRACE_FILE=output.json TRACE_SAMPLE_RATE=100 cargo run ...
 ```
-  [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
 ```
+
+Samply uses the Firefox profiler to create a nice visualization of your programs execution.
+![An example screenshot of the Firefox Profiler](../profiling.png)
+
+#### Interpreting the Profile
+- The "time" measurement in the profiler is actually the number of cycles spent, 
+in general the less cycles for a given callframe the better.
+
+- The CPU usage of the program will always be constant, as its running in the VM which is single threaded.

crates/cli/Cargo.toml

@@ -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"

crates/cli/src/bin/cargo-prove.rs

@@ -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,
 };
@@ -27,7 +27,6 @@ pub enum ProveCliCommands {
     Build(BuildCmd),
     BuildToolchain(BuildToolchainCmd),
     InstallToolchain(InstallToolchainCmd),
-    Trace(TraceCmd),
     Vkey(VkeyCmd),
 }
 
@@ -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(),
     }
 }

crates/cli/src/commands/mod.rs

@@ -2,5 +2,4 @@ pub mod build;
 pub mod build_toolchain;
 pub mod install_toolchain;
 pub mod new;
-pub mod trace;
 pub mod vkey;