Skip to content

Commit

Permalink
perf(470): Add metrics for transaction cpu and elapsed time (#483)
Browse files Browse the repository at this point in the history
Closes #470.
  • Loading branch information
joshua-spacetime authored Oct 28, 2023
1 parent 5f98d70 commit e12c26b
Show file tree
Hide file tree
Showing 2 changed files with 40 additions and 1 deletion.
31 changes: 30 additions & 1 deletion crates/core/src/db/datastore/locking_tx_datastore/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ use std::{
collections::{BTreeMap, BTreeSet, HashMap},
ops::{Deref, RangeBounds},
sync::Arc,
time::{Duration, Instant},
vec,
};

Expand Down Expand Up @@ -119,6 +120,8 @@ impl<'a> DataRef<'a> {

pub struct MutTxId {
lock: ArcMutexGuard<RawMutex, Inner>,
lock_wait_time: Duration,
timer: Instant,
}

struct CommittedState {
Expand Down Expand Up @@ -1972,29 +1975,55 @@ impl traits::MutTx for Locking {
type MutTxId = MutTxId;

fn begin_mut_tx(&self) -> Self::MutTxId {
let timer = Instant::now();
let mut inner = self.inner.lock_arc();
let lock_wait_time = timer.elapsed();
if inner.tx_state.is_some() {
panic!("The previous transaction was not properly rolled back or committed.");
}
inner.tx_state = Some(TxState::new());
MutTxId { lock: inner }
MutTxId {
lock: inner,
lock_wait_time,
timer,
}
}

fn rollback_mut_tx(&self, ctx: &ExecutionContext, mut tx: Self::MutTxId) {
let elapsed_time = tx.timer.elapsed();
let cpu_time = elapsed_time - tx.lock_wait_time;
DB_METRICS
.rdb_num_txns_rolledback
.with_label_values(&ctx.txn_type(), &ctx.database(), ctx.reducer_name().unwrap_or(""))
.inc();
DB_METRICS
.rdb_txn_cpu_time_ns
.with_label_values(&ctx.txn_type(), &ctx.database(), ctx.reducer_name().unwrap_or(""))
.observe(cpu_time.as_nanos() as f64);
DB_METRICS
.rdb_txn_elapsed_time_ns
.with_label_values(&ctx.txn_type(), &ctx.database(), ctx.reducer_name().unwrap_or(""))
.observe(elapsed_time.as_nanos() as f64);
tx.lock.rollback();
}

fn commit_mut_tx(&self, ctx: &ExecutionContext, mut tx: Self::MutTxId) -> super::Result<Option<TxData>> {
let elapsed_time = tx.timer.elapsed();
let cpu_time = elapsed_time - tx.lock_wait_time;
// Note, we record empty transactions in our metrics.
// That is, transactions that don't write any rows to the commit log.
DB_METRICS
.rdb_num_txns_committed
.with_label_values(&ctx.txn_type(), &ctx.database(), ctx.reducer_name().unwrap_or(""))
.inc();
DB_METRICS
.rdb_txn_cpu_time_ns
.with_label_values(&ctx.txn_type(), &ctx.database(), ctx.reducer_name().unwrap_or(""))
.observe(cpu_time.as_nanos() as f64);
DB_METRICS
.rdb_txn_elapsed_time_ns
.with_label_values(&ctx.txn_type(), &ctx.database(), ctx.reducer_name().unwrap_or(""))
.observe(elapsed_time.as_nanos() as f64);
tx.lock.commit()
}

Expand Down
10 changes: 10 additions & 0 deletions crates/core/src/db/db_metrics/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -75,6 +75,16 @@ metrics_group!(
#[help = "The cumulative number of rolled back transactions"]
#[labels(txn_type: TransactionType, db: Address, reducer: str)]
pub rdb_num_txns_rolledback: IntCounterVec,

#[name = spacetime_txn_elapsed_time_ns]
#[help = "The total elapsed (wall) time of a transaction (nanoseconds)"]
#[labels(txn_type: TransactionType, db: Address, reducer: str)]
pub rdb_txn_elapsed_time_ns: HistogramVec,

#[name = spacetime_txn_cpu_time_ns]
#[help = "The time spent executing a transaction (nanoseconds), excluding time spent waiting to acquire database locks"]
#[labels(txn_type: TransactionType, db: Address, reducer: str)]
pub rdb_txn_cpu_time_ns: HistogramVec,
}
);

Expand Down

1 comment on commit e12c26b

@github-actions
Copy link

@github-actions github-actions bot commented on e12c26b Oct 28, 2023

Choose a reason for hiding this comment

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

Benchmarking failed. Please check the workflow run for details.

Please sign in to comment.