Skip to content

Commit

Permalink
Track time spent in each wasm instance env call (#427)
Browse files Browse the repository at this point in the history
Additionally, this further tidies the interface between the
host and the wasm instance env. In particular, reducer calls
are explicitly started and stopped, and the wasm instance env
becomes responsible for its own instrumentation.
kulakowski authored Oct 17, 2023
1 parent 63ef6eb commit b9bfe2c
Showing 8 changed files with 310 additions and 82 deletions.
9 changes: 5 additions & 4 deletions Cargo.lock

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

1 change: 1 addition & 0 deletions Cargo.toml
Original file line number Diff line number Diff line change
@@ -91,6 +91,7 @@ dirs = "5.0.1"
duct = "0.13.5"
email_address = "0.2.4"
enum-as-inner = "0.6"
enum-map = "2.6.3"
env_logger = "0.10"
flate2 = "1.0.24"
fs2 = "0.4.3"
1 change: 1 addition & 0 deletions crates/core/Cargo.toml
Original file line number Diff line number Diff line change
@@ -34,6 +34,7 @@ crossbeam-channel.workspace = true
derive_more.workspace = true
dirs.workspace = true
email_address.workspace = true
enum-map.workspace = true
flate2.workspace = true
fs2.workspace = true
futures.workspace = true
1 change: 1 addition & 0 deletions crates/core/src/host/wasm_common.rs
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
pub mod abi;
pub mod instrumentation;
pub mod module_host_actor;

use std::time::Instant;
127 changes: 127 additions & 0 deletions crates/core/src/host/wasm_common/instrumentation.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,127 @@
//! This file defines `CallSpan` and `CallSpanStart`,
//! which describe the time that a module spends executing "host calls,"
//! the WASM analog to syscalls.
//!
//! We can collect `CallSpan` timing data for various parts of host-call execution:
//! - `WasmInstanceEnv`, responsible for direct communication between WASM and the host.
//! - `InstanceEnv`, responsible for calls into the relational DB.
//! - Others?
//!
//! The instrumentation has non-negligible overhead,
//! so we enable it on a per-component basis with `cfg` attributes.
//! This is accomplished by defining two interchangeable modules,
//! `noop` and `op`, both of which implement the call-span interface.
//! `noop` does nothing.
//! `op` uses `std::time::Instant` and `std::time::Duration` to capture timings.
//! Components which use the time-span interface will conditionally import one of the two modules, like:
//! ```no-run
//! #[cfg(feature = "spacetimedb-wasm-instance-times)]
//! use instrumentation::op as span;
//! #[cfg(not(feature = "spacetimedb-wasm-instance-times)]
//! use instrumentation::noop as span;
//! ```
use std::time::{Duration, Instant};

use enum_map::{enum_map, Enum, EnumMap};

#[allow(unused)]
pub mod noop {
use super::*;

pub struct CallSpanStart;

impl CallSpanStart {
pub fn new(_call: Call) -> Self {
Self
}

pub fn end(self) -> CallSpan {
CallSpan
}
}

pub struct CallSpan;

pub fn record_span(_call_times: &mut CallTimes, _span: CallSpan) {}
}

#[allow(unused)]
pub mod op {
use super::*;

pub struct CallSpanStart {
call: Call,
start: Instant,
}

impl CallSpanStart {
pub fn new(call: Call) -> Self {
let start = Instant::now();
Self { call, start }
}

pub fn end(self) -> CallSpan {
let call = self.call;
let duration = self.start.elapsed();
CallSpan { call, duration }
}
}

#[derive(Debug)]
pub struct CallSpan {
pub(super) call: Call,
pub(super) duration: Duration,
}

pub fn record_span(times: &mut CallTimes, span: CallSpan) {
times.span(span)
}
}

/// Tags for each call that a `WasmInstanceEnv` can make.
#[derive(Debug, Enum)]
pub enum Call {
CancelReducer,
ConsoleLog,
CreateIndex,
DeleteByColEq,
GetTableId,
Insert,
IterByColEq,
IterDrop,
IterNext,
IterStart,
IterStartFiltered,
ScheduleReducer,
}

#[derive(Debug)]
/// Associates each `Call` tag with a cumulative total `Duration` spent within that call.
pub struct CallTimes {
times: EnumMap<Call, Duration>,
}

impl CallTimes {
/// Create a new timing structure, with times for all calls set to zero.
pub fn new() -> Self {
let times = enum_map! { _ => Duration::ZERO };
Self { times }
}

/// Track a particular `CallSpan` by adding its duration to the
/// associated `Call`'s timing information.
pub fn span(&mut self, span: op::CallSpan) {
self.times[span.call] += span.duration;
}

/// Taking the record of call times gives a copy of the
/// current values and resets the values to zero.
///
/// WasmInstanceEnv::finish_reducer (and other future per-reducer-call metrics)
/// will `take`` the CallTimes after running a reducer and report the taken times,
/// leaving a fresh zeroed CallTimes for the next reducer invocation.
pub fn take(&mut self) -> CallTimes {
std::mem::replace(self, Self::new())
}
}
33 changes: 25 additions & 8 deletions crates/core/src/host/wasm_common/module_host_actor.rs
Original file line number Diff line number Diff line change
@@ -31,6 +31,7 @@ use crate::identity::Identity;
use crate::subscription::module_subscription_actor::{ModuleSubscriptionManager, SubscriptionEventSender};
use crate::worker_metrics::{REDUCER_COMPUTE_TIME, REDUCER_COUNT, REDUCER_WRITE_SIZE};

use super::instrumentation::CallTimes;
use super::*;

pub trait WasmModule: Send + 'static {
@@ -74,9 +75,14 @@ pub struct EnergyStats {
pub remaining: EnergyQuanta,
}

pub struct ExecutionTimings {
pub total_duration: Duration,
pub wasm_instance_env_call_times: CallTimes,
}

pub struct ExecuteResult<E> {
pub energy: EnergyStats,
pub execution_duration: Duration,
pub timings: ExecutionTimings,
pub call_result: Result<Result<(), Box<str>>, E>,
}

@@ -602,28 +608,39 @@ impl<T: WasmInstance> WasmModuleInstance<T> {

let ExecuteResult {
energy,
execution_duration,
timings,
call_result,
} = result;

self.energy_monitor
.record(&energy_fingerprint, energy.used, execution_duration);
.record(&energy_fingerprint, energy.used, timings.total_duration);

const FRAME_LEN_60FPS: Duration = match Duration::from_secs(1).checked_div(60) {
Some(d) => d,
None => unreachable!(),
};
if execution_duration > FRAME_LEN_60FPS {
if timings.total_duration > FRAME_LEN_60FPS {
// If we can't get your reducer done in a single frame
// we should debug it.
log::debug!("Long running reducer {func_ident:?} took {execution_duration:?} to execute");
// we should debug it. To that end, this logging includes a detailed
// breakdown of where time is spent in the reducer call.
//
// TODO(george) only print the per-call timings if they are actually collected.
log::debug!(
"Long running reducer {func_ident:?} took {:?} to execute, with the following wasm_instance_env call times: {:?}",
timings.total_duration,
timings.wasm_instance_env_call_times
);
} else {
log::trace!("Reducer {func_ident:?} ran: {execution_duration:?}, {:?}", energy.used);
log::trace!(
"Reducer {func_ident:?} ran: {:?}, {:?}",
timings.total_duration,
energy.used
);
}

REDUCER_COMPUTE_TIME
.with_label_values(&[address, func_ident])
.observe(execution_duration.as_secs_f64());
.observe(timings.total_duration.as_secs_f64());

// If you can afford to take 500 ms for a transaction
// you can afford to generate a flamegraph. Fix your stuff.
Loading

1 comment on commit b9bfe2c

@github-actions
Copy link

Choose a reason for hiding this comment

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

Benchmark results

Benchmark Report

Legend:

  • load: number of rows pre-loaded into the database
  • count: number of rows touched by the transaction
  • index types:
    • unique: a single index on the id column
    • non_unique: no indexes
    • multi_index: non-unique index on every column
  • schemas:
    • person(id: u32, name: String, age: u64)
    • location(id: u32, x: u64, y: u64)

All throughputs are single-threaded.

Empty transaction

db on disk new latency old latency new throughput old throughput
sqlite 💿 457.9±1.13ns 451.6±2.19ns - -
sqlite 🧠 460.3±1.85ns 445.2±2.66ns - -
stdb_module 💿 15.6±0.54µs 15.9±0.52µs - -
stdb_module 🧠 16.0±0.45µs 16.2±0.47µs - -
stdb_raw 💿 105.1±0.04ns 103.6±0.05ns - -
stdb_raw 🧠 100.6±0.22ns 103.6±0.13ns - -

Single-row insertions

db on disk schema index type load new latency old latency new throughput old throughput
sqlite 💿 location multi_index 0 15.0±2.08µs 14.8±0.72µs 65.0 Ktx/sec 66.0 Ktx/sec
sqlite 💿 location multi_index 1000 15.9±0.10µs 15.8±0.10µs 61.3 Ktx/sec 61.9 Ktx/sec
sqlite 💿 location non_unique 0 7.3±0.03µs 7.2±0.05µs 134.1 Ktx/sec 136.1 Ktx/sec
sqlite 💿 location non_unique 1000 7.1±0.04µs 7.0±0.06µs 136.8 Ktx/sec 139.5 Ktx/sec
sqlite 💿 location unique 0 7.3±0.72µs 7.2±0.34µs 133.7 Ktx/sec 135.2 Ktx/sec
sqlite 💿 location unique 1000 7.2±0.05µs 7.0±0.04µs 135.8 Ktx/sec 138.9 Ktx/sec
sqlite 💿 person multi_index 0 14.4±0.04µs 14.6±1.21µs 67.7 Ktx/sec 66.7 Ktx/sec
sqlite 💿 person multi_index 1000 16.3±0.13µs 16.1±0.20µs 59.8 Ktx/sec 60.7 Ktx/sec
sqlite 💿 person non_unique 0 7.3±0.45µs 7.3±0.52µs 133.0 Ktx/sec 134.4 Ktx/sec
sqlite 💿 person non_unique 1000 7.4±0.06µs 7.2±0.06µs 132.0 Ktx/sec 135.6 Ktx/sec
sqlite 💿 person unique 0 7.3±0.04µs 7.2±0.05µs 134.0 Ktx/sec 135.4 Ktx/sec
sqlite 💿 person unique 1000 7.4±0.05µs 7.3±0.09µs 132.4 Ktx/sec 134.5 Ktx/sec
sqlite 🧠 location multi_index 0 4.1±0.01µs 4.1±0.01µs 239.3 Ktx/sec 235.9 Ktx/sec
sqlite 🧠 location multi_index 1000 5.3±0.02µs 5.3±0.04µs 184.5 Ktx/sec 183.3 Ktx/sec
sqlite 🧠 location non_unique 0 1898.7±4.99ns 1852.1±5.23ns 514.3 Ktx/sec 527.3 Ktx/sec
sqlite 🧠 location non_unique 1000 1936.7±15.49ns 1920.8±12.97ns 504.3 Ktx/sec 508.4 Ktx/sec
sqlite 🧠 location unique 0 1872.3±5.76ns 1843.7±5.45ns 521.6 Ktx/sec 529.7 Ktx/sec
sqlite 🧠 location unique 1000 1973.5±8.53ns 1956.9±13.38ns 494.8 Ktx/sec 499.0 Ktx/sec
sqlite 🧠 person multi_index 0 3.9±0.01µs 4.0±0.04µs 250.9 Ktx/sec 242.5 Ktx/sec
sqlite 🧠 person multi_index 1000 5.8±0.06µs 6.1±0.04µs 168.7 Ktx/sec 159.4 Ktx/sec
sqlite 🧠 person non_unique 0 1959.2±6.91ns 1949.1±6.90ns 498.4 Ktx/sec 501.0 Ktx/sec
sqlite 🧠 person non_unique 1000 2.1±0.10µs 2.0±0.01µs 468.6 Ktx/sec 477.2 Ktx/sec
sqlite 🧠 person unique 0 1947.1±8.65ns 1926.3±3.68ns 501.6 Ktx/sec 507.0 Ktx/sec
sqlite 🧠 person unique 1000 2.1±0.04µs 2.1±0.02µs 457.8 Ktx/sec 469.3 Ktx/sec
stdb_module 💿 location multi_index 0 38.6±6.19µs 39.3±4.92µs 25.3 Ktx/sec 24.9 Ktx/sec
stdb_module 💿 location multi_index 1000 316.9±155.44µs 508.3±88.61µs 3.1 Ktx/sec 1967 tx/sec
stdb_module 💿 location non_unique 0 34.9±2.79µs 32.8±4.27µs 28.0 Ktx/sec 29.8 Ktx/sec
stdb_module 💿 location non_unique 1000 252.5±19.61µs 327.7±108.61µs 3.9 Ktx/sec 3.0 Ktx/sec
stdb_module 💿 location unique 0 36.9±4.67µs 37.8±3.18µs 26.5 Ktx/sec 25.8 Ktx/sec
stdb_module 💿 location unique 1000 179.6±51.66µs 220.7±17.37µs 5.4 Ktx/sec 4.4 Ktx/sec
stdb_module 💿 person multi_index 0 53.4±5.81µs 48.9±6.74µs 18.3 Ktx/sec 20.0 Ktx/sec
stdb_module 💿 person multi_index 1000 543.5±17.70µs 572.4±30.09µs 1839 tx/sec 1747 tx/sec
stdb_module 💿 person non_unique 0 38.4±4.55µs 35.9±4.12µs 25.4 Ktx/sec 27.2 Ktx/sec
stdb_module 💿 person non_unique 1000 316.3±25.43µs 263.4±24.61µs 3.1 Ktx/sec 3.7 Ktx/sec
stdb_module 💿 person unique 0 46.7±4.34µs 44.9±4.84µs 20.9 Ktx/sec 21.7 Ktx/sec
stdb_module 💿 person unique 1000 498.8±15.08µs 443.8±23.96µs 2004 tx/sec 2.2 Ktx/sec
stdb_module 🧠 location multi_index 0 33.2±3.64µs 29.7±2.27µs 29.4 Ktx/sec 32.9 Ktx/sec
stdb_module 🧠 location multi_index 1000 212.5±9.86µs 393.0±14.15µs 4.6 Ktx/sec 2.5 Ktx/sec
stdb_module 🧠 location non_unique 0 26.8±2.39µs 27.7±2.44µs 36.4 Ktx/sec 35.3 Ktx/sec
stdb_module 🧠 location non_unique 1000 182.0±2.02µs 216.2±17.14µs 5.4 Ktx/sec 4.5 Ktx/sec
stdb_module 🧠 location unique 0 27.8±2.44µs 27.5±3.55µs 35.2 Ktx/sec 35.6 Ktx/sec
stdb_module 🧠 location unique 1000 350.9±6.97µs 193.1±86.48µs 2.8 Ktx/sec 5.1 Ktx/sec
stdb_module 🧠 person multi_index 0 39.7±3.96µs 37.8±2.92µs 24.6 Ktx/sec 25.8 Ktx/sec
stdb_module 🧠 person multi_index 1000 216.4±23.46µs 434.2±106.92µs 4.5 Ktx/sec 2.2 Ktx/sec
stdb_module 🧠 person non_unique 0 27.8±2.26µs 27.6±1.75µs 35.1 Ktx/sec 35.4 Ktx/sec
stdb_module 🧠 person non_unique 1000 257.6±31.94µs 230.0±10.77µs 3.8 Ktx/sec 4.2 Ktx/sec
stdb_module 🧠 person unique 0 33.3±2.72µs 32.5±2.64µs 29.3 Ktx/sec 30.0 Ktx/sec
stdb_module 🧠 person unique 1000 344.8±8.07µs 276.9±33.25µs 2.8 Ktx/sec 3.5 Ktx/sec
stdb_raw 💿 location multi_index 0 5.3±0.01µs 5.3±0.03µs 182.8 Ktx/sec 185.3 Ktx/sec
stdb_raw 💿 location multi_index 1000 34.0±0.65µs 60.7±280.69µs 28.7 Ktx/sec 16.1 Ktx/sec
stdb_raw 💿 location non_unique 0 3.5±0.01µs 3.5±0.01µs 276.0 Ktx/sec 277.3 Ktx/sec
stdb_raw 💿 location non_unique 1000 21.7±0.18µs 21.7±0.19µs 44.9 Ktx/sec 45.0 Ktx/sec
stdb_raw 💿 location unique 0 4.3±0.01µs 4.3±0.27µs 225.9 Ktx/sec 225.8 Ktx/sec
stdb_raw 💿 location unique 1000 26.8±0.18µs 48.3±215.18µs 36.5 Ktx/sec 20.2 Ktx/sec
stdb_raw 💿 person multi_index 0 9.1±0.01µs 9.0±0.21µs 107.6 Ktx/sec 108.1 Ktx/sec
stdb_raw 💿 person multi_index 1000 25.5±1.03µs 69.7±448.70µs 38.3 Ktx/sec 14.0 Ktx/sec
stdb_raw 💿 person non_unique 0 4.2±0.04µs 4.1±0.01µs 232.8 Ktx/sec 235.6 Ktx/sec
stdb_raw 💿 person non_unique 1000 29.4±149.17µs 14.1±0.15µs 33.3 Ktx/sec 69.4 Ktx/sec
stdb_raw 💿 person unique 0 6.0±0.01µs 6.0±0.31µs 163.3 Ktx/sec 163.6 Ktx/sec
stdb_raw 💿 person unique 1000 21.5±0.41µs 21.5±0.46µs 45.3 Ktx/sec 45.4 Ktx/sec
stdb_raw 🧠 location multi_index 0 4.2±0.01µs 4.2±0.01µs 229.8 Ktx/sec 233.0 Ktx/sec
stdb_raw 🧠 location multi_index 1000 28.8±0.72µs 28.9±0.55µs 34.0 Ktx/sec 33.8 Ktx/sec
stdb_raw 🧠 location non_unique 0 2.3±0.01µs 2.3±0.00µs 428.3 Ktx/sec 430.2 Ktx/sec
stdb_raw 🧠 location non_unique 1000 18.7±0.05µs 19.4±0.12µs 52.2 Ktx/sec 50.3 Ktx/sec
stdb_raw 🧠 location unique 0 3.1±0.01µs 3.1±0.01µs 313.6 Ktx/sec 317.6 Ktx/sec
stdb_raw 🧠 location unique 1000 24.6±0.35µs 24.9±0.23µs 39.7 Ktx/sec 39.3 Ktx/sec
stdb_raw 🧠 person multi_index 0 7.7±0.01µs 7.6±0.01µs 127.2 Ktx/sec 127.7 Ktx/sec
stdb_raw 🧠 person multi_index 1000 21.9±1.41µs 22.0±1.21µs 44.6 Ktx/sec 44.4 Ktx/sec
stdb_raw 🧠 person non_unique 0 2.9±0.00µs 2.9±0.01µs 335.7 Ktx/sec 341.2 Ktx/sec
stdb_raw 🧠 person non_unique 1000 13.1±0.18µs 12.8±0.15µs 74.7 Ktx/sec 76.3 Ktx/sec
stdb_raw 🧠 person unique 0 4.6±0.01µs 4.6±0.01µs 210.9 Ktx/sec 211.2 Ktx/sec
stdb_raw 🧠 person unique 1000 17.2±0.56µs 17.1±0.57µs 56.9 Ktx/sec 57.1 Ktx/sec

Multi-row insertions

db on disk schema index type load count new latency old latency new throughput old throughput
sqlite 💿 location multi_index 0 100 129.7±0.52µs 131.6±5.30µs 7.5 Ktx/sec 7.4 Ktx/sec
sqlite 💿 location multi_index 1000 100 203.9±1.44µs 207.0±41.89µs 4.8 Ktx/sec 4.7 Ktx/sec
sqlite 💿 location non_unique 0 100 49.9±1.03µs 50.4±1.82µs 19.6 Ktx/sec 19.4 Ktx/sec
sqlite 💿 location non_unique 1000 100 52.4±0.38µs 53.2±0.37µs 18.6 Ktx/sec 18.4 Ktx/sec
sqlite 💿 location unique 0 100 52.3±1.23µs 52.3±0.29µs 18.7 Ktx/sec 18.7 Ktx/sec
sqlite 💿 location unique 1000 100 57.1±0.29µs 57.5±0.41µs 17.1 Ktx/sec 17.0 Ktx/sec
sqlite 💿 person multi_index 0 100 120.7±3.44µs 121.0±6.65µs 8.1 Ktx/sec 8.1 Ktx/sec
sqlite 💿 person multi_index 1000 100 238.6±37.87µs 230.1±0.45µs 4.1 Ktx/sec 4.2 Ktx/sec
sqlite 💿 person non_unique 0 100 50.5±1.20µs 49.6±0.45µs 19.4 Ktx/sec 19.7 Ktx/sec
sqlite 💿 person non_unique 1000 100 61.2±0.29µs 62.9±0.48µs 15.9 Ktx/sec 15.5 Ktx/sec
sqlite 💿 person unique 0 100 52.9±2.81µs 52.0±3.97µs 18.5 Ktx/sec 18.8 Ktx/sec
sqlite 💿 person unique 1000 100 57.9±0.28µs 56.8±0.33µs 16.9 Ktx/sec 17.2 Ktx/sec
sqlite 🧠 location multi_index 0 100 119.2±0.32µs 119.3±0.41µs 8.2 Ktx/sec 8.2 Ktx/sec
sqlite 🧠 location multi_index 1000 100 171.8±0.42µs 171.1±0.61µs 5.7 Ktx/sec 5.7 Ktx/sec
sqlite 🧠 location non_unique 0 100 44.7±0.42µs 43.1±0.41µs 21.9 Ktx/sec 22.7 Ktx/sec
sqlite 🧠 location non_unique 1000 100 45.5±0.44µs 45.5±0.35µs 21.5 Ktx/sec 21.5 Ktx/sec
sqlite 🧠 location unique 0 100 46.0±0.25µs 46.1±0.36µs 21.2 Ktx/sec 21.2 Ktx/sec
sqlite 🧠 location unique 1000 100 48.4±0.31µs 48.8±0.34µs 20.2 Ktx/sec 20.0 Ktx/sec
sqlite 🧠 person multi_index 0 100 109.2±0.49µs 107.9±0.35µs 8.9 Ktx/sec 9.1 Ktx/sec
sqlite 🧠 person multi_index 1000 100 191.8±0.35µs 190.2±0.56µs 5.1 Ktx/sec 5.1 Ktx/sec
sqlite 🧠 person non_unique 0 100 44.3±0.29µs 45.2±0.40µs 22.1 Ktx/sec 21.6 Ktx/sec
sqlite 🧠 person non_unique 1000 100 48.0±0.33µs 48.4±0.27µs 20.3 Ktx/sec 20.2 Ktx/sec
sqlite 🧠 person unique 0 100 46.2±0.52µs 45.3±0.20µs 21.2 Ktx/sec 21.5 Ktx/sec
sqlite 🧠 person unique 1000 100 50.2±0.52µs 50.5±0.41µs 19.5 Ktx/sec 19.3 Ktx/sec
stdb_module 💿 location multi_index 0 100 805.2±179.41µs 711.1±105.69µs 1241 tx/sec 1406 tx/sec
stdb_module 💿 location multi_index 1000 100 900.3±52.17µs 871.8±66.92µs 1110 tx/sec 1147 tx/sec
stdb_module 💿 location non_unique 0 100 531.1±19.87µs 526.1±36.45µs 1882 tx/sec 1900 tx/sec
stdb_module 💿 location non_unique 1000 100 788.1±80.09µs 763.1±98.29µs 1268 tx/sec 1310 tx/sec
stdb_module 💿 location unique 0 100 547.3±52.22µs 676.8±8.54µs 1827 tx/sec 1477 tx/sec
stdb_module 💿 location unique 1000 100 837.3±68.52µs 986.1±105.83µs 1194 tx/sec 1014 tx/sec
stdb_module 💿 person multi_index 0 100 1482.9±9.38µs 939.8±100.58µs 674 tx/sec 1064 tx/sec
stdb_module 💿 person multi_index 1000 100 1175.7±207.44µs 1852.6±12.42µs 850 tx/sec 539 tx/sec
stdb_module 💿 person non_unique 0 100 686.4±3.54µs 682.5±22.44µs 1456 tx/sec 1465 tx/sec
stdb_module 💿 person non_unique 1000 100 1024.0±14.92µs 1059.5±43.28µs 976 tx/sec 943 tx/sec
stdb_module 💿 person unique 0 100 985.7±3.60µs 975.1±19.65µs 1014 tx/sec 1025 tx/sec
stdb_module 💿 person unique 1000 100 1410.1±112.92µs 1426.1±19.85µs 709 tx/sec 701 tx/sec
stdb_module 🧠 location multi_index 0 100 746.8±7.01µs 737.7±4.62µs 1339 tx/sec 1355 tx/sec
stdb_module 🧠 location multi_index 1000 100 990.0±107.93µs 1002.1±35.47µs 1010 tx/sec 997 tx/sec
stdb_module 🧠 location non_unique 0 100 433.8±12.17µs 429.0±10.35µs 2.3 Ktx/sec 2.3 Ktx/sec
stdb_module 🧠 location non_unique 1000 100 588.4±3.38µs 615.8±5.29µs 1699 tx/sec 1623 tx/sec
stdb_module 🧠 location unique 0 100 581.3±1.99µs 579.5±1.33µs 1720 tx/sec 1725 tx/sec
stdb_module 🧠 location unique 1000 100 887.1±23.43µs 888.7±34.57µs 1127 tx/sec 1125 tx/sec
stdb_module 🧠 person multi_index 0 100 1357.1±38.50µs 901.1±10.95µs 736 tx/sec 1109 tx/sec
stdb_module 🧠 person multi_index 1000 100 1431.0±15.00µs 1266.2±231.00µs 698 tx/sec 789 tx/sec
stdb_module 🧠 person non_unique 0 100 553.3±30.50µs 604.5±2.07µs 1807 tx/sec 1654 tx/sec
stdb_module 🧠 person non_unique 1000 100 762.4±8.18µs 843.3±9.85µs 1311 tx/sec 1185 tx/sec
stdb_module 🧠 person unique 0 100 856.7±16.98µs 852.6±17.34µs 1167 tx/sec 1172 tx/sec
stdb_module 🧠 person unique 1000 100 1106.2±10.17µs 1307.0±49.49µs 904 tx/sec 765 tx/sec
stdb_raw 💿 location multi_index 0 100 317.8±16.81µs 314.3±37.31µs 3.1 Ktx/sec 3.1 Ktx/sec
stdb_raw 💿 location multi_index 1000 100 369.4±1.43µs 391.5±310.16µs 2.6 Ktx/sec 2.5 Ktx/sec
stdb_raw 💿 location non_unique 0 100 145.8±0.14µs 146.4±8.41µs 6.7 Ktx/sec 6.7 Ktx/sec
stdb_raw 💿 location non_unique 1000 100 168.8±1.12µs 180.8±136.57µs 5.8 Ktx/sec 5.4 Ktx/sec
stdb_raw 💿 location unique 0 100 226.1±8.12µs 222.7±0.21µs 4.3 Ktx/sec 4.4 Ktx/sec
stdb_raw 💿 location unique 1000 100 271.1±1.46µs 270.0±1.69µs 3.6 Ktx/sec 3.6 Ktx/sec
stdb_raw 💿 person multi_index 0 100 657.1±16.88µs 649.7±0.57µs 1521 tx/sec 1539 tx/sec
stdb_raw 💿 person multi_index 1000 100 709.3±1.28µs 747.9±473.72µs 1409 tx/sec 1337 tx/sec
stdb_raw 💿 person non_unique 0 100 203.7±9.91µs 201.2±12.58µs 4.8 Ktx/sec 4.9 Ktx/sec
stdb_raw 💿 person non_unique 1000 100 240.7±161.86µs 223.1±0.65µs 4.1 Ktx/sec 4.4 Ktx/sec
stdb_raw 💿 person unique 0 100 369.4±1.49µs 363.8±0.35µs 2.6 Ktx/sec 2.7 Ktx/sec
stdb_raw 💿 person unique 1000 100 409.0±0.99µs 440.5±333.79µs 2.4 Ktx/sec 2.2 Ktx/sec
stdb_raw 🧠 location multi_index 0 100 321.1±0.51µs 313.7±0.89µs 3.0 Ktx/sec 3.1 Ktx/sec
stdb_raw 🧠 location multi_index 1000 100 370.0±0.67µs 361.1±0.61µs 2.6 Ktx/sec 2.7 Ktx/sec
stdb_raw 🧠 location non_unique 0 100 141.7±0.88µs 139.6±0.66µs 6.9 Ktx/sec 7.0 Ktx/sec
stdb_raw 🧠 location non_unique 1000 100 164.5±0.96µs 161.9±0.19µs 5.9 Ktx/sec 6.0 Ktx/sec
stdb_raw 🧠 location unique 0 100 221.5±0.88µs 217.3±0.40µs 4.4 Ktx/sec 4.5 Ktx/sec
stdb_raw 🧠 location unique 1000 100 268.1±0.95µs 266.2±0.77µs 3.6 Ktx/sec 3.7 Ktx/sec
stdb_raw 🧠 person multi_index 0 100 657.1±0.47µs 643.1±0.45µs 1521 tx/sec 1554 tx/sec
stdb_raw 🧠 person multi_index 1000 100 721.5±2.13µs 694.1±1.65µs 1385 tx/sec 1440 tx/sec
stdb_raw 🧠 person non_unique 0 100 199.2±0.15µs 196.2±0.16µs 4.9 Ktx/sec 5.0 Ktx/sec
stdb_raw 🧠 person non_unique 1000 100 222.9±0.86µs 216.9±0.56µs 4.4 Ktx/sec 4.5 Ktx/sec
stdb_raw 🧠 person unique 0 100 364.4±0.28µs 358.8±0.36µs 2.7 Ktx/sec 2.7 Ktx/sec
stdb_raw 🧠 person unique 1000 100 406.0±0.92µs 404.6±0.68µs 2.4 Ktx/sec 2.4 Ktx/sec

Full table iterate

db on disk schema index type new latency old latency new throughput old throughput
sqlite 💿 location unique 8.9±0.13µs 9.0±0.09µs 109.4 Ktx/sec 108.3 Ktx/sec
sqlite 💿 person unique 9.4±0.09µs 10.4±0.11µs 103.6 Ktx/sec 94.3 Ktx/sec
sqlite 🧠 location unique 7.8±0.15µs 7.9±0.10µs 124.5 Ktx/sec 123.7 Ktx/sec
sqlite 🧠 person unique 8.0±0.08µs 9.0±0.11µs 121.7 Ktx/sec 108.0 Ktx/sec
stdb_module 💿 location unique 42.6±2.48µs 45.5±4.06µs 22.9 Ktx/sec 21.5 Ktx/sec
stdb_module 💿 person unique 57.1±8.84µs 53.6±9.23µs 17.1 Ktx/sec 18.2 Ktx/sec
stdb_module 🧠 location unique 44.6±3.11µs 45.4±3.22µs 21.9 Ktx/sec 21.5 Ktx/sec
stdb_module 🧠 person unique 57.4±7.24µs 63.4±4.80µs 17.0 Ktx/sec 15.4 Ktx/sec
stdb_raw 💿 location unique 11.3±0.02µs 10.6±0.02µs 86.3 Ktx/sec 91.9 Ktx/sec
stdb_raw 💿 person unique 12.7±0.01µs 11.8±0.03µs 76.6 Ktx/sec 83.0 Ktx/sec
stdb_raw 🧠 location unique 11.3±0.01µs 10.6±0.01µs 86.4 Ktx/sec 92.0 Ktx/sec
stdb_raw 🧠 person unique 12.6±0.15µs 11.8±0.03µs 77.3 Ktx/sec 82.8 Ktx/sec

Find unique key

db on disk key type load new latency old latency new throughput old throughput
sqlite 💿 u32 1000 2.4±0.01µs 2.4±0.01µs 407.3 Ktx/sec 413.1 Ktx/sec
sqlite 🧠 u32 1000 1156.8±6.15ns 1175.6±15.05ns 844.2 Ktx/sec 830.7 Ktx/sec
stdb_module 💿 u32 1000 17.6±0.58µs 17.4±0.31µs 55.5 Ktx/sec 56.0 Ktx/sec
stdb_module 🧠 u32 1000 18.1±0.95µs 17.8±0.38µs 54.0 Ktx/sec 54.9 Ktx/sec
stdb_raw 💿 u32 1000 496.5±1.04ns 494.8±1.45ns 1966.8 Ktx/sec 1973.8 Ktx/sec
stdb_raw 🧠 u32 1000 495.9±1.15ns 489.0±1.49ns 1969.5 Ktx/sec 1997.1 Ktx/sec

Filter

db on disk key type index strategy load count new latency old latency new throughput old throughput
sqlite 💿 string indexed 1000 10 5.8±0.03µs 5.7±0.02µs 168.3 Ktx/sec 169.9 Ktx/sec
sqlite 💿 string non_indexed 1000 10 48.7±0.30µs 60.2±0.61µs 20.1 Ktx/sec 16.2 Ktx/sec
sqlite 💿 u64 indexed 1000 10 5.6±0.01µs 5.4±0.02µs 174.6 Ktx/sec 180.2 Ktx/sec
sqlite 💿 u64 non_indexed 1000 10 32.9±0.07µs 32.9±0.05µs 29.7 Ktx/sec 29.7 Ktx/sec
sqlite 🧠 string indexed 1000 10 4.3±0.02µs 4.3±0.02µs 227.8 Ktx/sec 226.1 Ktx/sec
sqlite 🧠 string non_indexed 1000 10 47.4±0.44µs 57.4±0.49µs 20.6 Ktx/sec 17.0 Ktx/sec
sqlite 🧠 u64 indexed 1000 10 4.2±0.02µs 4.0±0.01µs 234.9 Ktx/sec 243.2 Ktx/sec
sqlite 🧠 u64 non_indexed 1000 10 31.5±0.10µs 32.2±0.07µs 31.0 Ktx/sec 30.3 Ktx/sec
stdb_module 💿 string indexed 1000 10 24.8±1.98µs 24.8±2.24µs 39.4 Ktx/sec 39.3 Ktx/sec
stdb_module 💿 string non_indexed 1000 10 199.8±1.23µs 215.5±2.11µs 4.9 Ktx/sec 4.5 Ktx/sec
stdb_module 💿 u64 indexed 1000 10 21.0±1.57µs 20.7±0.89µs 46.5 Ktx/sec 47.1 Ktx/sec
stdb_module 💿 u64 non_indexed 1000 10 163.7±4.43µs 169.8±5.38µs 6.0 Ktx/sec 5.8 Ktx/sec
stdb_module 🧠 string indexed 1000 10 26.4±2.41µs 25.5±2.20µs 37.0 Ktx/sec 38.3 Ktx/sec
stdb_module 🧠 string non_indexed 1000 10 194.4±3.65µs 209.8±2.24µs 5.0 Ktx/sec 4.7 Ktx/sec
stdb_module 🧠 u64 indexed 1000 10 21.3±1.21µs 21.3±1.17µs 45.9 Ktx/sec 45.8 Ktx/sec
stdb_module 🧠 u64 non_indexed 1000 10 159.7±3.26µs 164.1±2.89µs 6.1 Ktx/sec 6.0 Ktx/sec
stdb_raw 💿 string indexed 1000 10 2.5±0.00µs 2.5±0.00µs 388.6 Ktx/sec 388.7 Ktx/sec
stdb_raw 💿 string non_indexed 1000 10 174.3±0.60µs 181.4±0.44µs 5.6 Ktx/sec 5.4 Ktx/sec
stdb_raw 💿 u64 indexed 1000 10 2.3±0.00µs 2.3±0.00µs 428.4 Ktx/sec 423.5 Ktx/sec
stdb_raw 💿 u64 non_indexed 1000 10 123.5±0.39µs 146.0±0.23µs 7.9 Ktx/sec 6.7 Ktx/sec
stdb_raw 🧠 string indexed 1000 10 2.5±0.00µs 2.5±0.00µs 387.4 Ktx/sec 388.7 Ktx/sec
stdb_raw 🧠 string non_indexed 1000 10 174.2±0.42µs 181.8±0.64µs 5.6 Ktx/sec 5.4 Ktx/sec
stdb_raw 🧠 u64 indexed 1000 10 2.3±0.00µs 2.3±0.01µs 430.6 Ktx/sec 428.6 Ktx/sec
stdb_raw 🧠 u64 non_indexed 1000 10 123.8±0.18µs 148.0±0.22µs 7.9 Ktx/sec 6.6 Ktx/sec

Serialize

schema format count new latency old latency new throughput old throughput
location bsatn 100 1850.8±30.99ns 1767.0±32.53ns 51.5 Mtx/sec 54.0 Mtx/sec
location json 100 3.5±0.05µs 3.3±0.03µs 26.9 Mtx/sec 28.8 Mtx/sec
location product_value 100 2.5±0.01µs 2.4±0.01µs 38.8 Mtx/sec 39.8 Mtx/sec
person bsatn 100 2.6±0.02µs 2.4±0.04µs 36.9 Mtx/sec 39.0 Mtx/sec
person json 100 5.0±0.03µs 5.0±0.02µs 19.0 Mtx/sec 19.2 Mtx/sec
person product_value 100 1628.3±11.04ns 1615.5±10.22ns 58.6 Mtx/sec 59.0 Mtx/sec

Module: invoke with large arguments

arg size new latency old latency new throughput old throughput
64KiB 77.3±6.99µs 79.2±4.72µs - -

Module: print bulk

line count new latency old latency new throughput old throughput
1 20.4±1.51µs 20.1±1.03µs - -
100 197.1±1.30µs 200.1±3.42µs - -
1000 1985.1±22.47µs 1920.7±76.11µs - -

Remaining benchmarks

name new latency old latency new throughput old throughput

Please sign in to comment.