SBPF code coverage and debugger tooling

[Lichtso]

Aggregating the discussions in anza-xyz/sbpf#67 and #7569 here.

[procdump]

Continuing the discussion from here.
And as the name of the discussion implies you guys are settling on the approach proposed here.
Do you have any hints in mind how to improve the accuracy of the code coverage results as alluded to here - catching ? in Rust, handling properly chained operations, some executed lines are showed uncovered, branching?
Since you're working this on top of master it won't allow us to test with litesvm currently as it's tied to 2.3. What's the suggested setup for a testing environment then?

[smoelius]

Do you have any hints in mind how to improve the accuracy of the code coverage results as alluded to #7569 (comment) - catching ? in Rust, handling properly chained operations, some executed lines are showed uncovered, branching?

In the screenshot you shared in #7569 (comment), a red ? is one that did not cause a return?

I can see that being useful. There is DWARF information that anchor-coverage throws away (e.g., column information). I can look into whether that could be incorporated into its output to show things like ? that do not cause returns.

Since you're working this on top of master it won't allow us to test with litesvm currently as it's tied to 2.3. What's the suggested setup for a testing environment then?

In #7569 (comment), you said you were able to make it work with LiteSVM 0.6.1 on Solana 2.1.20. Can I ask what you did to make it work?

[procdump]

In the screenshot you shared in #7569 (comment), a red ? is one that did not cause a return?

Yes.

In #7569 (comment), you said you were able to make it work with LiteSVM 0.6.1 on Solana 2.1.20. Can I ask what you did to make it work?

Here's the example vault program repository that has everything wrapped up so that you can inspect the code coverage output easily.

git clone -b anchor_coverage_dwarf https://github.com/LimeChain/anchor-coverage-example.git

I see you've rebased sbpf-coverage to solana-sbpf 0.12.2 . Please, have in mind that the example from the link uses your previous rebase to solana-sbpf 0.10.0 for two reasons - firstly it's the same version that's used in litesvm 0.6.1 and it's the one that I've managed to wrap everything to work with. Here's what I think was breaking things in the first place.

[smoelius]

Can I copy the following text (from here) into a GitHub issue?

The accuracy of the results must be improved:

- `?` in Rust
- chained operations
- some executed lines are reported as uncovered or as to be hit erroneous number of times
- branching

Here's what I think was breaking things in the first place.

Could you expand on that? What broke and why do you think that code caused it?

[procdump]

Can I copy the following text (from here) into a GitHub issue?

The accuracy of the results must be improved:

- `?` in Rust
- chained operations
- some executed lines are reported as uncovered or as to be hit erroneous number of times
- branching

Sure.

Here's what I think was breaking things in the first place.

Could you expand on that? What broke and why do you think that code caused it?

If addr2line's find_location fails once for at least one virtual address then code was treating it as an error and then followed the error path and eventually there wouldn't be any lcov files to work with for the coverage generation.

[procdump]

If addr2line's find_location fails once for at least one virtual address then code was treating it as an error and then followed the error path and eventually there wouldn't be any lcov files to work with for the coverage generation.

After conducting some tests it seems this change isn't necessary at all when using the Solana toolchain from 2.1.20 so I'll have it reverted.

[procdump]

I'd like to add a few remarks that do seem more like tough obstacles to overcome with this approach.

First of all, in order to reduce byte code size and CUs Solana programs are aggressively optimized upon compilation. Moreover some functions result inlined and the SBPF code coverage generator remain blind for them. Setting opt-level = 0 to disable optimizations comes next to mind and it seems that statistics are slightly more accurate. Yes, a Solana program may compile but there are error-like warnings of this kind:

Error: programs/vault/src/lib.rs:12:1 Function _ZN5vault9__private5__idl14__idl_dispatch17h4ec7e837dde08b48E Stack offset of 4568 exceeded max offset of 4096 by 472 bytes, please minimize large stack variables. Estimated function frame size: 4904 bytes. Exceeding the maximum stack offset may cause undefined behavior during execution.

Error: A function call in method _ZN4sha26sha5124soft23sha512_digest_block_u6417ha80f68336056f090E overwrites values in the frame. Please, decrease stack usage or remove parameters from the call.The function call may cause undefined behavior during execution.

Is it viable to allow bigger than 4k stack frames for Solana programs compiled without optimizations? And this would be only in the case when trying to get more accurate code coverage statistics? Probably there's a better approach?

