Adding additional logging when overflow occurs in calculate_stake_rew…

[roryharr]

Problem

Currently unwrap is used during calculate_stake_rewards, this lead to a lack of logging when an overflow occurs.

It might be better to take an action other than panic!, but it matches the current code and it's not clear to me what other action should be taken.

Summary of Changes

Additional logs during overflow calculations during calculate_stake_rewards
No change of functionality, validated through new unit tests.

Fixes #

[mergify]

The Firedancer team maintains a line-for-line reimplementation of the
native programs, and until native programs are moved to BPF, those
implementations must exactly match their Agave counterparts.
If this PR represents a change to a native program implementation (not
tests), please include a reviewer from the Firedancer team. And please
keep refactors to a minimum.

[joncinque]

Thanks for your contribution! If you want logging with unwrap(), rather than adding all of the match statements, it's more idiomatic to use expect(&format!("My formatted message with {variable}")): https://doc.rust-lang.org/std/option/enum.Option.html#method.expect

How about making that change?

[roryharr]

Thanks for your contribution! If you want logging with unwrap(), rather than adding all of the match statements, it's more idiomatic to use expect(&format!("My formatted message with {variable}")): https://doc.rust-lang.org/std/option/enum.Option.html#method.expect

How about making that change?

Thanks. Rewriting it in this way does make me think that bigints should be used for the temporary product, but that would be a functional change and have a minor performance impact. I'm not familiar enough with the hot path to know whether that is a concern and the trade off is worth making.

For the final division, fitting within a u64 makes sense as an expected outcome.

[joncinque]

Sorry for only doing this now, but I ran a bench on this PR, and just adding the string formatting has a surprising negative performance impact, causing this function to go from ~5.28ns to ~7ns.

Since rewards payouts are a huge bottleneck, I'm hesitant to do anything that will negatively impact performance. I also tried changing to unwrap_or_else to panic lazily, but it made no difference. If we use static strings, however, the performance is exactly the same. What do you think about using static strings instead? That would be just "Rewards should fit within u128" and "Rewards should fit within u64"

[roryharr]

Interesting! I guess it can discard the values otherwise/re-use the register space. I wonder if it's a single value causing the perf differentiation (eg points).

Let me see if i can get setup on my side to measure and get a no perf delta improvement that still provides some useful data.

[joncinque]

Yeah for sure! Here's my bench -- it requires making a few extra structs public to make it work, but I hope it provides a good start:

#![feature(test)]

extern crate test;
use {
    solana_stake_program::{points::{PointValue, null_tracer}, rewards::calculate_stake_rewards, stake_state::new_stake},
    solana_vote_program::vote_state::VoteState,
    solana_sdk::{
        pubkey::Pubkey,
        stake_history::StakeHistory,
    },
    test::Bencher,
};


#[bench]
fn calculate_rewards_tests(bencher: &mut Bencher) {
    let stake = 1_000_000_000;
    let rewards = 20_000_000_000;
    let credits = 30_000_000_000;

    let mut vote_state = VoteState::default();

    let stake = new_stake(stake, &Pubkey::default(), &vote_state, 100_000_000_000);

    vote_state.increment_credits(0, credits);

    bencher.iter(|| {
        calculate_stake_rewards(
            0,
            &stake,
            &PointValue {
                rewards: rewards,
                points: 1,
            },
            &vote_state,
            &StakeHistory::default(),
            null_tracer(),
            None,
        );
    });
}

[roryharr]

Yup, I got it to work locally. Seeing similar results that means there is no way to log useful values without effecting performance.

One interesting/very surprising result:

    let rewards = points
        .checked_mul(u128::from(point_value.rewards))
        .expect(&format!(
            "Rewards should fit within u128, inputs were {}", 3 as u32
        ));

test rewards::tests::bench_add_two ... bench: 38.25 ns/iter (+/- 0.54)

    let rewards = points
        .checked_mul(u128::from(point_value.rewards))
        .expect(&format!(
            "Rewards should fit within u128, inputs were {}", 3
        ));

test rewards::tests::bench_add_two ... bench: 22.27 ns/iter (+/- 0.67)

Even printing constants as u32 is causing a performance degradation.

[roryharr]

On further testing, even having the expects statement is causing a performance delta.

I will close this out.

[joncinque]

On my testing, when I did expect("static string") it recovered the original performance, which makes sense since there's no extra work required. If you wanted to do that, I'd be down!

[roryharr]

I tested that and still saw significant performance delta.
Base code:
test rewards::tests::bench_calculate_stake_rewards ... bench: 8.78 ns/iter (+/- 0.32)

With expects using static string:
test rewards::tests::bench_calculate_stake_rewards ... bench: 23.16 ns/iter (+/- 0.43)

Edit: It was because the format call was still present, despite no formatting being used. Removing the formatting call I get the same results as with unwrap.

[joncinque]

One last little thing to make this clearer, then we can get this in! Thanks for your patience.

[joncinque]

Also, be sure to run ./cargo nightly fmt --all from the top of the repo for formatting and ./scripts/cargo-clippy-nightly.sh to make sure it'll pass CI. I think there's just the one issue, but this way you'll be sure before pushing

[joncinque]

clippy is also complaining about this line in CI https://buildkite.com/anza/agave/builds/15002#01938ee1-02e8-4df2-8494-112c107b5803:

Suggested change

	rewards: rewards,
	rewards,

[joncinque]

Thanks for your contribution!