How to profile sBPF programs
contents
Profiling sBPF programs is very different from typical profiling. Most CPU profilers are "sampling" profilers,
which stop each thread every so often and ask "What are you doing right now? What does your call stack look like?", and then write that down to show you later. Linux's perf is the canonical example of a sampling profiler. The output here is a statistical representation of what your program is doing, so a given profile isn't easily reproducible on a complex program.
When writing a performant sBPF program, you don't really care about "how long" something takes in terms of wall-clock time. [1](1) Validator client devs actually do care about how long transactions take to execute. Thankfully, CU consumption & wall-clock latency are generally correlated. Your primary concern is "compute unit" (CU) consumption, where 1 CU == 1 sBPF instruction, with the exception of syscalls.
So what does this mean for profiling them? Well, if we install a few hooks in the VM, we can keep track of basically everything the program does with no overhead. From this, we'll get a deterministic representation of what our program is doing. This means that if we run the same profile 1,000 times, we'll get the same result every time, so even tiny micro-optimizations will be immediately noticeable!
here is what we built
There's a couple other sBPF profilers available right now.
- sBPF Profiler does support instrumentation across CPI [2](2) "Cross-program invocation". For Solana programs to talk to one another, the runtime has to create a new VM, load the callee program, and invoke the callee's entrypoint function in the same way that the caller was initialized. boundaries, but unfortunately the symbolication & call stack reconstruction is a bit weak. It also doesn't provide a standalone test harness, which in my opinion is super useful to have with your profiler.
- Quasar provides a really great test runner & program development framework, and its profiler has better symbolication than sBPF Profiler, but it only does static analysis on the ELFs which leaves a lot to be desired. [3](3) The Quasar profiler is great for optimizing binary size, which makes program deploys cheaper. Neither sBPF Profiler nor Seashell directly expose this type of information.
I've maintained my own test harness (which I think is great) for a while now, so it made sense that if I were to build a profiler, it should function as a pretty simple drop-in for consumers of the harness. I also wanted to get full symbolication (or as much as possible) and be able to see across CPI boundaries, so the CPI syscalls wouldn't show up as a huge amount of CU consumption with no information as to what it actually did.
Here's a profile of the program from this repo generated by sBPF profiler, Quasar, and Seashell.
Quasar's flamegraph is notably distinct. This is because Quasar does static analysis on all code in the ELF, and in the case of an Anchor program (which this is), there's a ton of proc-macro codegen cruft that actually isn't even executed for a lot of instructions. [4](4) There's a valuable lesson in here. If you are trying to write performant sBPF programs you probably do not want a ton of proc-macro codegen cruft in your compiled binary. Quasar's program framework & pinocchio are great options for building good programs.
On the other hand, the sBPF Profiler & Seashell outputs look pretty similar. The really cool thing about our flamegraph is that you can see every function that was called, even if the compiler inlined it!
We're able to do this because of DWARF.
an aside on dwarf
DWARF is kind of the textbook debugging format. If you compile something with clang/gcc and the -g flag, it'll include DWARF debug info in the binary. DWARF's job is to basically embed enough information in the binary that a debugger can figure out all sorts of things about a running program, like what a variable is named or where its value is stored.
The thing that we want out of DWARF is the DW_TAG_inlined_subroutine entries. These can tell us things like where an inlined function call was in the original source and what range of addresses the inlined function's instructions span. For obvious reasons, this is really useful for our profiling efforts.
Let's see this in action! We'll compile this program with cargo build and take a look at what DWARF gives us.
use std::hint::black_box;
#[inline(always)]
fn square(x: i32) -> i32 {
x * x
}
fn main() {
black_box(square(black_box(4)));
}
We need the black_boxes so the compiler doesn't fold everything to a noop when it notices we aren't using the result of square.
Once this is compiled, we can look at the generated ELF's DWARF info via llvm-dwarfdump, and we'll find this:
❯ llvm-dwarfdump --debug-info target/debug/playground | rg -B2 -A6 square
# all functions defined in a program have a "subprogram" entry
0x000003aa: DW_TAG_subprogram
DW_AT_name ("square")
DW_AT_decl_file ("src/main.rs")
DW_AT_decl_line (4)
DW_AT_type (0x3fe "i32")
DW_AT_inline (DW_INL_inlined)
# only functions that were inlined have a "subroutine" entry
0x000003df: DW_TAG_inlined_subroutine
DW_AT_abstract_origin (0x3aa "square")
DW_AT_low_pc (0x14eff) # where does function start inline?
DW_AT_high_pc (0x14f19) # where does function end inline?
DW_AT_call_line (9)
Great! We have a DW_TAG_inlined_subroutine entry, so the compiler correctly inlined square into main and didn't fold everything away.
For DW_TAG_inlined_subroutine, the fields DW_AT_low_pc and DW_AT_high_pc represent the addresses in the executable that contain the inlined function's body. Here we can see that DW_AT_low_pc = 0x14eff and DW_AT_high_pc = 0x14f19.
What instructions does the binary contain between 0x14eff and 0x14f19?
❯ objdump -d --start-address=0x14eff --stop-address=0x14f19 target/debug/playground
target/debug/playground: file format elf64-x86-64
Disassembly of section .text:
0000000000014eff <_ZN10playground4main17h1804aa1854293c5eE+0xf>:
14eff: imul %eax,%eax # this is our mul function!
14f02: mov %eax,(%rsp) # store the result
# do overflow checks, panic on overflow, etc.
14f05: seto %al
14f08: jo 14f0c
14f0a: jmp 14f19
14f0c: lea 0x40545(%rip),%rdi
14f13: call *0x42f97(%rip)
Without DWARF, our call graph for this binary would just be main. Now we know between 0x14eff and 0x14f19, we're in square, so our call graph is now main -> square. This is pretty neat!
the solana toolchain
Solana uses an LLVM fork to compile on chain programs. When you run cargo build-sbf, the toolchain will generate 2 binaries:
target/deploy/my_program.so. This binary is fully stripped bystrip=all, so it contains no.symtabor DWARF at all.sbf-solana-solana/release/my_program.so. This binary has debug info stripped bystrip=debuginfo, so we have.symtabbut no DWARF.
There's also a --debug option which generates a target/deploy/my_program.debug file containing no .text segment.
You'd think that the --debug option would generate DWARF.
➜ cargo build-sbf --debug
Finished `release` profile [optimized] target(s) in 0.12s
➜ objdump -h target/deploy/my_program.debug | grep debug
target/deploy/my_program.debug: file format elf64-unknown
Hm. Well, what if we try -g?
➜ RUSTFLAGS='-g' cargo build-sbf --debug
Finished `release` profile [optimized] target(s) in 0.12s
➜ objdump -h target/deploy/cpi_caller.debug | grep debug
target/deploy/cpi_caller.debug: file format elf64-unknown
As of Rust 1.77, release builds will enable strip=debuginfo by default. Since cargo build-sbf only builds release profiles, this will obviously not work.
Ok, so let's try to set -g -C debuginfo=2 -C strip=none.
➜ RUSTFLAGS="-C debuginfo=2 -C strip=none" cargo build-sbf --debug
Finished `release` profile [optimized] target(s) in 0.22s
➜ objdump -h target/deploy/cpi_caller.debug | grep debug
target/deploy/cpi_caller.debug: file format elf64-unknown
8 .debug_loc 00004818 0000000000000000 DEBUG
9 .debug_abbrev 00000740 0000000000000000 DEBUG
10 .debug_info 00007b4c 0000000000000000 DEBUG
11 .debug_aranges 00000120 0000000000000000 DEBUG
12 .debug_ranges 00002020 0000000000000000 DEBUG
13 .debug_str 00007b76 0000000000000000 DEBUG
14 .debug_frame 00000170 0000000000000000 DEBUG
15 .debug_line 00001a69 0000000000000000 DEBUG
Perfect! Now we have DWARF to use in our profiler.
..but only sometimes
On Solana toolchain versions < v1.51 the outputted DWARF is mangled beyond repair.
Let's see what that looks like.
#![no_std]
#[panic_handler]
fn panic(_: &core::panic::PanicInfo) -> ! {
loop {}
}
#[no_mangle]
pub extern "C" fn entrypoint(input: *mut u8) -> u64 {
let mut acc = 5u64;
{
let y = unsafe { core::ptr::read_volatile(input) } as u64;
acc += y;
unsafe { core::ptr::write_volatile(input, acc as u8) };
}
acc
}
We'll compile this against both platform-tools v1.50 (broken) and v1.51 (fixed) with cargo build-sbf. Both of these toolchains use rustc 1.84.1, only the linker differs.
Upon inspection of the DWARF, we can see this:
schema ┌───── address slot ──────┐ ┌─ size ─┐ ┌note┐ ┌─ name offset ─┐
v1.51 (good): 14 20 01 00 00 00 00 00 00 20 00 00 00 01 5a 83 02 00 00 ..
v1.50 (bad): 14 00 00 00 00 20 01 00 00 20 00 00 00 00 00 83 02 00 00 ..
These are DW_TAG_subprogram entries for the entrypoint function. Every function in a program compiled with DWARF enabled has a DW_TAG_subprogram entry, which contains information like what file & line a function definition is in the original source. If the function isn't inlined, it'll also tell us the address range that the function spans.
➜ nm target-v1.51/sbpf-solana-solana/release/dwarf_demo.so | grep entrypoint
0000000000000120 T entrypoint
➜ nm target-v1.50/sbpf-solana-solana/release/dwarf_demo.so | grep entrypoint
0000000000000120 T entrypoint
In both ELFs, the entrypoint function lives at 0x120, or 20 01. The good DWARF has the function address where it's supposed to be at the start of the entry. The bad DWARF has it shifted by 4 bytes. The address read naively here is about a trillion times too big, but we can just shift it back to get the actual address.
The problem is with the note section. v1.51 correctly generates 01 5a as the "note" on this entry. However, v1.50 has zeroed these bytes.
So what happened to them? The older toolchain versions mishandled .debug_info sections by applying R_BPF_64_64 relocations (meant for lddw instructions). This type of relocation puts the low 4 bytes of the immediate at addr+4, and the high 4 bytes of the immediate at addr+12, split across 2 8-byte instruction slots.
lddw ixn (what R_BPF_64_64 expects):
+0 +1 +2 +3 +4 +5 +6 +7
┌───┬───┬───┬───┬───┬───┬───┬───┐
│op │ │ │ │ imm low │
└───┴───┴───┴───┴───┴───┴───┴───┘
↑
addr+4
+8 +9 +10 +11 +12 +13 +14 +15
┌───┬───┬───┬───┬───┬───┬───┬───┐
│op │ │ │ │ imm high │
└───┴───┴───┴───┴───┴───┴───┴───┘
↑
addr+12
When the linker goes to fill in the blank left by the compiler at the .debug_info section for the entrypoint relocation, it sees that entrypoint lives at 0x120. This number is much smaller than 32 bits. So the linker puts the low half (which is all of it) at addr+4 and the high half (which is zero) at addr+12, stomping on this entry's note section.
This is recoverable though, because the note section on sBPF will always be 01 5a, so while llvm-dwarfdump chokes on this, we can fix it up in our symbolicator before trying to use it. [5](5) The reason that the name offset field isn't stomped on here is because string offsets have independent relocations, which overwrite the 00 00 written by the linker into the first two bytes of its range.
Here's the nasty part. The inner { let y ... } block in our program gets a DW_TAG_lexical_block entry in the DWARF. Let's look at what our toolchains emitted there.
schema ┌──── address slot ──────┐ ┌─ size ─┐ schema
v1.51 (good): 16 20 01 00 00 00 00 00 00 18 00 00 00 17 ..
v1.50 (bad): 16 00 00 00 00 20 01 00 00 18 00 00 00 00 ..
We have the same problem in the address slot as we did for the entrypoint record. That's ok, because we can just shift it back to figure out where it actually starts. [6]
The real issue is in the schema section. With the DW_TAG_subprogram entry, we were lucky enough that bytes 15 & 16 of the mishandled relocation were also subject to relocation, so the linker fixed its own mistake when it wrote the string relocation into the name offset section. Since the schema tag is not an address & is statically known by the compiler, nothing is going to save us from the linker having overwritten it. While we don't actually need the DW_TAG_lexical_block entries for our profiler, the first irreparable relocation bug prevents us from decoding all entries after it, including things we really want like our friend DW_TAG_inlined_subroutine from the last section.
This is because when you want to decode all DWARF info that a program has, you have to start at the first entry and go entry-by-entry until you get them all. The DIE "stream" has no indexes and no boundaries, so the only way to see what's at index N is to decode index 0...index N - 1. If an entry is unreadable because of a linker bug that wasn't fixed by a subsequent relocation pass, all entries after it are lost.
This is disastrous for our budding profiler efforts. Without DWARF information, we can't possibly hope to provide richer symbolication than what .symtab gives us, which is top-level functions only.
Thankfully, we have an escape hatch.
dwarf 5
The Rust compiler, by default, uses DWARF version 4. In DWARF versions < 5, the address info is stored inline within the .debug_info sections, and therefore relocations are applied directly to .debug_info. This is what caused our problems in the last section on older Solana toolchains.
In February 2017, DWARF version 5 was released. The key change for us between prior DWARF versions and v5 is that DWARF v5 no long stores addresses inline, but includes a new linker section called .debug_addr. The .debug_addr section is a tightly-packed list of 8-byte addresses, and the DIEs in .debug_info store indexes into the .debug_addr section rather than the addresses inline.
If we set -Z dwarf-version=5, we can build our program on platform-tools v1.50 like this:
RUSTC_BOOTSTRAP=1 RUSTFLAGS="-C debuginfo=2 -C strip=none -Z dwarf-version=5" \
cargo build-sbf --tools-version v1.50 --debug
and we can build on the newer versions like this:
RUSTFLAGS="-C debuginfo=2 -C strip=none -C dwarf-version=5" \
cargo build-sbf --tools-version v1.54 --debug
In DWARF 4, the linker's bad address relocations in .debug_info were the reason we couldn't make much use of the info. Now that addresses are stored in .debug_addr, the linker will perform (similarly bad) relocations there instead, leaving .debug_info unsullied. If we look at .debug_info between v1.50 and v1.51 when building with DWARF 5, we'll see that this is the case.
➜ shasum -a 256 v1.50.debug_info v1.51.debug_info
d328019643ffb6437069a800e5428bad01873db89150cfc89f2a08cd2cdd4e57 v1.50.debug_info
d328019643ffb6437069a800e5428bad01873db89150cfc89f2a08cd2cdd4e57 v1.51.debug_info
Super cool! Now that our DIE stream is parseable, llvm-dwarfdump should at least be able to emit something for our binary.
➜ llvm-dwarfdump --debug-info v1.50.demo.so | grep -B5 'DW_AT_name.*"entrypoint"'
0x00000374: DW_TAG_subprogram
DW_AT_low_pc (0x0000012000000000)
DW_AT_high_pc (0x0000012000000020)
DW_AT_frame_base (DW_OP_reg10)
DW_AT_name ("entrypoint")
There's good news and bad news here. We're finally able to get llvm-dwarfdump to not choke on our ELF, which is great. Unfortunately, it seems to think that our entrypoint starts at 0x0000012000000000 instead of 0x120. Astute readers may notice that 0x120 << 32 = 0x0000012000000000, which is the exact signature of the bad R_BPF_64_64 relocations. If we take a look at the .debug_addr section, this becomes very obvious:
┌───── entry: 0x120 ──────┐ ┌───── entry: 0x128 ──────┐
v1.51 (good): 20 01 00 00 00 00 00 00 28 01 00 00 00 00 00 00
v1.50 (bad): 00 00 00 00 20 01 00 00 00 00 00 00 28 01 00 00
While we could get some of the info back with DWARF 4 by just undoing the shift, the real problem was that the 00 00 high half of the relocation would stomp on essential & irrecoverable data. With v5, since all .debug_addr entries are relocated, and all the relocations are predictably & identically misapplied, we can repair everything by just shifting back! [7](7) Technically, only in SBPF versions <3. sBPF v3 ELFs place .text at MM_BYTECODE_START = 0x1_0000_0000, so all addresses are now > 2³², and if we shift those we'll get nonsense and end up throwing away tons of DIE subtrees. You can't build for sBPF v3 (correctly, at least) with any toolchain <1.53 anyway so this doesn't matter.
In our profiler's DWARF parser, we can get all the correct addresses from DWARF 5, compiled with any toolchain, like this:
fn unmangle_addr(x: u64, text_base: u64) -> u64 {
// special handling for sbpf v3
if x >= text_base {
return x;
}
(x >> 32).wrapping_add(x & 0xFFFF_FFFF)
}
Now we have fully-parseable DWARF info emitted by all toolchains, and we can finally get started on actually profiling something.
profiling
As we know, perf and other sampling profilers construct a statistical representation of a program's behavior. As opposed to sampling, instrumenting is very time-consuming and expensive on "normal" programs, so measurements can be disrupted by the instrumenter's overhead.
Thankfully, we don't really care about how long it takes for our programs to execute in the profiling environment. The VM defines exactly how expensive every operation is, so we should be able to figure out exactly where resources were spent. Sampling a deterministic view in an environment unencumbered by actual latency constraints would just be throwing away information for no reason.
So, what operations does the VM implement? There's really only two big ones:
- sBPF instruction execution. All sBPF instructions consume 1 compute unit. [8](8)
lddwreally should consume 2 compute units as it takes up 2 8-byte instruction slots. - Syscall execution. Syscalls vary in consumption but have statically known costs.
We also care about function call/return at the VM level and program enter/exit at the runtime level. These aren't really operations so much as boundaries that we use to build our call graph within a program & across CPI boundaries. Syscalls also double as a boundary (and as we'll find out, a pretty important one).
Our goal is to build a tree of boundaries, and within each boundary's node we want to know how many compute units that boundary consumed, who its children are, and who its parent is. [9](9) This is known as a "calling context tree", which is really just a call graph.
We'll define our node like this:
pub struct CctNode {
pub key: FrameKey,
pub parent: Option<usize>,
pub callsite_pc: Option<u64>,
pub self_cu: u64,
pub pc_cu: BTreeMap<u64, u64>,
pub children: BTreeMap<(Option<u64>, FrameKey), usize>,
}
So the root node will have no parent, the leaf nodes will have no children, and we'll be able to traverse from the parent node to any leaf node via a series of boundaries. For the most part, this is pretty trivial. We install some on_instruction, on_call, on_return, etc. hooks that add new nodes to our tree and we end up with a kinda ok looking call graph.
However, there's a couple problems that make it interesting.
inlined functions
If you remember the simple DWARF example program from earlier, the DW_TAG_inlined_subroutine entries allowed us to extend our call graph from just main to main -> square. What would happen if square called another function, multiply, which isn't inlined?
use std::hint::black_box;
#[inline(always)]
fn square(x: i32) -> i32 {
multiply(x, x)
}
#[inline(never)]
fn multiply(x: i32, y: i32) -> i32 {
x * y
}
fn main() {
black_box(square(black_box(4)));
}
Now we get the following assembly for this program:
❯ objdump -dC --no-show-raw-insn --disassemble=playground::main ./target/debug/playground
./target/debug/playground: file format elf64-x86-64
Disassembly of section .text:
0000000000014140 <playground::main>:
14140: push %rax
14141: mov $0x4,%edi
14146: call 141c0 <core::hint::black_box>
1414b: mov %eax,%esi
1414d: mov %esi,0x4(%rsp)
14151: mov %esi,%edi
14153: call 14170 <playground::multiply>
14158: mov %eax,%edi
1415a: call 141c0 <core::hint::black_box>
1415f: pop %rax
14160: ret
Without DWARF, we'd naively place a boundary at only the call to multiply, and thus our resulting call graph will just be main -> multiply.
If we look at the generated DWARF, however, we can see this:
❯ llvm-dwarfdump --debug-info target/debug/playground | rg -B2 -A6 "square"
0x0000002f: DW_TAG_subprogram
DW_AT_linkage_name ("square")
DW_AT_name ("square")
DW_AT_decl_file ("src/main.rs")
DW_AT_decl_line (4)
DW_AT_type (0xbd "i32")
DW_AT_inline (DW_INL_inlined)
0x00000064: DW_TAG_inlined_subroutine
DW_AT_abstract_origin (0x2f "square")
DW_AT_low_pc (0x14151)
DW_AT_high_pc (0x1415a)
DW_AT_call_line (14)
And between DW_AT_low_pc and DW_AT_high_pc, we'll know that we're in square. The call to multiply happens at 0x14153, within our square boundaries, and so we're able to correctly attribute multiply as a callee of square.
The way that we make this work in our profiler is by keeping track of the callsite_pc for a given boundary, which represents the address at which this boundary was triggered. Then, we can work backwards from the DWARF information to determine if this was actually a call made by an inlined function.
syscall accounting
When the sBPF interpreter encounters a syscall, it calls this function:
fn dispatch_syscall(&mut self, function: BuiltinFunction<C>) -> &ProgramResult {
self.vm.due_insn_count = self.vm.previous_instruction_meter - self.vm.due_insn_count;
self.vm.registers[0..6].copy_from_slice(&self.reg[0..6]);
self.vm.invoke_function(function);
self.vm.due_insn_count = 0;
&self.vm.program_result
}
Where the syscall to invoke is the function: BuiltinFunction<C> parameter. EbpfVm::invoke_function is a special function used to invoke a program's entrypoint & to invoke syscalls.
A syscall is a boundary, so we want to record when we enter the syscall, and we want to record when we exit the syscall. Naively, we might do something like this:
fn dispatch_syscall(&mut self, key: u32 /* name */, function: BuiltinFunction<C>) -> &ProgramResult {
self.vm.due_insn_count = self.vm.previous_instruction_meter - self.vm.due_insn_count;
self.vm.registers[0..6].copy_from_slice(&self.reg[0..6]);
// create a new boundary for syscall invocation & set current to this node
self.vm.context().on_syscall_enter(self.reg[11], key);
// figure out how many CUs we have left before syscall invoke
let remaining_before = self.vm.context().get_remaining();
self.vm.invoke_function(function);
// figure out how many CUs we have left after syscall invoke
let remaining_after = self.vm.context().get_remaining();
// assume that the syscall consumed remaining_before - remaining_after CUs
let syscall_cost = remaining_before.saturating_sub(remaining_after);
// record the cu consumption of this syscall and pop current to parent node
self.vm.context().on_syscall_exit(syscall_cost);
self.vm.due_insn_count = 0;
&self.vm.program_result
}
If we attribute CUs this way, and we check the invariant sum(all_nodes_self_cu) == actual_consumed_cu, we see a crazy amount of double-counting! Why?
All Solana transactions execute within some ProgramRuntimeEnvironment. This environment, created prior to transaction execution, principally serves to describe the set of syscalls that are available to the transaction. The creation of a ProgramRuntimeEnvironment basically looks like this:
pub fn create_program_runtime_environment(
feature_set: &SVMFeatureSet,
compute_budget: &SVMTransactionExecutionBudget,
reject_deployment_of_broken_elfs: bool,
debugging_features: bool,
) -> Result<ProgramRuntimeEnvironment, Error> {
// figure out correct config ...
let config = Config {
// initialize config ...
};
let mut result = BuiltinProgram::new_loader(config);
// register the abort syscall with the environment
SyscallAbort::register(&mut result, "abort")?;
// register more syscalls ...
Ok(ProgramRuntimeEnvironment::from(result))
}
Each syscall, defined as a BuiltinFunction, has a corresponding trait implementation of BuiltinFunctionDefinition.
The BuiltinFunctionDefinition trait exposes two key default methods: vm and register. BuiltinFunctionDefinition::vm serves as the bridge between sBPF's EbpfVm and the native Rust implementation of the syscall, while BuiltinFunctionDefinition::register is used in create_program_runtime_environment to make the syscall known to the EbpfVm. The syscall's Rust implementation is defined in BuiltinFunctionDefinition::rust, which has no default method.
Critically, BuiltinFunctionDefinition::register uses the BuiltinFunctionDefinition::vm wrapper for the Rust implementation as the syscall's body. This means that EbpfVm::invoke_function will execute the vm wrapper when invoked by dispatch_syscall.
When a syscall (such as SyscallAbort) is defined, the declare_builtin_function! macro is used. This macro requires the implementor to provide a fn rust override for BuiltinFunctionDefinition, and delegates the rest of that trait's functions to their defaults.
Here's what SyscallAbort's definition looks like:
declare_builtin_function!(
SyscallAbort,
fn rust(
_invoke_context: &mut InvokeContext<'_, '_>,
_arg1: u64,
_arg2: u64,
_arg3: u64,
_arg4: u64,
_arg5: u64,
) -> Result<u64, Error> {
Err(SyscallError::Abort.into())
}
);
You may be asking: Why does all this wiring matter? How does knowing this help us solve our double-counting problem?
Well, the runtime needs some way to keep track of all CUs consumed within a transaction, and a sensible place to reconcile VM executed instructions with runtime consumed CUs is at the syscall boundary. [10](10) CUs are also flushed on program enter / exit. So, within BuiltinFunctionDefinition::vm, we flush all CUs consumed since the last syscall like this:
let enable_insn_meter = vm.loader.get_config().enable_instruction_meter;
// this is always true on live clusters
if enable_insn_meter {
let used_cus = vm.previous_instruction_meter - vm.due_insn_count;
vm.context().consume(used_cus);
}
And the first line of dispatch_syscall changes the representation of due_insn_count from "what do we have to pay at the next flush" to "how much will we have left after this flush".
// within dispatch_syscall
self.vm.due_insn_count = self.vm.previous_instruction_meter - self.vm.due_insn_count;
The key part of this is that before the invoke_function call, all CUs consumed between the prior syscall and this one are still unknown to ContextObject::get_remaining. This means that our naive example, where we assume that remaining_before - remaining_after is the true cost of the syscall, is actually double-counting all consumption since the last syscall and attributing it to this one.
Fortunately, this is really easy to fix. Now that we understand this phenomenon, all we have to do is be cognizant of it when recording syscall CU consumption.
fn dispatch_syscall(&mut self, key: u32, function: BuiltinFunction<C>) -> &ProgramResult {
self.vm.due_insn_count = self.vm.previous_instruction_meter - self.vm.due_insn_count;
self.vm.registers[0..6].copy_from_slice(&self.reg[0..6]);
self.vm.context().on_syscall_enter(self.reg[11], key);
// figure out how many CUs are due for flush since the last syscall
// these CUs are not accounted for in `ContextObject::get_remaining`
let base_flush = self
.vm
.previous_instruction_meter
.saturating_sub(self.vm.due_insn_count);
// figure out how many CUs we have left before syscall invoke
let remaining_before = self.vm.context().get_remaining();
self.vm.invoke_function(function);
// figure out how many CUs we have left after syscall invoke
let remaining_after = self.vm.context().get_remaining();
// syscall cost = remaining_before - remaining_after - flushed within invoke_function
let syscall_cost = remaining_before
.saturating_sub(remaining_after)
.saturating_sub(base_flush);
self.vm.context().on_syscall_exit(syscall_cost);
self.vm.due_insn_count = 0;
&self.vm.program_result
}
Now if we check our invariant sum(all_nodes_self_cu) == actual_consumed_cu again, it holds!
conclusion
This is pretty cool. Despite the best efforts of the toolchain developers, we've successfully built an sBPF profiler that actually works.
Having good profiling makes writing highly performant Solana programs 1000x easier, and I think it's essential for most nontrivial program dev work at this point. Don't get caught by resource fees!
using it yourself
If you are interested in using this, Seashell is actively maintained and you can find it on my GitHub.
The example repo used for the profiles generated in this blog post can be found here.
The example repo for the DWARF debacle can be found here.
Validator client devs actually do care about how long transactions take to execute. Thankfully, CU consumption & wall-clock latency are generally correlated. ↩︎
"Cross-program invocation". For Solana programs to talk to one another, the runtime has to create a new VM, load the callee program, and invoke the callee's entrypoint function in the same way that the caller was initialized. ↩︎
The Quasar profiler is great for optimizing binary size, which makes program deploys cheaper. Neither sBPF Profiler nor Seashell directly expose this type of information. ↩︎
There's a valuable lesson in here. If you are trying to write performant sBPF programs you probably do not want a ton of proc-macro codegen cruft in your compiled binary. Quasar's program framework & pinocchio are great options for building good programs. ↩︎
The reason that the name offset field isn't stomped on here is because string offsets have independent relocations, which overwrite the
00 00written by the linker into the first two bytes of its range. ↩︎You may be asking why the lexical block & the entrypoint start at the same address. The compiler folded
let mut acc = 5u64;into the accumulator atacc += y, so the generated assembly looks like this:
↩︎0x120: ldxb r0, [r1 + 0x0] 0x128: add64 r0, 0x5 # folded! 0x130: stxb [r1+ 0x0], r0 0x138: exitTechnically, only in SBPF versions <3. sBPF v3 ELFs place
.textatMM_BYTECODE_START = 0x1_0000_0000, so all addresses are now > 2³², and if we shift those we'll get nonsense and end up throwing away tons of DIE subtrees. You can't build for sBPF v3 (correctly, at least) with any toolchain <1.53 anyway so this doesn't matter. ↩︎lddwreally should consume 2 compute units as it takes up 2 8-byte instruction slots. ↩︎This is known as a "calling context tree", which is really just a call graph. ↩︎
CUs are also flushed on program enter / exit. ↩︎