[LucasSte]

Is it viable to allow bigger than 4k stack frames for Solana programs compiled without optimizations?

To circumvent the stack problem, we released SBPFv1 with dynamic stack frames. To use it, run cargo-build-sbf --arch v1. The difference between a v1 and a v0 program will be an extra instruction to adjust the stack pointer for functions that need stack space.

And this would be only in the case when trying to get more accurate code coverage statistics?

The optimizations you are describing are a common problem for every optimizing compiler, wherein many functions will be inlined and transformed.

Probably there's a better approach?

LLVM offers instrumentation based code coverage (see https://releases.llvm.org/12.0.0/docs/CoverageMappingFormat.html), which is a common approach for calculating coverage in code bases. SBPF is not compatible with that.

[procdump]

To circumvent the stack problem, we released SBPFv1 with dynamic stack frames. To use it, run cargo-build-sbf --arch v1. The difference between a v1 and a v0 program will be an extra instruction to adjust the stack pointer for functions that need stack space.

This has been added in Solana 2.2.x. However I've only managed to make the SBPF coverage vault example work with 2.1.x (particularly 2.1.20). So in order to try building the program with dynamic stack frames my next step was to try to jump to 2.2.x or 2.3.x but unfortunately the addr2line/gimli crates don't seem to work with the SBPF debug information built along the vault program. The first difference between 2.1.x and 2.2.x I've spotted is the migration to a new Machine type in the ELF header:

llvm-readelf -h 2.1.20/vault.debug | grep -i Machine
llvm-readelf: warning: '2.1.20/vault.debug': no valid dynamic table was found
Machine:                           EM_BPF

llvm-readelf -h 2.2.20/vault.debug | grep -i Machine
llvm-readelf: warning: '2.2.20/vault.debug': no valid dynamic table was found
Machine:                           107

Solana 2.2.x and 2.3.x built programs make llvm-addr2line emit warnings like this:

llvm-addr2line -f -e 2.2.20/vault.debug  -i 0x85f8
warning: DWARF unit at offset 0x0012bf04 contains invalid abbreviation 56 at offset 0x0012d19f, valid abbreviations are 1-54
...

Probably this is an expected behavior since the machine type has changed and the standard llvm tools can't handle it correctly?

Can you provide some clarification what has changed in the DWARF abbreviation definitions since 2.2.x?
The main question however is whether the addr2line / gimli crates are expected work with the SBPF debug symbols as they're the core to getting the mapping from a program counter to a Rust line of code?

I may be wrong here but LiteSVM is tied to solana-program-runtime which is tied to the legacy SBPFVersion::V0 format. Doesn't it automatically deprive us of the ability to use dynamic stack frames in this setup in the first place?

[LucasSte]

You don't need to update the versions on your code to match the CLI version. They are independent. You can use the newer CLI to build your program and execute with the old and use old versions in your Cargo.toml file.

Solana 2.2.x and 2.3.x built programs make llvm-addr2line emit warnings like this:

This is a bug in the platform tools that was fixed in version v1.51. Again, you don't need to update your code or change the CLI. To use the new version, do cargo-build-sbf --tools-version v1.51.

[LucasSte]

The first difference between 2.1.x and 2.2.x I've spotted is the migration to a new Machine type in the ELF header:

There is a new machine type, but it shouldn't make a difference. If the warning annoys you, you can use the Solana provided readelf in .cache/solana/v1.51/platform-tools/llvm/bin/llvm-readelf.

[LucasSte]

I may be wrong here but LiteSVM is tied to solana-program-runtime which is tied to the legacy SBPFVersion::V0 format. Doesn't it automatically deprive us of the ability to use dynamic stack frames in this setup in the first place?

That value you pointed is a dummy to invoke the bpf loader. The vm to execute the program is created inside the bpf loader:

agave/programs/bpf_loader/src/lib.rs

Lines 278 to 284 in e9670b6

	Ok(EbpfVm::new(
	program.get_loader().clone(),
	program.get_sbpf_version(),
	invoke_context,
	memory_mapping,
	stack_size,
	))

[LucasSte]

The main question however is whether the addr2line / gimli crates are expected work with the SBPF debug symbols as they're the core to getting the mapping from a program counter to a Rust line of code?

Do you mean importing addr2lin and gimli to a Solana program? If you are using them to read SBF DWARF, I think everything would be fine. There was a bug in DWARF generation that was fixed recently.

[procdump]

You don't need to update the versions on your code to match the CLI version. They are independent. You can use the newer CLI to build your program and execute with the old and use old versions in your Cargo.toml file.

Solana 2.2.x and 2.3.x built programs make llvm-addr2line emit warnings like this:

This is a bug in the platform tools that was fixed in version v1.51. Again, you don't need to update your code or change the CLI. To use the new version, do cargo-build-sbf --tools-version v1.51.

Got it, I've extended the anchor coverage wrapper cli (@smoelius) to take into account two environment variables so that the SBPF and the platform-tools versions can be set. It seems even most recent Solana versions ship with v1.48 though and maybe you have some reason behind this:

$ cargo-build-sbf --help
solana-cargo-build-sbf 2.3.8
platform-tools v1.48
rustc 1.84.1

Now in the vault app setup if optimizations are disabled (for this to be possible the SBPFVersion 1 must be used to take advantage of dynamic stack frames) the accuracy of the code coverage results is improved. There is still work to be done tough.

I may be wrong here but LiteSVM is tied to solana-program-runtime which is tied to the legacy SBPFVersion::V0 format. Doesn't it automatically deprive us of the ability to use dynamic stack frames in this setup in the first place?

That value you pointed is a dummy to invoke the bpf loader. The vm to execute the program is created inside the bpf loader:

agave/programs/bpf_loader/src/lib.rs

Lines 278 to 284 in e9670b6

	Ok(EbpfVm::new(
	program.get_loader().clone(),
	program.get_sbpf_version(),
	invoke_context,
	memory_mapping,
	stack_size,
	))

Now I got it. Thanks for the clarification.

The main question however is whether the addr2line / gimli crates are expected work with the SBPF debug symbols as they're the core to getting the mapping from a program counter to a Rust line of code?

Do you mean importing addr2lin and gimli to a Solana program? If you are using them to read SBF DWARF, I think everything would be fine. There was a bug in DWARF generation that was fixed recently.

Not importing but just using them to read the SBF DWARF. I can confirm that with platform-tools v1.51 they seem to work.

I've also updated the vault program example so that further improvements can be investigated and played with.

[smoelius]

Can you provide some clarification what has changed in the DWARF abbreviation definitions since 2.2.x?

A bug in Solana rustc's DWARF generation code was fixed in this PR: anza-xyz/llvm-project#159

I think that's what @LucasSte was referring to in #7569 (comment), and that's what you're seeing.

The fix appears in Solana platform tools 1.51.

I suspect it would be possible to patch an earlier version of the platform tools, but I haven't tried.

[procdump]

As @smoelius has pointed out here, the pcs must somehow reach out to the parsing application - either being written to files as he had implemented it, or possibly through some IPC which could allow for many consumers to get to them. Maybe writing to files is a good approach to start with?

[Lichtso]

Now that we added an environment variable for the remote debugger (VM_DEBUG_PORT) in anza-xyz/sbpf#69, how about we do the same (e.g. VM_TRACE_DIR) for the instruction trace in anza-xyz/sbpf#67?

[procdump]

Now that we added an environment variable for the remote debugger (VM_DEBUG_PORT) in anza-xyz/sbpf#69, how about we do the same (e.g. VM_TRACE_DIR) for the instruction trace in anza-xyz/sbpf#67?

I've just filed a PR to allow for exporting the instruction trace from LiteSVM. here
As it seems the answer is already in place - we're settling on the approach where the export is done directly in solana-sbpf.
So far it's the 12 registers that will get exported - not just the program counter. However in order to judge for branch code coverage the executed instruction is also mandatory to be exported as @smoelius had proposed it in the first place.

[Lichtso]

I re-opened anza-xyz/sbpf#71 with only the move of the instruction trace from the ContextObject to the EbpfVM. @smoelius and @procdump let me know if that is an issue for your endeavors.

[smoelius]

Thanks very much for asking. On the face of it, this doesn't affect me.

[procdump]

I re-opened anza-xyz/sbpf#71 with only the move of the instruction trace from the ContextObject to the EbpfVM. @smoelius and @procdump let me know if that is an issue for your endeavors.

Just for a reference here, I've started wrapping up the VM_TRACE_DIR code on top of what you did - anza-xyz/sbpf#72. I'm open to comments and suggestions.

[0xalpharush]

Beyond having the parsed instruction alongside the register trace (anza-xyz/sbpf#71), it would also be nice to have the program ID of the executing program. To recover this currently, I have to do something like the following:

            let cpi_instructions = &meta.inner_instructions;
            let msg = transaction.message;
            let msg_keys = msg.static_account_keys();
            // Resolve which program is being executed for each frame in the trace
            let mut program_id_invocation_order = Vec::new();
            for (ix_idx, cpi_ixs) in cpi_instructions.iter().enumerate() {
                let top_level_program_id = msg.instructions()[ix_idx].program_id(msg_keys); 
                program_id_invocation_order.push(top_level_program_id);
                for inner_ix in cpi_ixs {
                    program_id_invocation_order.push(inner_ix.instruction.program_id(msg_keys));
                }
            }
            if program_id_invocation_order.is_empty() {
                program_id_invocation_order.push(msg.instructions().first().expect("No instructions in message").program_id(msg_keys));
            }

Fwiw, I also resorted to forking sbpf to avoid tracing every instruction in favor of tracing JMP class opcodes only.

[procdump]

Beyond having the parsed instruction alongside the register trace (anza-xyz/sbpf#71), it would also be nice to have the program ID of the executing program. To recover this currently, I have to do something like the following:

            let cpi_instructions = &meta.inner_instructions;
            let msg = transaction.message;
            let msg_keys = msg.static_account_keys();
            // Resolve which program is being executed for each frame in the trace
            let mut program_id_invocation_order = Vec::new();
            for (ix_idx, cpi_ixs) in cpi_instructions.iter().enumerate() {
                let top_level_program_id = msg.instructions()[ix_idx].program_id(msg_keys); 
                program_id_invocation_order.push(top_level_program_id);
                for inner_ix in cpi_ixs {
                    program_id_invocation_order.push(inner_ix.instruction.program_id(msg_keys));
                }
            }
            if program_id_invocation_order.is_empty() {
                program_id_invocation_order.push(msg.instructions().first().expect("No instructions in message").program_id(msg_keys));
            }

I came also into this necessity while trying to figure out the invocation order after the processed transaction.

Fwiw, I also resorted to forking sbpf to avoid tracing every instruction in favor of tracing JMP class opcodes only.

A future improvement could be to have instruction trace filter classes for specific opcodes as in your case.

[Lichtso]

Alright, I think I found a solution (#8285) which should cover all the wishes:

• all register traces in a transaction, even through CPI
• @0xalpharush: parsed instruction alongside the register trace
• @procdump: filter classes for specific opcodes

One example of how it could be used:

invoke_context.iterate_vm_traces(|instruction_context, executable, register_trace| {
    let program_id = instruction_context.get_program_key().unwrap();
    let instruction_data = instruction_context.get_instruction_data();
    let borrowed_account = instruction_context.try_borrow_instruction_account(0).unwrap();
    let first_instruction_account_key = borrowed_account.get_key();
    let first_instruction_account_lamports = borrowed_account.get_lamports();
    let first_instruction_account_data = borrowed_account.get_data();

    let (_vm_addr, program) = executable.get_text_bytes();
    let joined = register_trace
        .iter()
        .map(|registers| {
            (
                registers,
                ebpf::get_insn_unchecked(program, registers[11] as usize),
            )
        })
        .filter(|(_registers, insn)| insn.opc & 7 == ebpf::BPF_JMP && insn.opc != ebpf::BPF_JA);

    // ... do your thing here
})

With this most of LiteSVM/litesvm#221 should be solved upstream and the PR could be reduced to the part that writes the files to SBF_TRACE_DIR.

[0xalpharush]

This seems like a huge improvement. It would be nice to avoid the program cache lookup and also perform the filtering at runtime. Our code originally was very similar to the example and parsing after the fact, but the perf hit compared to forking SBPF is significant.

Would adding the parsed instruction to the trace and filtering with a function passed as an arg within SBPF be possible?

[Lichtso]

What exactly are you tracing anyway for pre-filtering to make such a big difference? Are you tracing all transactions?

[procdump]

I've filed a PR (#8407) that is related to this discussion. Briefly we have to be sure SBPF is in interpreter mode so that any register tracing can be obtained at all and hence introduce a feature for this. Please have a look at the PR for more context.