Feat: Vm Profiling #1789

nhtyy · 2024-11-14T00:44:55Z

Building on a previous PR #1713

The logic to preserve the callstack is now done during execution (debug only)
and by default the trace file is now a gecko profile json, which can opened via samply load ...

book/developers/profiling.md

yuwen01

overall looks pretty good, made some small comments about cleaning up docs

book/developers/profiling.md

crates/core/executor/src/profiler.rs

nhtyy · 2024-11-14T22:54:17Z

@yuwen01 the CLI CI test seems to be failing silently here.. Wdyt?

yuwen01

Left some doc comments, but logic is pretty clear now thanks to your comments. You can check that your changes to the book look good by running mdbook serve from the sp1 root directory

book/developers/profiling.md

book/writing-programs/cycle-tracking.md

crates/core/executor/src/profiler.rs

book/writing-programs/cycle-tracking.md

examples/fibonacci/trace.json

crates/core/executor/src/profiler.rs

ctian1 · 2024-11-18T17:58:02Z

book/writing-programs/cycle-tracking.md

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


IMO this doc could be a bit clearer and friendlier. The title should be something like "Profiling a zkVM Program", and then it should explain what that means and give a sample firefox URL and maybe a screenshot. To explain how to use it, we should make it clear that you just need to set some env vars while ProverClient.execute is called, and then call a samply command. Then we can explain when you might want to adjust the sample rate (ex >100m cycles?).

It would also help to have a few lines about how to interpret the info in the profiler.

crates/core/executor/Cargo.toml

crates/prover/src/lib.rs

examples/fibonacci/trace.json

examples/rsp/script/trace.json

examples/rsp/trace.json

yuwen01

feature flagging profiling is WAY better than the debug assertions thing i like

in general, since everything we do is open source, we highly prioritize having clean code and docs. this pretty much involves

complete sentences whenever possible. sometimes, when describing struct fields, it's okay to not have a complete sentence. something like this

// The profiler.
profiler: whatever

is fine, but you should still use caps and punctuation. Especially when writing docs, also try not to use run-on sentences -- claude can probably catch a lot of these grammar mistakes.

yuwen01 · 2024-11-22T18:36:49Z

book/writing-programs/cycle-tracking.md


-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 is a good way to get an understanding of what is bottlenecking your program, note only one program may be profiled at a time.


nit: ... program. Note only ...

yuwen01 · 2024-11-22T18:37:13Z

book/writing-programs/cycle-tracking.md


-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 have to setup a script to execute the program, 


nit: ... program. Many examples ...

yuwen01 · 2024-11-22T18:38:43Z

book/writing-programs/cycle-tracking.md


-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.


nit: ... profile. It is the ...

yuwen01 · 2024-11-22T18:39:30Z

book/writing-programs/cycle-tracking.md

 ```
+


nit: capitalize Firefox, program's execution.

@ctian1 thoughts on a screenshot?

grammar mistake unsolved

yuwen01 · 2024-11-22T18:42:25Z

crates/core/executor/src/profiler.rs

+        let mut function_ranges = Vec::new();
+        let mut builder = ThreadBuilder::new(1, 0, std::time::Instant::now(), false, false);
+
+        // We need to extract all the functions from the elf file


yuwen01 · 2024-11-22T18:42:31Z

crates/core/executor/src/profiler.rs

+                let start_address = sym.st_value;
+                let end_address = start_address + size - 4;
+
+                // Now that we have the name lets immediately intern it so we only need to copy


yuwen01 · 2024-11-22T18:43:08Z

crates/core/executor/src/profiler.rs

+    Serde(#[from] serde_json::Error),
+}
+
+/// The ZKVM Profiler.


nit: use caps and punctuation in these doc comments

yuwen01 · 2024-11-22T18:43:19Z

crates/core/executor/src/profiler.rs

+            self.builder.add_sample(
+                last_known_time,
+                sample.stack.into_iter(),
+                // We don't have a way to know the duration of each sample, so we just use 1us for


yuwen01 · 2024-11-22T18:45:23Z

crates/core/executor/src/executor.rs

@@ -190,11 +192,52 @@ impl<'a> Executor<'a> {
        Self::with_context(program, opts, SP1Context::default())
    }

+    /// Crete a new runtime for the program, and setup the profiler if `TRACE_FILE` env var is set


nit spelling

yuwen01 · 2024-11-22T18:48:40Z

crates/core/executor/src/executor.rs

-    /// # Panics
-    ///
-    /// This function may panic if it fails to create the trace file if `TRACE_FILE` is set.
+    /// Note: This function *will not* set up the profiler.
    #[must_use]


to clarify, the purpose of this function now is solely to maintain backwards compatibility?

book/writing-programs/cycle-tracking.md

ctian1 · 2024-11-23T00:14:10Z

book/writing-programs/cycle-tracking.md

+![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, 


this is good, it would be nice to explain what each view in the profiler is and how to interpret it, like call tree (invert call stack), flame graph, the timeline at the top

like some people might not know how to read the flame graph, for example

or they might not know to invert call stack in order to find the most frequent functions

Co-authored-by: Chris T. <ctian.2001@gmail.com>

yuwen01

Some more comments on the docs

yuwen01 · 2024-11-26T01:54:17Z

book/writing-programs/cycle-tracking.md


+The full command to profile should look something like this


Maybe we should just provide an end-to-end example of how to profile the fibonacci example or something. Right now these docs are a bit redundant. For example, I don't really like the overview section at the top. If you explain stuff step by step in your main explanation, I think that will probably suffice

yuwen01 · 2024-11-26T01:55:23Z

book/writing-programs/cycle-tracking.md

 ```
