Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Adding additional logging when overflow occurs in calculate_stake_rew… #3783

Merged
merged 4 commits into from
Dec 4, 2024
Merged

Adding additional logging when overflow occurs in calculate_stake_rew… #3783

Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
d8b2668
Adding additional logging when overflow occurs in calculate_stake_rew…
roryharr Nov 25, 2024
90ef04b
Merge branch 'master' into log_stake_rewards_overflows
roryharr Nov 25, 2024
3c0e51e
Updated code to use expects statements, and test case macros based on…
roryharr Nov 28, 2024
377016d
Resolving Performance Degredation by removing formatted output
roryharr Dec 3, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
39 changes: 35 additions & 4 deletions programs/stake/src/rewards.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -185,11 +185,17 @@ fn calculate_stake_rewards(

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

let rewards = u64::try_from(rewards).unwrap();
// The unwrap is safe, as points_value.points is guaranteed to be non zero above.
// Expect is verifying that the result fits in u64
let rewards = u64::try_from(rewards.checked_div(point_value.points).unwrap()).expect(&format!(
"Rewards should fit within u64, inputs were {}, {} and {}",
points, point_value.rewards, point_value.points
));
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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"

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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,
        );
    });
}

Copy link
Author

@roryharr roryharr Dec 3, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Author

@roryharr roryharr Dec 3, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

I will close this out.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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!

Copy link
Author

@roryharr roryharr Dec 3, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.


// don't bother trying to split if fractional lamports got truncated
if rewards == 0 {
Expand Down Expand Up @@ -231,6 +237,8 @@ mod tests {
super::*,
crate::{points::null_tracer, stake_state::new_stake},
solana_sdk::{native_token, pubkey::Pubkey},
std::u64,
roryharr marked this conversation as resolved.
Show resolved Hide resolved
test_case::test_case,
};

#[test]
Expand Down Expand Up @@ -610,6 +618,29 @@ mod tests {
);
}

#[test_case(u64::MAX, 1_000, u64::MAX => panics "Rewards should fit within u128")]
#[test_case(1, u64::MAX, u64::MAX => panics "Rewards should fit within u64")]
fn calculate_rewards_tests(stake: u64, rewards: u64, credits: u64) {
let mut vote_state = VoteState::default();

let stake = new_stake(stake, &Pubkey::default(), &vote_state, u64::MAX);

vote_state.increment_credits(0, credits);

calculate_stake_rewards(
0,
&stake,
&PointValue {
rewards: rewards,
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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,

points: 1,
},
&vote_state,
&StakeHistory::default(),
null_tracer(),
None,
);
}

#[test]
fn test_stake_state_calculate_points_with_typical_values() {
let vote_state = VoteState::default();
Expand Down