Skip to content

Commit

Permalink
Add execute metrics
Browse files Browse the repository at this point in the history
  • Loading branch information
@carllin @t-nelson
carllin authored and t-nelson committed Jan 5, 2022
1 parent 87da0c3 commit 7dbfa33
Show file tree
Hide file tree
Showing 12 changed files with 278 additions and 38 deletions.
1 change: 1 addition & 0 deletions Cargo.lock
View file

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

8 changes: 6 additions & 2 deletions core/src/cost_update_service.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -69,8 +69,12 @@ impl CostUpdateServiceTiming {
}

pub enum CostUpdate {
FrozenBank { bank: Arc<Bank> },
ExecuteTiming { execute_timings: ExecuteTimings },
FrozenBank {
bank: Arc<Bank>,
},
ExecuteTiming {
execute_timings: Box<ExecuteTimings>,
},
}

pub type CostUpdateReceiver = Receiver<CostUpdate>;
Expand Down
92 changes: 84 additions & 8 deletions core/src/progress_map.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -82,45 +82,121 @@ impl ReplaySlotStats {
i64
),
(
"serialize_us",
"execute_details_serialize_us",
self.execute_timings.details.serialize_us,
i64
),
(
"create_vm_us",
"execute_details_create_vm_us",
self.execute_timings.details.create_vm_us,
i64
),
(
"execute_inner_us",
"execute_details_execute_inner_us",
self.execute_timings.details.execute_us,
i64
),
(
"deserialize_us",
"execute_details_deserialize_us",
self.execute_timings.details.deserialize_us,
i64
),
(
"changed_account_count",
"execute_details_get_or_create_executor_us",
self.execute_timings.details.get_or_create_executor_us,
i64
),
(
"execute_details_changed_account_count",
self.execute_timings.details.changed_account_count,
i64
),
(
"total_account_count",
"execute_details_total_account_count",
self.execute_timings.details.total_account_count,
i64
),
(
"total_data_size",
"execute_details_total_data_size",
self.execute_timings.details.total_data_size,
i64
),
(
"data_size_changed",
"execute_details_data_size_changed",
self.execute_timings.details.data_size_changed,
i64
),
(
"execute_accessories_feature_set_clone_us",
self.execute_timings
.execute_accessories
.feature_set_clone_us,
i64
),
(
"execute_accessories_compute_budget_process_transaction_us",
self.execute_timings
.execute_accessories
.compute_budget_process_transaction_us,
i64
),
(
"execute_accessories_get_executors_us",
self.execute_timings.execute_accessories.get_executors_us,
i64
),
(
"execute_accessories_transaction_context_ctor_us",
self.execute_timings
.execute_accessories
.transaction_context_ctor_us,
i64
),
(
"execute_accessories_last_blockhash_and_lamports_per_signature_us",
self.execute_timings
.execute_accessories
.last_blockhash_and_lamports_per_signature_us,
i64
),
(
"execute_accessories_process_message_us",
self.execute_timings.execute_accessories.process_message_us,
i64
),
(
"execute_accessories_update_executors_us",
self.execute_timings.execute_accessories.update_executors_us,
i64
),
(
"execute_accessories_process_instruction_verify_caller_us",
self.execute_timings
.execute_accessories
.process_instruction_verify_caller_us,
i64
),
(
"execute_accessories_process_instruction_compile_instruction_us",
self.execute_timings
.execute_accessories
.process_instruction_compile_instruction_us,
i64
),
(
"execute_accessories_process_instruction_process_executable_chain_us",
self.execute_timings
.execute_accessories
.process_instruction_process_executable_chain_us,
i64
),
(
"execute_accessories_process_instruction_verify_callee_us",
self.execute_timings
.execute_accessories
.process_instruction_verify_callee_us,
i64
),
);