+


grammar mistake unsolved

yuwen01 · 2024-11-26T01:57:47Z

book/writing-programs/cycle-tracking.md

+![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, 


yuwen01 · 2024-11-26T01:58:02Z

book/writing-programs/cycle-tracking.md

+![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, 


like some people might not know how to read the flame graph, for example

yuwen01 · 2024-11-26T01:58:22Z

book/writing-programs/cycle-tracking.md

+![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, 


or they might not know to invert call stack in order to find the most frequent functions

nhtyy force-pushed the n/profiling-in-executor branch 2 times, most recently from e04ad2b to 5e1c1b9 Compare November 14, 2024 00:52

yuwen01 reviewed Nov 14, 2024

View reviewed changes

book/developers/profiling.md Outdated Show resolved Hide resolved

nhtyy force-pushed the n/profiling-in-executor branch from 27923bd to a1a732c Compare November 14, 2024 18:22

yuwen01 reviewed Nov 14, 2024

View reviewed changes

book/developers/profiling.md Outdated Show resolved Hide resolved

crates/core/executor/src/profiler.rs Outdated Show resolved Hide resolved

crates/core/executor/src/profiler.rs Show resolved Hide resolved

crates/core/executor/src/profiler.rs Show resolved Hide resolved

nhtyy mentioned this pull request Nov 14, 2024

chore: deprecate cargo prove #1792

Merged

nhtyy force-pushed the n/profiling-in-executor branch 2 times, most recently from 9c5d7fc to 40b61fc Compare November 14, 2024 23:28

yuwen01 reviewed Nov 15, 2024

View reviewed changes

nhtyy force-pushed the n/profiling-in-executor branch 2 times, most recently from b5a3684 to 6b834d1 Compare November 16, 2024 00:24

yuwen01 reviewed Nov 18, 2024

View reviewed changes

examples/fibonacci/trace.json Outdated Show resolved Hide resolved

yuwen01 reviewed Nov 18, 2024

View reviewed changes

crates/core/executor/src/profiler.rs Outdated Show resolved Hide resolved

ctian1 requested changes Nov 18, 2024

View reviewed changes

nhtyy force-pushed the n/profiling-in-executor branch 7 times, most recently from 6ec9289 to 64417f6 Compare November 22, 2024 18:31

yuwen01 reviewed Nov 22, 2024

View reviewed changes

nhtyy force-pushed the n/profiling-in-executor branch 2 times, most recently from 846a2af to f4e042a Compare November 22, 2024 20:12

ctian1 reviewed Nov 23, 2024

View reviewed changes

nhtyy added 4 commits November 25, 2024 11:56

feat: profiling

bb681e1

fix: explain why we use samply

94d4460

chore: add screenshot, grammar/spelling

465d127

chore: add interpreting results section

3dbe1cb

nhtyy and others added 3 commits November 25, 2024 11:56

Update book/writing-programs/cycle-tracking.md

24b650d

Co-authored-by: Chris T. <ctian.2001@gmail.com>

Update book/writing-programs/cycle-tracking.md

8991870

Co-authored-by: Chris T. <ctian.2001@gmail.com>

fix: fmt

bb14e17

nhtyy force-pushed the n/profiling-in-executor branch from f7c2fa1 to bb14e17 Compare November 25, 2024 19:56

yuwen01 reviewed Nov 26, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Feat: Vm Profiling #1789

Feat: Vm Profiling #1789

nhtyy commented Nov 14, 2024

yuwen01 left a comment

nhtyy commented Nov 14, 2024

yuwen01 left a comment

ctian1 Nov 18, 2024

yuwen01 left a comment

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 26, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

yuwen01 Nov 22, 2024

ctian1 Nov 23, 2024

yuwen01 Nov 26, 2024

yuwen01 Nov 26, 2024

yuwen01 Nov 26, 2024

yuwen01 left a comment

yuwen01 Nov 26, 2024

yuwen01 Nov 26, 2024

yuwen01 Nov 26, 2024

yuwen01 Nov 26, 2024

yuwen01 Nov 26, 2024


		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 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:
		To profile a program, you have to setup a script to execute the program,


		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.

Feat: Vm Profiling #1789

Are you sure you want to change the base?

Feat: Vm Profiling #1789

Conversation

nhtyy commented Nov 14, 2024

yuwen01 left a comment

Choose a reason for hiding this comment

nhtyy commented Nov 14, 2024

yuwen01 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yuwen01 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yuwen01 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment