changes

book/SUMMARY.md

@@ -20,6 +20,8 @@
 
 - [Patched Crates](./writing-programs/patched-crates.md)
 
+- [Cycle Tracking](./writing-programs/cycle-tracking.md)
+
 # Generating Proofs
 
 - [Setup](./generating-proofs/setup.md)

book/generating-proofs/basics.md

@@ -14,9 +14,11 @@ To make this more concrete, let's walk through a simple example of generating a
 {{#include ../../examples/fibonacci-io/script/src/main.rs}}
 ```
 
+You can run the above script with `RUST_LOG=info cargo run --release`.
+
 ## Build Script
 
-If you want your program crate to be built automatically whenever you build/run your script crate, you can add a `build.rs` file inside of `script/`:
+If you want your program crate to be built automatically whenever you build/run your script crate, you can add a `build.rs` file inside of `script/` (at the same level as `Cargo.toml`):
 
 ```rust,noplayground
 {{#include ../../examples/fibonacci-io/script/build.rs}}
@@ -28,3 +30,14 @@ Make sure to also add `sp1-helper` as a build dependency in `script/Cargo.toml`:
 [build-dependencies]
 sp1-helper = { git = "https://github.com/succinctlabs/sp1.git" }
 ```
+
+If you run `RUST_LOG=info cargo run --release -vv`, you will see the following output from the build script if the program has changed, indicating that the program was rebuilt:
+```
+[fibonacci-script 0.1.0] cargo:rerun-if-changed=../program/src
+[fibonacci-script 0.1.0] cargo:rerun-if-changed=../program/Cargo.toml
+[fibonacci-script 0.1.0] cargo:rerun-if-changed=../program/Cargo.lock
+[fibonacci-script 0.1.0] cargo:warning=fibonacci-program built at 2024-03-02 22:01:26
+[fibonacci-script 0.1.0] [sp1]    Compiling fibonacci-program v0.1.0 (/Users/umaroy/Documents/fibonacci/program)
+[fibonacci-script 0.1.0] [sp1]     Finished release [optimized] target(s) in 0.15s
+warning: [email protected]: fibonacci-program built at 2024-03-02 22:01:26```
+``````

book/writing-programs/cycle-tracking.md

@@ -0,0 +1,40 @@
+# 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:
+
+```rust,noplayground
+{{#include ../../examples/cycle-tracking/program/src/main.rs}}
+```
+
+Note that to use the macro, you must add the `sp1-derive` crate to your dependencies for your program.
+
+```toml
+[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=info cargo run --release`. You should see the following output:
+
+```
+$ RUST_LOG=info cargo run --release
+    Finished release [optimized] target(s) in 0.61s
+    Running `target/release/cycle-tracking-script`
+2024-03-02T19:47:07.490898Z  INFO runtime.run(...):load memory: close time.busy=280µs time.idle=3.92µs
+2024-03-02T19:47:07.491085Z  INFO runtime.run(...): ┌╴setup
+2024-03-02T19:47:07.491531Z  INFO runtime.run(...): └╴4,398 cycles
+2024-03-02T19:47:07.491570Z  INFO runtime.run(...): ┌╴main-body
+2024-03-02T19:47:07.491607Z  INFO runtime.run(...): │ ┌╴expensive_function
+2024-03-02T19:47:07.491886Z  INFO runtime.run(...): │ └╴1,368 cycles
+2024-03-02T19:47:07.492045Z  INFO runtime.run(...): stdout: result: 5561
+2024-03-02T19:47:07.492112Z  INFO runtime.run(...): │ ┌╴expensive_function
+2024-03-02T19:47:07.492358Z  INFO runtime.run(...): │ └╴1,368 cycles
+2024-03-02T19:47:07.492501Z  INFO runtime.run(...): stdout: result: 2940
+2024-03-02T19:47:07.492560Z  INFO runtime.run(...): └╴5,766 cycles
+2024-03-02T19:47:07.494178Z  INFO runtime.run(...):postprocess: close time.busy=1.57ms time.idle=625ns
+```
+
+Note that we elegantly handle nested cycle tracking, as you can see above.

book/writing-programs/patched-crates.md

@@ -29,7 +29,7 @@ sha2-v0-10-8 = { git = "https://github.com/sp1-patches/RustCrypto-hashes", packa
 curve25519-dalek = { git = "https://github.com/sp1-patches/curve25519-dalek", branch = "patch-v4.1.1" }
 curve25519-dalek-ng = { git = "https://github.com/sp1-patches/curve25519-dalek-ng", branch = "patch-v4.1.1" }
 ed25519-consensus = { git = "https://github.com/sp1-patches/ed25519-consensus", branch = "patch-v2.1.0" }
-tiny-keccak = { git = "https://github.com/succinctlabs/tiny-keccak-private", branch = "patch-v2.0.2" }
+tiny-keccak = { git = "https://github.com/sp1-patches/tiny-keccak", branch = "patch-v2.0.2" }
 revm = { git = "https://github.com/sp1-patches/revm", branch = "patch-v5.0.0" }
 reth-primitives = { git = "https://github.com/sp1-patches/reth", default-features = false, branch = "sp1-reth" }
 ```
@@ -65,3 +65,36 @@ cargo tree -p [email protected]
 ```
 
 Next to the package name, it should have a link to the Github repository that you patched with.
+
+**Checking whether a precompile is used**
+
+To check if a precompile is used by your program, when running the script to generate a proof, make sure to use the `RUST_LOG=info` environment variable and set up `utils::setup_logger()` in your script. Then, when you run the script, you should see a log message like the following:
+
+```bash
+2024-03-02T19:10:39.570244Z  INFO runtime.run(...): ... 
+2024-03-02T19:10:39.570244Z  INFO runtime.run(...): ... 
+2024-03-02T19:10:40.003907Z  INFO runtime.prove(...): Sharding the execution record.
+2024-03-02T19:10:40.003916Z  INFO runtime.prove(...): Generating trace for each chip.
+2024-03-02T19:10:40.003918Z  INFO runtime.prove(...): Record stats before generate_trace (incomplete): ShardStats {
+    nb_cpu_events: 7476561,
+    nb_add_events: 2126546,
+    nb_mul_events: 11116,
+    nb_sub_events: 54075,
+    nb_bitwise_events: 646940,
+    nb_shift_left_events: 142595,
+    nb_shift_right_events: 274016,
+    nb_divrem_events: 0,
+    nb_lt_events: 81862,
+    nb_field_events: 0,
+    nb_sha_extend_events: 0,
+    nb_sha_compress_events: 0,
+    nb_keccak_permute_events: 2916,
+    nb_ed_add_events: 0,
+    nb_ed_decompress_events: 0,
+    nb_weierstrass_add_events: 0,
+    nb_weierstrass_double_events: 0,
+    nb_k256_decompress_events: 0,
+}
+```
+
+The `ShardStats` struct contains the number of events for each "table" from the execution of the program, including precompile tables. In the example above, the `nb_keccak_permute_events` field is `2916`, indicating that the precompile for the Keccak permutation was used. 

cli/src/assets/.vscode/settings.json

@@ -0,0 +1,25 @@
+{
+    "editor.inlineSuggest.enabled": true,
+    "[rust]": {
+        "editor.defaultFormatter": "rust-lang.rust-analyzer",
+    },
+    "editor.rulers": [
+        100
+    ],
+    "rust-analyzer.check.overrideCommand": [
+        "cargo",
+        "clippy",
+        "--workspace",
+        "--message-format=json",
+        "--all-features",
+        "--all-targets",
+        "--",
+        "-A",
+        "incomplete-features"
+    ],
+    "rust-analyzer.linkedProjects": [
+        "program/Cargo.toml",
+        "script/Cargo.toml",
+    ],
+    "rust-analyzer.showUnlinkedFileNotification": false
+}

cli/src/assets/script/Cargo.toml

@@ -6,3 +6,6 @@ edition = "2021"
 
 [dependencies]
 sp1-core = { git = "https://github.com/succinctlabs/sp1.git" }
+
+[build-dependencies]
+sp1-helper = { git = "https://github.com/succinctlabs/sp1.git" }

cli/src/assets/script/build.rs

@@ -0,0 +1,5 @@
+use sp1_helper::build_program;
+
+fn main() {
+    build_program("../program")
+}

cli/src/commands/new.rs

@@ -8,7 +8,9 @@ const PROGRAM_MAIN_RS: &str = include_str!("../assets/program/main.rs");
 const SCRIPT_CARGO_TOML: &str = include_str!("../assets/script/Cargo.toml");
 const SCRIPT_MAIN_RS: &str = include_str!("../assets/script/main.rs");
 const SCRIPT_RUST_TOOLCHAIN: &str = include_str!("../assets/script/rust-toolchain");
+const SCRIPT_BUILD_RS: &str = include_str!("../assets/script/build.rs");
 const GIT_IGNORE: &str = include_str!("../assets/.gitignore");
+const VS_CODE_SETTINGS_JSON: &str = include_str!("../assets/.vscode/settings.json");
 
 #[derive(Parser)]
 #[command(name = "new", about = "Setup a new project that runs inside the SP1.")]
@@ -44,10 +46,18 @@ impl NewCmd {
         )?;
         fs::write(script_root.join("src").join("main.rs"), SCRIPT_MAIN_RS)?;
         fs::write(script_root.join("rust-toolchain"), SCRIPT_RUST_TOOLCHAIN)?;
+        fs::write(script_root.join("build.rs"), SCRIPT_BUILD_RS)?;
 
         // Add .gitignore file to root.
         fs::write(root.join(".gitignore"), GIT_IGNORE)?;
 
+        // Add .vscode/settings.json to root.
+        fs::create_dir(root.join(".vscode"))?;
+        fs::write(
+            root.join(".vscode").join("settings.json"),
+            VS_CODE_SETTINGS_JSON,
+        )?;
+
         println!(
             "    \x1b[1m{}\x1b[0m {} ({})",
             Paint::green("Initialized"),

core/src/runtime/mod.rs

@@ -67,9 +67,15 @@ pub struct Runtime {
     /// A counter for the number of cycles that have been executed in certain functions.
     pub cycle_tracker: HashMap<String, (u32, u32)>,
 
+    /// A buffer for stdout and stderr IO.
+    pub io_buf: HashMap<u32, String>,
+
     /// A buffer for writing trace events to a file.
     pub trace_buf: Option<BufWriter<File>>,
 
+    /// Whether the runtime should fail on panic or not.
+    pub fail_on_panic: bool,
+
     /// Whether the runtime is in constrained mode or not.
     /// In unconstrained mode, any events, clock, register, or memory changes are reset after leaving
     /// the unconstrained block. The only thing preserved is writes to the input stream.
@@ -103,7 +109,9 @@ impl Runtime {
             cpu_record: CpuRecord::default(),
             shard_size: env::shard_size() as u32 * 4,
             cycle_tracker: HashMap::new(),
+            io_buf: HashMap::new(),
             trace_buf,
+            fail_on_panic: true,
             unconstrained: false,
             unconstrained_state: ForkState::default(),
             syscall_map: default_syscall_map(),
@@ -822,6 +830,20 @@ impl Runtime {
         if let Some(ref mut buf) = self.trace_buf {
             buf.flush().unwrap();
         }
+        // Flush remaining stdout/stderr
+        for (fd, buf) in self.io_buf.iter() {
+            if !buf.is_empty() {
+                match fd {
+                    1 => {
+                        println!("[stdout] {}", buf);
+                    }
+                    2 => {
+                        println!("[stderr] {}", buf);
+                    }
+                    _ => {}
+                }
+            }
+        }
 
         // Call postprocess to set up all variables needed for global accounts, like memory
         // argument or any other deferred tables.

core/src/syscall/halt.rs

@@ -10,6 +10,13 @@ impl SyscallHalt {
 
 impl Syscall for SyscallHalt {
     fn execute(&self, ctx: &mut SyscallContext) -> u32 {
+        let exit_code = ctx.register_unsafe(Register::X10);
+        if ctx.rt.fail_on_panic && exit_code != 0 {
+            panic!(
+                "RISC-V runtime halted during program execution with non-zero exit code {}. This likely means your program panicked during execution.",
+                exit_code
+            );
+        }
         ctx.set_next_pc(0);
         ctx.register_unsafe(Register::X10)
     }

core/src/syscall/write.rs

@@ -56,11 +56,21 @@ impl Syscall for SyscallWrite {
                         u32_to_comma_separated(rt.state.global_clk - start)
                     );
                 } else {
-                    log::info!("stdout: {}", s.trim_end());
+                    let flush_s = update_io_buf(ctx, fd, s);
+                    if !flush_s.is_empty() {
+                        flush_s
+                            .into_iter()
+                            .for_each(|line| println!("[stdout] {}", line));
+                    }
                 }
             } else if fd == 2 {
                 let s = core::str::from_utf8(slice).unwrap();
-                log::info!("stderr: {}", s.trim_end());
+                let flush_s = update_io_buf(ctx, fd, s);
+                if !flush_s.is_empty() {
+                    flush_s
+                        .into_iter()
+                        .for_each(|line| println!("[stderr] {}", line));
+                }
             } else if fd == 3 {
                 rt.state.output_stream.extend_from_slice(slice);
             } else if fd == 4 {
@@ -72,3 +82,22 @@ impl Syscall for SyscallWrite {
         0
     }
 }
+
+pub fn update_io_buf(ctx: &mut SyscallContext, fd: u32, s: &str) -> Vec<String> {
+    let rt = &mut ctx.rt;
+    let entry = rt.io_buf.entry(fd).or_default();
+    entry.push_str(s);
+    if entry.contains('\n') {
+        // Return lines except for the last from buf.
+        let prev_buf = std::mem::take(entry);
+        let mut lines = prev_buf.split('\n').collect::<Vec<&str>>();
+        let last = lines.pop().unwrap_or("");
+        *entry = last.to_string();
+        lines
+            .into_iter()
+            .map(|line| line.to_string())
+            .collect::<Vec<String>>()
+    } else {
+        vec![]
+    }
+}