Feature Request: add cpi breakdown to bench results

[redmannequin]

It would be nice to have a breakdown of how many CU are incurred by the "root" program and it's CPI(s) calls in the result.

example:

Name	CUs	Delta	my_program	cpi(s)
create_config	8388	-52	3657	4731
update_config	528	--	528	--
update_claim	863	- new -	863	--

[buffalojoec]

Unfortunately, it's not possible for Mollusk to capture CPI-only compute units without modifying the InvokeContext API that comes from Agave. InvokeContext::process_instruction accepts a &mut u64 for compute units consumed, and doesn't give you a way to discern where the consumption comes from.

We try to avoid making changes to Agave that aren't necessary for validator tasks. Maybe you can share more about what you're trying to measure/do and we can see about an alternate approach?

Side note: it's technically possible actually, if we re-write the sol_invoke_signed syscall on Mollusk-side, but that seems like more trouble than it's worth, since it invalidates the Agave-mirrored test environment.

[redmannequin]

Wouldn't it be possible by parsing the logs? Is there anyway to access the logs of an execution?

I'm currently building/playing around with a dummy framework built on top of pinocchio, and I'm trying to benchmark my changes to see their impact and catch any regressions.

[redmannequin]

I just thought of another neat use-case -- give an options of result format, add json to to the mix; this way you can easily write a CI step to auto bench and flag regressions. (this is just an idea, probably need's its own issue just dumping here for later)

[redmannequin]

After thinking about it, this doesn’t feel like the right place to be parsing logs. Might be better to just surface the logs alongside the execution result — gives more flexibility and keeps the crate lightweight. What are your thoughts?

Do you happen to know if there are any structured Solana log parsers out there?

[buffalojoec]

To me, parsing logs seems like it's rife for bugs. A program could just emit logs that spoof the bencher. I don't know why you would, but you could.

If you want to parse logs on your end, you can! You just need to query the log collector's messages and apply your parsing.

Do you happen to know if there are any structured Solana log parsers out there?

Nope, not that I know of. But if you create one, feel free to share!

[redmannequin]

Perfect, I've update the PR with some changes, adds a new function that doesn't write the file and returns the bench results as well as it adds the logs of a bench execution to the result type.

[ananas-block]

It would be interesting to add CU costs for the entrypoint and runtime internal cpi preparation (eg cpi data, account size) as well.

Have been playing with logging any CU consumption in the InvokeContext by setting a print here and running solana program test.

If you end up parsing logs you can probably just patch the program runtime dep and log all runtime internal CU cost that way.

[redmannequin]

@ananas-block im a little confused, solana already logs the consumed units for each invocation, no? I've been using the logs of the format Program {id} consumed {cus consumed} of {cu budget} compute units I have no idea where this log is emitted but it seems to be there, including in mainnet.

here's a little utility lib I wrote to parse logs if you're interested(not sure if/when ill publish it)

sol-log-parser

I'm sure in the future I'll be wanting to test account sizes, thanks for pointing out where too look.

[buffalojoec]

@ananas-block the direction you're heading makes me think about adding support for a pluggable InvokeContext. More accurately, a generic instruction processor. That way, if you wanted, you could extend Mollusk's Agave functionality by providing modified Agave components to the API, some of which might include more fine-grained CU tracking.

This would be for advanced use cases, but it could also mean Mollusk would be generic over some VM... 👀

[redmannequin]

@buffalojoec funny enough I was directed to mollusk because I was looking to have a rust runtime for pinocchio that would allow me to step through the code execution for testing/debugging. I think having a plugable "VM" would be really nice though im not sure how much effort that would be and if anybody else would benefit from it.

[buffalojoec]

@buffalojoec funny enough I was directed to mollusk because I was looking to have a rust runtime for pinocchio that would allow me to step through the code execution for testing/debugging. I think having a plugable "VM" would be really nice though im not sure how much effort that would be and if anybody else would benefit from it.

Actually that's another really good idea! With a pluggable VM, someone could use the interpreter (instead of JIT) on the Agave sBPF VM and hook up a debugger! Then you'd be able to accomplish exactly what you're describing.

I guess the "pluggable" bit would be the "invoke context", which would be not just the VM but the compilation/interpretation method, the syscall registry, etc. There's room to make a lot of things pluggable, actually. I can think of another nice use case where you are testing a change to a syscall and need to register a new or different one in the loader.