let mut per_pubkey_timings: Vec<_> = self
Expand Down
4 changes: 3 additions & 1 deletion core/src/replay_stage.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2248,7 +2248,9 @@ impl ReplayStage {
// send accumulated excute-timings to cost_update_service
if !execute_timings.details.per_program_timings.is_empty() {
cost_update_sender
.send(CostUpdate::ExecuteTiming { execute_timings })
.send(CostUpdate::ExecuteTiming {
execute_timings: Box::new(execute_timings),
})
.unwrap_or_else(|err| warn!("cost_update_sender failed: {:?}", err));
}

Expand Down
1 change: 1 addition & 0 deletions program-runtime/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ log = "0.4.14"
num-derive = { version = "0.3" }
num-traits = { version = "0.2" }
serde = { version = "1.0.129", features = ["derive", "rc"] }
solana-measure = { path = "../measure", version = "=1.10.0" }
solana-sdk = { path = "../sdk", version = "=1.10.0" }
thiserror = "1.0"

Expand Down
70 changes: 60 additions & 10 deletions program-runtime/src/invoke_context.rs
View file
Original file line number Diff line number Diff line change
@@ -1,9 +1,14 @@
use {
crate::{
accounts_data_meter::AccountsDataMeter, ic_logger_msg, ic_msg,
instruction_recorder::InstructionRecorder, log_collector::LogCollector,
native_loader::NativeLoader, pre_account::PreAccount, timings::ExecuteDetailsTimings,
accounts_data_meter::AccountsDataMeter,
ic_logger_msg, ic_msg,
instruction_recorder::InstructionRecorder,
log_collector::LogCollector,
native_loader::NativeLoader,
pre_account::PreAccount,
timings::{ExecuteDetailsTimings, ExecuteTimings},
},
solana_measure::measure::Measure,
solana_sdk::{
account::{AccountSharedData, ReadableAccount},
bpf_loader_upgradeable::{self, UpgradeableLoaderState},
Expand Down Expand Up @@ -564,6 +569,7 @@ impl<'a> InvokeContext<'a> {
&instruction_accounts,
&program_indices,
&mut compute_units_consumed,
&mut ExecuteTimings::default(),
)?;

// Verify the called program has not misbehaved
Expand Down Expand Up @@ -734,6 +740,7 @@ impl<'a> InvokeContext<'a> {
instruction_accounts: &[InstructionAccount],
program_indices: &[usize],
compute_units_consumed: &mut u64,
timings: &mut ExecuteTimings,
) -> Result<(), InstructionError> {
*compute_units_consumed = 0;
let program_id = program_indices
Expand All @@ -751,10 +758,20 @@ impl<'a> InvokeContext<'a> {
}
} else {
// Verify the calling program hasn't misbehaved
self.verify_and_update(instruction_accounts, true)?;
let mut verify_caller_time = Measure::start("verify_caller_time");
let verify_caller_result = self.verify_and_update(instruction_accounts, true);
verify_caller_time.stop();
timings
.execute_accessories
.process_instruction_verify_caller_us = timings
.execute_accessories
.process_instruction_verify_caller_us
.saturating_add(verify_caller_time.as_us());
verify_caller_result?;

// Record instruction
if let Some(instruction_recorder) = &self.instruction_recorder {
let mut compile_instruction_time = Measure::start("compile_instruction_time");
let compiled_instruction = CompiledInstruction {
program_id_index: self
.transaction_context
Expand All @@ -766,28 +783,57 @@ impl<'a> InvokeContext<'a> {
.map(|instruction_account| instruction_account.index_in_transaction as u8)
.collect(),
};

instruction_recorder
.borrow_mut()
.record_compiled_instruction(compiled_instruction);
compile_instruction_time.stop();
timings
.execute_accessories
.process_instruction_compile_instruction_us = timings
.execute_accessories
.process_instruction_compile_instruction_us
.saturating_add(compile_instruction_time.as_us());
}
}

let result = self
.push(instruction_accounts, program_indices, instruction_data)
.and_then(|_| {
let mut process_executable_chain_time =
Measure::start("process_executable_chain_time");
self.return_data = (program_id, Vec::new());
let pre_remaining_units = self.compute_meter.borrow().get_remaining();
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?;
process_executable_chain_time.stop();

// Verify the called program has not misbehaved
if is_lowest_invocation_level {
self.verify(instruction_accounts, program_indices)
} else {
self.verify_and_update(instruction_accounts, false)
}
let mut verify_callee_time = Measure::start("verify_callee_time");
let result = execution_result.and_then(|_| {
if is_lowest_invocation_level {
self.verify(instruction_accounts, program_indices)
} else {
self.verify_and_update(instruction_accounts, false)
}
});
verify_callee_time.stop();

timings
.execute_accessories
.process_instruction_process_executable_chain_us = timings
.execute_accessories
.process_instruction_process_executable_chain_us
.saturating_add(process_executable_chain_time.as_us());
timings
.execute_accessories
.process_instruction_verify_callee_us = timings
.execute_accessories
.process_instruction_verify_callee_us
.saturating_add(verify_callee_time.as_us());

result
});

// Pop the invoke_stack to restore previous state
Expand Down Expand Up @@ -1482,6 +1528,7 @@ mod tests {
&inner_instruction_accounts,
&program_indices,
&mut compute_units_consumed,
&mut ExecuteTimings::default(),
);

// Because the instruction had compute cost > 0, then regardless of the execution result,
Expand Down Expand Up @@ -1596,6 +1643,7 @@ mod tests {
&instruction_accounts,
&[2],
&mut 0,
&mut ExecuteTimings::default(),
);

assert!(result.is_ok());
Expand All @@ -1614,6 +1662,7 @@ mod tests {
&instruction_accounts,
&[2],
&mut 0,
&mut ExecuteTimings::default(),
);

assert!(result.is_ok());
Expand All @@ -1632,6 +1681,7 @@ mod tests {
&instruction_accounts,
&[2],
&mut 0,
&mut ExecuteTimings::default(),
);

assert!(result.is_err());
Expand Down

0 comments on commit 7dbfa33

Please sign in to comment.