Skip to content

Commit

Permalink
[BlockSTM] Add latency counter for fetching next task (#6956)
Browse files Browse the repository at this point in the history
  • Loading branch information
sitalkedia authored Mar 8, 2023
1 parent eee3eea commit 66c0a3e
Show file tree
Hide file tree
Showing 4 changed files with 55 additions and 2 deletions.
44 changes: 44 additions & 0 deletions aptos-move/block-executor/src/counters.rs
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,28 @@ pub static SPECULATIVE_ABORT_COUNT: Lazy<IntCounter> = Lazy::new(|| {
.unwrap()
});

pub static PARALLEL_EXECUTION_SECONDS: Lazy<Histogram> = Lazy::new(|| {
register_histogram!(
// metric name
"aptos_parallel_execution_seconds",
// metric description
"The time spent in seconds in parallel execution",
exponential_buckets(/*start=*/ 1e-6, /*factor=*/ 2.0, /*count=*/ 30).unwrap(),
)
.unwrap()
});

pub static RAYON_EXECUTION_SECONDS: Lazy<Histogram> = Lazy::new(|| {
register_histogram!(
// metric name
"aptos_rayon_execution_seconds",
// metric description
"The time spent in seconds in rayon thread pool in parallel execution",
exponential_buckets(/*start=*/ 1e-6, /*factor=*/ 2.0, /*count=*/ 30).unwrap(),
)
.unwrap()
});

pub static VM_INIT_SECONDS: Lazy<Histogram> = Lazy::new(|| {
register_histogram!(
// metric name
Expand All @@ -46,6 +68,17 @@ pub static TASK_VALIDATE_SECONDS: Lazy<Histogram> = Lazy::new(|| {
.unwrap()
});

pub static WORK_WITH_TASK_SECONDS: Lazy<Histogram> = Lazy::new(|| {
register_histogram!(
// metric name
"aptos_execution_work_with_task_seconds",
// metric description
"The time spent in work task with scope call in Block STM",
exponential_buckets(/*start=*/ 1e-6, /*factor=*/ 2.0, /*count=*/ 30).unwrap(),
)
.unwrap()
});

pub static TASK_EXECUTE_SECONDS: Lazy<Histogram> = Lazy::new(|| {
register_histogram!(
// metric name
Expand All @@ -57,6 +90,17 @@ pub static TASK_EXECUTE_SECONDS: Lazy<Histogram> = Lazy::new(|| {
.unwrap()
});

pub static GET_NEXT_TASK_SECONDS: Lazy<Histogram> = Lazy::new(|| {
register_histogram!(
// metric name
"aptos_execution_get_next_task_seconds",
// metric description
"The time spent in seconds for getting next task from the scheduler",
exponential_buckets(/*start=*/ 1e-6, /*factor=*/ 2.0, /*count=*/ 30).unwrap(),
)
.unwrap()
});

pub static DEPENDENCY_WAIT_SECONDS: Lazy<Histogram> = Lazy::new(|| {
register_histogram!(
"aptos_execution_dependency_wait",
Expand Down
9 changes: 8 additions & 1 deletion aptos-move/block-executor/src/executor.rs
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,10 @@

use crate::{
counters,
counters::{TASK_EXECUTE_SECONDS, TASK_VALIDATE_SECONDS, VM_INIT_SECONDS},
counters::{
PARALLEL_EXECUTION_SECONDS, RAYON_EXECUTION_SECONDS, TASK_EXECUTE_SECONDS,
TASK_VALIDATE_SECONDS, VM_INIT_SECONDS, WORK_WITH_TASK_SECONDS,
},
errors::*,
output_delta_resolver::OutputDeltaResolver,
scheduler::{Scheduler, SchedulerTask, Version, Wave},
Expand Down Expand Up @@ -201,6 +204,7 @@ where
let executor = E::init(*executor_arguments);
drop(init_timer);

let _timer = WORK_WITH_TASK_SECONDS.start_timer();
let mut scheduler_task = SchedulerTask::NoTask;
loop {
// Only one thread try_commit to avoid contention.
Expand Down Expand Up @@ -252,6 +256,7 @@ where
signature_verified_block: &Vec<T>,
base_view: &S,
) -> Result<Vec<(E::Output, Vec<(T::Key, WriteOp)>)>, E::Error> {
let _timer = PARALLEL_EXECUTION_SECONDS.start_timer();
assert!(self.concurrency_level > 1, "Must use sequential execution");

let versioned_data_cache = MVHashMap::new();
Expand All @@ -265,6 +270,7 @@ where
let committing = AtomicBool::new(true);
let scheduler = Scheduler::new(num_txns);

let timer = RAYON_EXECUTION_SECONDS.start_timer();
RAYON_EXEC_POOL.scope(|s| {
for _ in 0..self.concurrency_level {
s.spawn(|_| {
Expand All @@ -280,6 +286,7 @@ where
});
}
});
drop(timer);

// TODO: for large block sizes and many cores, extract outputs in parallel.
let mut final_results = Vec::with_capacity(num_txns);
Expand Down
2 changes: 2 additions & 0 deletions aptos-move/block-executor/src/scheduler.rs
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
// Parts of the project are originally copyright © Meta Platforms, Inc.
// SPDX-License-Identifier: Apache-2.0

use crate::counters::GET_NEXT_TASK_SECONDS;
use aptos_infallible::Mutex;
use crossbeam::utils::CachePadded;
use parking_lot::{RwLock, RwLockUpgradableReadGuard};
Expand Down Expand Up @@ -291,6 +292,7 @@ impl Scheduler {

/// Return the next task for the thread.
pub fn next_task(&self, committing: bool) -> SchedulerTask {
let _timer = GET_NEXT_TASK_SECONDS.start_timer();
loop {
if self.done() {
// No more tasks.
Expand Down
2 changes: 1 addition & 1 deletion execution/executor/src/block_executor.rs
Original file line number Diff line number Diff line change
Expand Up @@ -175,6 +175,7 @@ where
block: (HashValue, Vec<T>),
parent_block_id: HashValue,
) -> Result<StateComputeResult, Error> {
let _timer = APTOS_EXECUTOR_EXECUTE_BLOCK_SECONDS.start_timer();
let (block_id, transactions) = block;
let committed_block = self.block_tree.root_block();
let mut block_vec = self
Expand Down Expand Up @@ -206,7 +207,6 @@ where
LogSchema::new(LogEntry::BlockExecutor).block_id(block_id),
"execute_block"
);
let _timer = APTOS_EXECUTOR_EXECUTE_BLOCK_SECONDS.start_timer();
let state_view = {
let _timer = APTOS_EXECUTOR_OTHER_TIMERS_SECONDS
.with_label_values(&["verified_state_view"])
Expand Down

0 comments on commit 66c0a3e

Please sign in to comment.