Rewards regression on 8/2 epoch

[sakridge]

Problem

There seems to be a much slower rewards calculation for the epoch which took place around 8/2 23:00 UTC.

Proposed Solution

Debug and fix.

[jeffwashington]

some master validators for the same time:

[HaoranYi]

logs/solana-validator.log.1:[2022-08-03T00:02:58.079314995Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=334i slot=144288000i parent_slot=144287991i thread_pool_creation_us=3026i apply_feature_activations=7030i activate_epoch_Us=162875i update_epoch_stakes_us=7470i update_rewards_with_thread_pool_us=8499460i load_vote_and_stake_accounts_us=5361851i calculate_points_us=73634i redeem_rewards_us=972264i store_stake_accounts_us=1829029i store_vote_accounts_us=34312i invalid_cached_vote_accounts=0i invalid_cached_stake_accounts=6i invalid_cached_stake_accounts_rent_epoch=0i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.1:[2022-08-03T00:03:07.777970058Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=334i slot=144288004i parent_slot=144287999i thread_pool_creation_us=3032i apply_feature_activations=246i activate_epoch_Us=190606i update_epoch_stakes_us=7489i update_rewards_with_thread_pool_us=9343111i load_vote_and_stake_accounts_us=5960023i calculate_points_us=147150i redeem_rewards_us=1027361i store_stake_accounts_us=1945928i store_vote_accounts_us=27184i invalid_cached_vote_accounts=1i invalid_cached_stake_accounts=7i invalid_cached_stake_accounts_rent_epoch=7i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.1:[2022-08-03T00:03:17.185745070Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=334i slot=144288028i parent_slot=144287999i thread_pool_creation_us=2932i apply_feature_activations=408i activate_epoch_Us=153402i update_epoch_stakes_us=7085i update_rewards_with_thread_pool_us=9099767i load_vote_and_stake_accounts_us=5992500i calculate_points_us=53692i redeem_rewards_us=921479i store_stake_accounts_us=1883080i store_vote_accounts_us=25727i invalid_cached_vote_accounts=1i invalid_cached_stake_accounts=36i invalid_cached_stake_accounts_rent_epoch=36i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.1:[2022-08-03T00:03:27.310297533Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=334i slot=144288001i parent_slot=144287999i thread_pool_creation_us=2327i apply_feature_activations=289i activate_epoch_Us=168244i update_epoch_stakes_us=7424i update_rewards_with_thread_pool_us=9609767i load_vote_and_stake_accounts_us=6263530i calculate_points_us=121387i redeem_rewards_us=871115i store_stake_accounts_us=2092611i store_vote_accounts_us=27393i invalid_cached_vote_accounts=0i invalid_cached_stake_accounts=2i invalid_cached_stake_accounts_rent_epoch=2i vote_accounts_cache_miss_count=0i


logs/solana-validator.log.5:[2022-07-30T22:22:48.732855550Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=333i slot=143856000i parent_slot=143855999i thread_pool_creation_us=2426i apply_feature_activations=4661i activate_epoch_Us=137725i update_epoch_stakes_us=7923i update_rewards_with_thread_pool_us=10922248i load_vote_and_stake_accounts_us=7523802i calculate_points_us=58966i redeem_rewards_us=850385i store_stake_accounts_us=2242944i store_vote_accounts_us=28347i invalid_cached_vote_accounts=0i invalid_cached_stake_accounts=0i invalid_cached_stake_accounts_rent_epoch=0i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.5:[2022-07-30T22:22:56.777865943Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=333i slot=143856004i parent_slot=143855999i thread_pool_creation_us=2848i apply_feature_activations=160i activate_epoch_Us=130614i update_epoch_stakes_us=7792i update_rewards_with_thread_pool_us=7714662i load_vote_and_stake_accounts_us=4687420i calculate_points_us=66225i redeem_rewards_us=913139i store_stake_accounts_us=1800267i store_vote_accounts_us=24210i invalid_cached_vote_accounts=1i invalid_cached_stake_accounts=7i invalid_cached_stake_accounts_rent_epoch=7i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.5:[2022-07-30T22:23:01.697609847Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=333i slot=143856008i parent_slot=143855999i thread_pool_creation_us=3981i apply_feature_activations=165i activate_epoch_Us=114960i update_epoch_stakes_us=7252i update_rewards_with_thread_pool_us=4791213i load_vote_and_stake_accounts_us=1966557i calculate_points_us=39778i redeem_rewards_us=737962i store_stake_accounts_us=1801237i store_vote_accounts_us=24269i invalid_cached_vote_accounts=1i invalid_cached_stake_accounts=14i invalid_cached_stake_accounts_rent_epoch=14i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.5:[2022-07-30T22:23:08.901327443Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=333i slot=143856016i parent_slot=143855999i thread_pool_creation_us=3576i apply_feature_activations=177i activate_epoch_Us=127597i update_epoch_stakes_us=7100i update_rewards_with_thread_pool_us=5533537i load_vote_and_stake_accounts_us=2556315i calculate_points_us=42014i redeem_rewards_us=714732i store_stake_accounts_us=1968474i store_vote_accounts_us=25840i invalid_cached_vote_accounts=1i invalid_cached_stake_accounts=18i invalid_cached_stake_accounts_rent_epoch=18i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.5:[2022-07-30T22:23:13.439938367Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=333i slot=143856020i parent_slot=143855999i thread_pool_creation_us=2174i apply_feature_activations=149i activate_epoch_Us=117756i update_epoch_stakes_us=7263i update_rewards_with_thread_pool_us=5405505i load_vote_and_stake_accounts_us=2519223i calculate_points_us=53630i redeem_rewards_us=585966i store_stake_accounts_us=2000767i store_vote_accounts_us=24507i invalid_cached_vote_accounts=1i invalid_cached_stake_accounts=28i invalid_cached_stake_accounts_rent_epoch=28i vote_accounts_cache_miss_count=0i
logs/solana-validator.log.5:[2022-07-30T22:23:19.431213792Z INFO  solana_metrics::metrics] datapoint: bank-new_from_parent-new_epoch_timings epoch=333i slot=143856012i parent_slot=143855999i thread_pool_creation_us=5701i apply_feature_activations=164i activate_epoch_Us=138441i update_epoch_stakes_us=8130i update_rewards_with_thread_pool_us=5836674i load_vote_and_stake_accounts_us=2820110i calculate_points_us=48220i redeem_rewards_us=912925i store_stake_accounts_us=1800818i store_vote_accounts_us=26308i invalid_cached_vote_accounts=1i invalid_cached_stake_accounts=16i invalid_cached_stake_accounts_rent_epoch=16i vote_accounts_cache_miss_count=0i

[HaoranYi]

2022-08-03T00:02:58.079314995Z epoch=334i slot=144288000i parent_slot=144287991i load_vote_and_stake_accounts_us=5361851i
2022-08-03T00:03:07.777970058Z epoch=334i slot=144288004i parent_slot=144287999i load_vote_and_stake_accounts_us=5960023i
2022-08-03T00:03:17.185745070Z epoch=334i slot=144288028i parent_slot=144287999i load_vote_and_stake_accounts_us=5992500i
2022-08-03T00:03:27.310297533Z epoch=334i slot=144288001i parent_slot=144287999i load_vote_and_stake_accounts_us=6263530i


2022-07-30T22:22:48.732855550Z epoch=333i slot=143856000i parent_slot=143855999i load_vote_and_stake_accounts_us=7523802i
2022-07-30T22:22:56.777865943Z epoch=333i slot=143856004i parent_slot=143855999i load_vote_and_stake_accounts_us=4687420i
2022-07-30T22:23:01.697609847Z epoch=333i slot=143856008i parent_slot=143855999i load_vote_and_stake_accounts_us=1966557i
2022-07-30T22:23:08.901327443Z epoch=333i slot=143856016i parent_slot=143855999i load_vote_and_stake_accounts_us=2556315i
2022-07-30T22:23:13.439938367Z epoch=333i slot=143856020i parent_slot=143855999i load_vote_and_stake_accounts_us=2519223i
2022-07-30T22:23:19.431213792Z epoch=333i slot=143856012i parent_slot=143855999i load_vote_and_stake_accounts_us=2820110i

[HaoranYi]

On 8/3, the first load actually take less time than on 7/30. However, the following slots didn't saw a decrease of load time. It looks like those accounts are no longer in the cache when the following load happens. So those loads are as expensive as the first load.
However, on 7/30, the first two loads are expensive, but the following loads get the benefit of the cache, which are much faster.

[HaoranYi]

[HaoranYi]

On 7/30, during the epoch, we see a spike of read_only_cache size. But not seen it on 8/3. This explains why the following loads of stake account on 8/3 are expensive. Now the question is why read_only_cache is not populated on 8/3?

[jeffwashington]

@jeffwashington Are there any recent cache eviction changes which could be relevant?

Not that I recall.

[HaoranYi]

We do get the same peak on both epoch boundaries. It looks like the cache is full around epoch boundaries. Maybe all the stake accounts are evicted before the next load. I am going to add stat of evicts to verify it.

[jeffwashington]

https://discord.com/channels/428295358100013066/960593861732884520/1008762023166881843
Are these the same epoch?

[sakridge]

short-term cache fixes are merged and long-term issues for rewards calculations are tracking this issue: #20384