diff --git a/core/src/cost_update_service.rs b/core/src/cost_update_service.rs index 0ebee0c09c..9430c920af 100644 --- a/core/src/cost_update_service.rs +++ b/core/src/cost_update_service.rs @@ -127,8 +127,10 @@ impl CostUpdateService { CostUpdate::FrozenBank { bank } => { bank.read_cost_tracker().unwrap().report_stats(bank.slot()); } - CostUpdate::ExecuteTiming { execute_timings } => { - dirty |= Self::update_cost_model(&cost_model, &execute_timings); + CostUpdate::ExecuteTiming { + mut execute_timings, + } => { + dirty |= Self::update_cost_model(&cost_model, &mut execute_timings); update_count += 1; } } @@ -151,16 +153,27 @@ impl CostUpdateService { } } - fn update_cost_model(cost_model: &RwLock, execute_timings: &ExecuteTimings) -> bool { + fn update_cost_model( + cost_model: &RwLock, + execute_timings: &mut ExecuteTimings, + ) -> bool { let mut dirty = false; { - let mut cost_model_mutable = cost_model.write().unwrap(); - for (program_id, timing) in &execute_timings.details.per_program_timings { - if timing.count < 1 { + for (program_id, program_timings) in &mut execute_timings.details.per_program_timings { + let current_estimated_program_cost = + cost_model.read().unwrap().find_instruction_cost(program_id); + program_timings.coalesce_error_timings(current_estimated_program_cost); + + if program_timings.count < 1 { continue; } - let units = timing.accumulated_units / timing.count as u64; - match cost_model_mutable.upsert_instruction_cost(program_id, units) { + + let units = program_timings.accumulated_units / program_timings.count as u64; + match cost_model + .write() + .unwrap() + .upsert_instruction_cost(program_id, units) + { Ok(c) => { debug!( "after replayed into bank, instruction {:?} has averaged cost {}", @@ -213,8 +226,8 @@ mod tests { #[test] fn test_update_cost_model_with_empty_execute_timings() { let cost_model = Arc::new(RwLock::new(CostModel::default())); - let empty_execute_timings = ExecuteTimings::default(); - CostUpdateService::update_cost_model(&cost_model, &empty_execute_timings); + let mut empty_execute_timings = ExecuteTimings::default(); + CostUpdateService::update_cost_model(&cost_model, &mut empty_execute_timings); assert_eq!( 0, @@ -247,9 +260,10 @@ mod tests { accumulated_us, accumulated_units, count, + errored_txs_compute_consumed: vec![], }, ); - CostUpdateService::update_cost_model(&cost_model, &execute_timings); + CostUpdateService::update_cost_model(&cost_model, &mut execute_timings); assert_eq!( 1, cost_model @@ -282,9 +296,10 @@ mod tests { accumulated_us, accumulated_units, count, + errored_txs_compute_consumed: vec![], }, ); - CostUpdateService::update_cost_model(&cost_model, &execute_timings); + CostUpdateService::update_cost_model(&cost_model, &mut execute_timings); assert_eq!( 1, cost_model @@ -303,4 +318,99 @@ mod tests { ); } } + + #[test] + fn test_update_cost_model_with_error_execute_timings() { + let cost_model = Arc::new(RwLock::new(CostModel::default())); + let mut execute_timings = ExecuteTimings::default(); + let program_key_1 = Pubkey::new_unique(); + + // Test updating cost model with a `ProgramTiming` with no compute units accumulated, i.e. + // `accumulated_units` == 0 + { + execute_timings.details.per_program_timings.insert( + program_key_1, + ProgramTiming { + accumulated_us: 1000, + accumulated_units: 0, + count: 0, + errored_txs_compute_consumed: vec![], + }, + ); + CostUpdateService::update_cost_model(&cost_model, &mut execute_timings); + // If both the `errored_txs_compute_consumed` is empty and `count == 0`, then + // nothing should be inserted into the cost model + assert!(cost_model + .read() + .unwrap() + .get_instruction_cost_table() + .is_empty()); + } + + // Test updating cost model with only erroring compute costs where the `cost_per_error` is + // greater than the current instruction cost for the program. Should update with the + // new erroring compute costs + let cost_per_error = 1000; + { + execute_timings.details.per_program_timings.insert( + program_key_1, + ProgramTiming { + accumulated_us: 1000, + accumulated_units: 0, + count: 0, + errored_txs_compute_consumed: vec![cost_per_error; 3], + }, + ); + CostUpdateService::update_cost_model(&cost_model, &mut execute_timings); + assert_eq!( + 1, + cost_model + .read() + .unwrap() + .get_instruction_cost_table() + .len() + ); + assert_eq!( + Some(&cost_per_error), + cost_model + .read() + .unwrap() + .get_instruction_cost_table() + .get(&program_key_1) + ); + } + + // Test updating cost model with only erroring compute costs where the error cost is + // `smaller_cost_per_error`, less than the current instruction cost for the program. + // The cost should not decrease for these new lesser errors + let smaller_cost_per_error = cost_per_error - 10; + { + execute_timings.details.per_program_timings.insert( + program_key_1, + ProgramTiming { + accumulated_us: 1000, + accumulated_units: 0, + count: 0, + errored_txs_compute_consumed: vec![smaller_cost_per_error; 3], + }, + ); + CostUpdateService::update_cost_model(&cost_model, &mut execute_timings); + assert_eq!( + 1, + cost_model + .read() + .unwrap() + .get_instruction_cost_table() + .len() + ); + assert_eq!( + Some(&cost_per_error), + cost_model + .read() + .unwrap() + .get_instruction_cost_table() + .get(&program_key_1) + ); + } + } } diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 7ae8b4ec8e..83641068e3 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -30,6 +30,12 @@ pub type TransactionAccountRefCells = Vec; pub type ProcessInstructionWithContext = fn(usize, &[u8], &mut InvokeContext) -> Result<(), InstructionError>; +#[derive(Debug, PartialEq)] +pub struct ProcessInstructionResult { + pub compute_units_consumed: u64, + pub result: Result<(), InstructionError>, +} + #[derive(Clone)] pub struct BuiltinProgram { pub program_id: Pubkey, @@ -499,7 +505,8 @@ impl<'a> InvokeContext<'a> { &program_indices, &account_indices, &caller_write_privileges, - )?; + ) + .result?; // Verify the called program has not misbehaved let do_support_realloc = self.feature_set.is_active(&do_support_realloc::id()); @@ -640,37 +647,48 @@ impl<'a> InvokeContext<'a> { program_indices: &[usize], account_indices: &[usize], caller_write_privileges: &[bool], - ) -> Result { + ) -> ProcessInstructionResult { let is_lowest_invocation_level = self.invoke_stack.is_empty(); if !is_lowest_invocation_level { // Verify the calling program hasn't misbehaved - self.verify_and_update(instruction, account_indices, caller_write_privileges)?; + let result = + self.verify_and_update(instruction, account_indices, caller_write_privileges); + if result.is_err() { + return ProcessInstructionResult { + compute_units_consumed: 0, + result, + }; + } } + let mut compute_units_consumed = 0; let result = self .push(message, instruction, program_indices, account_indices) .and_then(|_| { self.return_data = (*instruction.program_id(&message.account_keys), Vec::new()); let pre_remaining_units = self.compute_meter.borrow().get_remaining(); - self.process_executable_chain(&instruction.data)?; + let execution_result = self.process_executable_chain(&instruction.data); let post_remaining_units = self.compute_meter.borrow().get_remaining(); + compute_units_consumed = pre_remaining_units.saturating_sub(post_remaining_units); + execution_result?; // Verify the called program has not misbehaved if is_lowest_invocation_level { - self.verify(message, instruction, program_indices)?; + self.verify(message, instruction, program_indices) } else { let write_privileges: Vec = (0..message.account_keys.len()) .map(|i| message.is_writable(i)) .collect(); - self.verify_and_update(instruction, account_indices, &write_privileges)?; + self.verify_and_update(instruction, account_indices, &write_privileges) } - - Ok(pre_remaining_units.saturating_sub(post_remaining_units)) }); // Pop the invoke_stack to restore previous state self.pop(); - result + ProcessInstructionResult { + compute_units_consumed, + result, + } } /// Calls the instruction's program entrypoint method @@ -983,6 +1001,10 @@ mod tests { ModifyOwned, ModifyNotOwned, ModifyReadonly, + ConsumeComputeUnits { + compute_units_consumed: u64, + desired_result: Result<(), InstructionError>, + }, } #[test] @@ -1052,6 +1074,17 @@ mod tests { .try_account_ref_mut()? .data_as_mut_slice()[0] = 1 } + MockInstruction::ConsumeComputeUnits { + compute_units_consumed, + desired_result, + } => { + invoke_context + .get_compute_meter() + .borrow_mut() + .consume(compute_units_consumed) + .unwrap(); + return desired_result; + } } } else { return Err(InstructionError::InvalidInstructionData); @@ -1260,13 +1293,15 @@ mod tests { .collect::>(); accounts[0].1.borrow_mut().data_as_mut_slice()[0] = 1; assert_eq!( - invoke_context.process_instruction( - &message, - &message.instructions[0], - &program_indices[1..], - &account_indices, - &caller_write_privileges, - ), + invoke_context + .process_instruction( + &message, + &message.instructions[0], + &program_indices[1..], + &account_indices, + &caller_write_privileges, + ) + .result, Err(InstructionError::ExternalAccountDataModified) ); accounts[0].1.borrow_mut().data_as_mut_slice()[0] = 0; @@ -1274,13 +1309,15 @@ mod tests { // readonly account modified by the invoker accounts[2].1.borrow_mut().data_as_mut_slice()[0] = 1; assert_eq!( - invoke_context.process_instruction( - &message, - &message.instructions[0], - &program_indices[1..], - &account_indices, - &caller_write_privileges, - ), + invoke_context + .process_instruction( + &message, + &message.instructions[0], + &program_indices[1..], + &account_indices, + &caller_write_privileges, + ) + .result, Err(InstructionError::ReadonlyDataModified) ); accounts[2].1.borrow_mut().data_as_mut_slice()[0] = 0; @@ -1288,15 +1325,33 @@ mod tests { invoke_context.pop(); let cases = vec![ - (MockInstruction::NoopSuccess, Ok(0)), + ( + MockInstruction::NoopSuccess, + ProcessInstructionResult { + result: Ok(()), + compute_units_consumed: 0, + }, + ), ( MockInstruction::NoopFail, - Err(InstructionError::GenericError), + ProcessInstructionResult { + result: Err(InstructionError::GenericError), + compute_units_consumed: 0, + }, + ), + ( + MockInstruction::ModifyOwned, + ProcessInstructionResult { + result: Ok(()), + compute_units_consumed: 0, + }, ), - (MockInstruction::ModifyOwned, Ok(0)), ( MockInstruction::ModifyNotOwned, - Err(InstructionError::ExternalAccountDataModified), + ProcessInstructionResult { + result: Err(InstructionError::ExternalAccountDataModified), + compute_units_consumed: 0, + }, ), ]; for case in cases { @@ -1497,4 +1552,92 @@ mod tests { ); invoke_context.pop(); } + + #[test] + fn test_process_instruction_compute_budget() { + let caller_program_id = solana_sdk::pubkey::new_rand(); + let callee_program_id = solana_sdk::pubkey::new_rand(); + let owned_account = AccountSharedData::new(42, 1, &callee_program_id); + let not_owned_account = AccountSharedData::new(84, 1, &solana_sdk::pubkey::new_rand()); + let readonly_account = AccountSharedData::new(168, 1, &solana_sdk::pubkey::new_rand()); + let loader_account = AccountSharedData::new(0, 0, &native_loader::id()); + let mut program_account = AccountSharedData::new(1, 0, &native_loader::id()); + program_account.set_executable(true); + + let accounts = vec![ + ( + solana_sdk::pubkey::new_rand(), + Rc::new(RefCell::new(owned_account)), + ), + ( + solana_sdk::pubkey::new_rand(), + Rc::new(RefCell::new(not_owned_account)), + ), + ( + solana_sdk::pubkey::new_rand(), + Rc::new(RefCell::new(readonly_account)), + ), + (caller_program_id, Rc::new(RefCell::new(loader_account))), + (callee_program_id, Rc::new(RefCell::new(program_account))), + ]; + let account_indices = [0, 1, 2]; + let program_indices = [3, 4]; + + let metas = vec![ + AccountMeta::new(accounts[0].0, false), + AccountMeta::new(accounts[1].0, false), + AccountMeta::new_readonly(accounts[2].0, false), + ]; + + let builtin_programs = &[BuiltinProgram { + program_id: callee_program_id, + process_instruction: mock_process_instruction, + }]; + let mut invoke_context = InvokeContext::new_mock(&accounts, builtin_programs); + + let compute_units_consumed = 10; + let desired_results = vec![Ok(()), Err(InstructionError::GenericError)]; + + for desired_result in desired_results { + let caller_instruction = + CompiledInstruction::new(program_indices[0] as u8, &(), vec![0, 1, 2, 3, 4]); + let callee_instruction = Instruction::new_with_bincode( + callee_program_id, + &MockInstruction::ConsumeComputeUnits { + compute_units_consumed, + desired_result: desired_result.clone(), + }, + metas.clone(), + ); + let message = Message::new(&[callee_instruction.clone()], None); + invoke_context + .push(&message, &caller_instruction, &program_indices[..1], &[]) + .unwrap(); + let caller_write_privileges = message + .account_keys + .iter() + .enumerate() + .map(|(i, _)| message.is_writable(i)) + .collect::>(); + let result = invoke_context.process_instruction( + &message, + &message.instructions[0], + &program_indices[1..], + &account_indices, + &caller_write_privileges, + ); + + // Because the instruction had compute cost > 0, then regardless of the execution result, + // the number of compute units consumed should be a non-default which is something greater + // than zero. + assert!(result.compute_units_consumed > 0); + assert_eq!( + result, + ProcessInstructionResult { + compute_units_consumed, + result: desired_result, + } + ); + } + } } diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index a61b621e1a..c5f71e177f 100644 --- a/program-runtime/src/timings.rs +++ b/program-runtime/src/timings.rs @@ -5,6 +5,18 @@ pub struct ProgramTiming { pub accumulated_us: u64, pub accumulated_units: u64, pub count: u32, + pub errored_txs_compute_consumed: Vec, +} + +impl ProgramTiming { + pub fn coalesce_error_timings(&mut self, current_estimated_program_cost: u64) { + for tx_error_compute_consumed in self.errored_txs_compute_consumed.drain(..) { + let compute_units_update = + std::cmp::max(current_estimated_program_cost, tx_error_compute_consumed); + self.accumulated_units = self.accumulated_units.saturating_add(compute_units_update); + self.count = self.count.saturating_add(1); + } + } } #[derive(Default, Debug)] @@ -46,10 +58,24 @@ impl ExecuteDetailsTimings { program_timing.count = program_timing.count.saturating_add(other.count); } } - pub fn accumulate_program(&mut self, program_id: &Pubkey, us: u64, units: u64) { + pub fn accumulate_program( + &mut self, + program_id: &Pubkey, + us: u64, + compute_units_consumed: u64, + is_error: bool, + ) { let program_timing = self.per_program_timings.entry(*program_id).or_default(); program_timing.accumulated_us = program_timing.accumulated_us.saturating_add(us); - program_timing.accumulated_units = program_timing.accumulated_units.saturating_add(units); - program_timing.count = program_timing.count.saturating_add(1); + if is_error { + program_timing + .errored_txs_compute_consumed + .push(compute_units_consumed); + } else { + program_timing.accumulated_units = program_timing + .accumulated_units + .saturating_add(compute_units_consumed); + program_timing.count = program_timing.count.saturating_add(1); + }; } } diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index d25ad9280c..d8b7fbe3f6 100644 --- a/program-test/src/lib.rs +++ b/program-test/src/lib.rs @@ -322,6 +322,7 @@ impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs { &account_indices, &caller_privileges, ) + .result .map_err(|err| ProgramError::try_from(err).unwrap_or_else(|err| panic!("{}", err)))?; // Copy writeable account modifications back into the caller's AccountInfos diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index d8a143d834..ea4db31321 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -2372,6 +2372,7 @@ fn call<'a, 'b: 'a>( &account_indices, &caller_write_privileges, ) + .result .map_err(SyscallError::InstructionError)?; // Copy results back to caller diff --git a/runtime/src/cost_model.rs b/runtime/src/cost_model.rs index a7fc6d5e86..75d5af43da 100644 --- a/runtime/src/cost_model.rs +++ b/runtime/src/cost_model.rs @@ -136,6 +136,20 @@ impl CostModel { self.instruction_execution_cost_table.get_cost_table() } + pub fn find_instruction_cost(&self, program_key: &Pubkey) -> u64 { + match self.instruction_execution_cost_table.get_cost(program_key) { + Some(cost) => *cost, + None => { + let default_value = self.instruction_execution_cost_table.get_mode(); + debug!( + "Program key {:?} does not have assigned cost, using mode {}", + program_key, default_value + ); + default_value + } + } + } + fn get_signature_cost(&self, transaction: &SanitizedTransaction) -> u64 { transaction.signatures().len() as u64 * SIGNATURE_COST } @@ -182,20 +196,6 @@ impl CostModel { cost } - fn find_instruction_cost(&self, program_key: &Pubkey) -> u64 { - match self.instruction_execution_cost_table.get_cost(program_key) { - Some(cost) => *cost, - None => { - let default_value = self.instruction_execution_cost_table.get_mode(); - debug!( - "Program key {:?} does not have assigned cost, using mode {}", - program_key, default_value - ); - default_value - } - } - } - fn calculate_cost_weight(&self, transaction: &SanitizedTransaction) -> u32 { if is_simple_vote_transaction(transaction) { // vote has zero cost weight, so it bypasses block cost limit checking diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index eccadcca8e..0129489513 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -3,7 +3,10 @@ use { solana_measure::measure::Measure, solana_program_runtime::{ instruction_recorder::InstructionRecorder, - invoke_context::{BuiltinProgram, Executors, InvokeContext, TransactionAccountRefCell}, + invoke_context::{ + BuiltinProgram, Executors, InvokeContext, ProcessInstructionResult, + TransactionAccountRefCell, + }, log_collector::LogCollector, timings::ExecuteDetailsTimings, }, @@ -105,16 +108,20 @@ impl MessageProcessor { Some(&instruction_recorders[instruction_index]); } let mut time = Measure::start("execute_instruction"); - let compute_meter_consumption = invoke_context - .process_instruction(message, instruction, program_indices, &[], &[]) - .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; + let ProcessInstructionResult { + compute_units_consumed, + result, + } = invoke_context.process_instruction(message, instruction, program_indices, &[], &[]); time.stop(); timings.accumulate_program( instruction.program_id(&message.account_keys), time.as_us(), - compute_meter_consumption, + compute_units_consumed, + result.is_err(), ); timings.accumulate(&invoke_context.timings); + result + .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; } Ok(()) }