Skip to content

Commit 8afe0b8

Browse files
ndr-dsndr-ds
committed
Measure operation/message execution latency in microseconds
1 parent 5fe1acb commit 8afe0b8

32 files changed

+215
-114
lines changed

‎linera-base/src/data_types.rs‎

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ use serde_with::{serde_as, Bytes};
2727
use thiserror::Error;
2828

2929
#[cfg(with_metrics)]
30-
use crate::prometheus_util::MeasureLatency as _;
30+
use crate::prometheus_util::{MeasureLatency as _, MeasurementUnit};
3131
use crate::{
3232
crypto::{BcsHashable, CryptoError, CryptoHash},
3333
doc_scalar, hex_debug, http,
@@ -1151,7 +1151,8 @@ impl Bytecode {
11511151
#[cfg(not(target_arch = "wasm32"))]
11521152
pub fn compress(&self) -> CompressedBytecode {
11531153
#[cfg(with_metrics)]
1154-
let _compression_latency = metrics::BYTECODE_COMPRESSION_LATENCY.measure_latency();
1154+
let _compression_latency =
1155+
metrics::BYTECODE_COMPRESSION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
11551156
let compressed_bytes_vec = zstd::stream::encode_all(&*self.bytes, 19)
11561157
.expect("Compressing bytes in memory should not fail");
11571158

@@ -1166,7 +1167,8 @@ impl Bytecode {
11661167
use ruzstd::encoding::{CompressionLevel, FrameCompressor};
11671168

11681169
#[cfg(with_metrics)]
1169-
let _compression_latency = metrics::BYTECODE_COMPRESSION_LATENCY.measure_latency();
1170+
let _compression_latency =
1171+
metrics::BYTECODE_COMPRESSION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
11701172

11711173
let mut compressed_bytes_vec = Vec::new();
11721174
let mut compressor = FrameCompressor::new(CompressionLevel::Fastest);
@@ -1227,7 +1229,8 @@ impl CompressedBytecode {
12271229
/// Decompresses a [`CompressedBytecode`] into a [`Bytecode`].
12281230
pub fn decompress(&self) -> Result<Bytecode, DecompressionError> {
12291231
#[cfg(with_metrics)]
1230-
let _decompression_latency = metrics::BYTECODE_DECOMPRESSION_LATENCY.measure_latency();
1232+
let _decompression_latency =
1233+
metrics::BYTECODE_DECOMPRESSION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
12311234
let bytes = zstd::stream::decode_all(&**self.compressed_bytes)?;
12321235

12331236
Ok(Bytecode { bytes })
@@ -1261,7 +1264,8 @@ impl CompressedBytecode {
12611264
use ruzstd::{decoding::StreamingDecoder, io::Read};
12621265

12631266
#[cfg(with_metrics)]
1264-
let _decompression_latency = BYTECODE_DECOMPRESSION_LATENCY.measure_latency();
1267+
let _decompression_latency =
1268+
metrics::BYTECODE_DECOMPRESSION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
12651269

12661270
let compressed_bytes = &*self.compressed_bytes;
12671271
let mut bytes = Vec::new();

‎linera-base/src/prometheus_util.rs‎

Lines changed: 34 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -100,6 +100,18 @@ pub fn linear_bucket_interval(start_value: f64, width: f64, end_value: f64) -> O
100100
Some(buckets)
101101
}
102102

103+
/// The unit of measurement for latency metrics.
104+
pub enum MeasurementUnit {
105+
/// Measure latency in seconds.
106+
Seconds,
107+
/// Measure latency in milliseconds.
108+
Milliseconds,
109+
/// Measure latency in microseconds.
110+
Microseconds,
111+
/// Measure latency in nanoseconds.
112+
Nanoseconds,
113+
}
114+
103115
/// A guard for an active latency measurement.
104116
///
105117
/// Finishes the measurement when dropped, and then updates the `Metric`.
@@ -109,6 +121,7 @@ where
109121
{
110122
start: Instant,
111123
metric: Option<&'metric Metric>,
124+
unit: MeasurementUnit,
112125
}
113126

114127
impl<Metric> ActiveMeasurementGuard<'_, Metric>
@@ -126,7 +139,16 @@ where
126139
fn finish_by_ref(&mut self) -> f64 {
127140
match self.metric.take() {
128141
Some(metric) => {
129-
let latency = self.start.elapsed().as_secs_f64() * 1000.0;
142+
let latency = match self.unit {
143+
MeasurementUnit::Seconds => self.start.elapsed().as_secs_f64(),
144+
MeasurementUnit::Milliseconds => self.start.elapsed().as_secs_f64() * 1000.0,
145+
MeasurementUnit::Microseconds => {
146+
self.start.elapsed().as_secs_f64() * 1_000_000.0
147+
}
148+
MeasurementUnit::Nanoseconds => {
149+
self.start.elapsed().as_secs_f64() * 1_000_000_000.0
150+
}
151+
};
130152
metric.finish_measurement(latency);
131153
latency
132154
}
@@ -152,35 +174,37 @@ where
152174
pub trait MeasureLatency: Sized {
153175
/// Starts measuring the latency, finishing when the returned
154176
/// [`ActiveMeasurementGuard`] is dropped.
155-
fn measure_latency(&self) -> ActiveMeasurementGuard<'_, Self>;
177+
fn measure_latency(&self, unit: MeasurementUnit) -> ActiveMeasurementGuard<'_, Self>;
156178

157-
/// Updates the metric with measured latency in `milliseconds`.
158-
fn finish_measurement(&self, milliseconds: f64);
179+
/// Updates the metric with measured latency in specified unit.
180+
fn finish_measurement(&self, value: f64);
159181
}
160182

161183
impl MeasureLatency for HistogramVec {
162-
fn measure_latency(&self) -> ActiveMeasurementGuard<'_, Self> {
184+
fn measure_latency(&self, unit: MeasurementUnit) -> ActiveMeasurementGuard<'_, Self> {
163185
ActiveMeasurementGuard {
164186
start: Instant::now(),
165187
metric: Some(self),
188+
unit,
166189
}
167190
}
168191

169-
fn finish_measurement(&self, milliseconds: f64) {
170-
self.with_label_values(&[]).observe(milliseconds);
192+
fn finish_measurement(&self, value: f64) {
193+
self.with_label_values(&[]).observe(value);
171194
}
172195
}
173196

174197
impl MeasureLatency for Histogram {
175-
fn measure_latency(&self) -> ActiveMeasurementGuard<'_, Self> {
198+
fn measure_latency(&self, unit: MeasurementUnit) -> ActiveMeasurementGuard<'_, Self> {
176199
ActiveMeasurementGuard {
177200
start: Instant::now(),
178201
metric: Some(self),
202+
unit,
179203
}
180204
}
181205

182-
fn finish_measurement(&self, milliseconds: f64) {
183-
self.observe(milliseconds);
206+
fn finish_measurement(&self, value: f64) {
207+
self.observe(value);
184208
}
185209
}
186210

‎linera-chain/src/block_tracker.rs‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ use std::collections::{BTreeMap, BTreeSet};
55

66
use custom_debug_derive::Debug;
77
#[cfg(with_metrics)]
8-
use linera_base::prometheus_util::MeasureLatency;
8+
use linera_base::prometheus_util::{MeasureLatency, MeasurementUnit};
99
use linera_base::{
1010
data_types::{Amount, Blob, BlockHeight, Event, OracleResponse, Timestamp},
1111
ensure,
@@ -141,7 +141,8 @@ impl<'resources, 'blobs> BlockExecutionTracker<'resources, 'blobs> {
141141
.track_block_size_of(&operation)
142142
.with_execution_context(chain_execution_context)?;
143143
#[cfg(with_metrics)]
144-
let _operation_latency = metrics::OPERATION_EXECUTION_LATENCY.measure_latency();
144+
let _operation_latency = metrics::OPERATION_EXECUTION_LATENCY
145+
.measure_latency(MeasurementUnit::Microseconds);
145146
let context = OperationContext {
146147
chain_id: self.chain_id,
147148
height: self.block_height,
@@ -196,7 +197,8 @@ impl<'resources, 'blobs> BlockExecutionTracker<'resources, 'blobs> {
196197
C::Extra: ExecutionRuntimeContext,
197198
{
198199
#[cfg(with_metrics)]
199-
let _message_latency = metrics::MESSAGE_EXECUTION_LATENCY.measure_latency();
200+
let _message_latency =
201+
metrics::MESSAGE_EXECUTION_LATENCY.measure_latency(MeasurementUnit::Microseconds);
200202
let context = MessageContext {
201203
chain_id: self.chain_id,
202204
origin: incoming_bundle.origin,

‎linera-chain/src/chain.rs‎

Lines changed: 7 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -54,7 +54,7 @@ use crate::{
5454
mod chain_tests;
5555

5656
#[cfg(with_metrics)]
57-
use linera_base::prometheus_util::MeasureLatency;
57+
use linera_base::prometheus_util::{MeasureLatency, MeasurementUnit};
5858

5959
#[cfg(with_metrics)]
6060
pub(crate) mod metrics {
@@ -86,7 +86,7 @@ pub(crate) mod metrics {
8686
"message_execution_latency",
8787
"Message execution latency",
8888
&[],
89-
exponential_bucket_latencies(50.0),
89+
exponential_bucket_interval(0.1_f64, 50_000.0),
9090
)
9191
});
9292

@@ -95,7 +95,7 @@ pub(crate) mod metrics {
9595
"operation_execution_latency",
9696
"Operation execution latency",
9797
&[],
98-
exponential_bucket_latencies(50.0),
98+
exponential_bucket_interval(0.1_f64, 50_000.0),
9999
)
100100
});
101101

@@ -780,7 +780,8 @@ where
780780
replaying_oracle_responses: Option<Vec<Vec<OracleResponse>>>,
781781
) -> Result<BlockExecutionOutcome, ChainError> {
782782
#[cfg(with_metrics)]
783-
let _execution_latency = metrics::BLOCK_EXECUTION_LATENCY.measure_latency();
783+
let _execution_latency =
784+
metrics::BLOCK_EXECUTION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
784785
chain.system.timestamp.set(block.timestamp);
785786

786787
let policy = chain
@@ -868,7 +869,8 @@ where
868869

869870
let state_hash = {
870871
#[cfg(with_metrics)]
871-
let _hash_latency = metrics::STATE_HASH_COMPUTATION_LATENCY.measure_latency();
872+
let _hash_latency = metrics::STATE_HASH_COMPUTATION_LATENCY
873+
.measure_latency(MeasurementUnit::Milliseconds);
872874
chain.crypto_hash_mut().await?
873875
};
874876

‎linera-core/src/chain_worker/state.rs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@ use std::{
1212

1313
use futures::future::Either;
1414
#[cfg(with_metrics)]
15-
use linera_base::prometheus_util::MeasureLatency as _;
15+
use linera_base::prometheus_util::{MeasureLatency, MeasurementUnit};
1616
use linera_base::{
1717
crypto::{CryptoHash, ValidatorPublicKey},
1818
data_types::{
@@ -438,7 +438,8 @@ where
438438
old_round: Option<Round>,
439439
) -> Result<NetworkActions, WorkerError> {
440440
#[cfg(with_metrics)]
441-
let _latency = metrics::CREATE_NETWORK_ACTIONS_LATENCY.measure_latency();
441+
let _latency =
442+
metrics::CREATE_NETWORK_ACTIONS_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
442443
let mut heights_by_recipient = BTreeMap::<_, Vec<_>>::new();
443444
let mut targets = self.chain.nonempty_outbox_chain_ids();
444445
if let Some(tracked_chains) = self.tracked_chains.as_ref() {

‎linera-core/src/client/chain_client/mod.rs‎

Lines changed: 9 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ use futures::{
1616
stream::{self, AbortHandle, FusedStream, FuturesUnordered, StreamExt, TryStreamExt},
1717
};
1818
#[cfg(with_metrics)]
19-
use linera_base::prometheus_util::MeasureLatency as _;
19+
use linera_base::prometheus_util::{MeasureLatency as _, MeasurementUnit};
2020
use linera_base::{
2121
abi::Abi,
2222
crypto::{signer, AccountPublicKey, CryptoHash, Signer, ValidatorPublicKey},
@@ -668,7 +668,8 @@ impl<Env: Environment> ChainClient<Env> {
668668
#[instrument(level = "trace")]
669669
pub async fn prepare_chain(&self) -> Result<Box<ChainInfo>, Error> {
670670
#[cfg(with_metrics)]
671-
let _latency = super::metrics::PREPARE_CHAIN_LATENCY.measure_latency();
671+
let _latency =
672+
super::metrics::PREPARE_CHAIN_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
672673

673674
let mut info = self.synchronize_to_known_height().await?;
674675

@@ -802,7 +803,8 @@ impl<Env: Environment> ChainClient<Env> {
802803
) -> Result<(), Error> {
803804
debug!(chain_id = %self.chain_id, "starting find_received_certificates");
804805
#[cfg(with_metrics)]
805-
let _latency = super::metrics::FIND_RECEIVED_CERTIFICATES_LATENCY.measure_latency();
806+
let _latency = super::metrics::FIND_RECEIVED_CERTIFICATES_LATENCY
807+
.measure_latency(MeasurementUnit::Milliseconds);
806808
// Use network information from the local chain.
807809
let chain_id = self.chain_id;
808810
let (_, committee) = self.admin_committee().await?;
@@ -1257,7 +1259,8 @@ impl<Env: Environment> ChainClient<Env> {
12571259
blobs: Vec<Blob>,
12581260
) -> Result<ExecuteBlockOutcome, Error> {
12591261
#[cfg(with_metrics)]
1260-
let _latency = super::metrics::EXECUTE_BLOCK_LATENCY.measure_latency();
1262+
let _latency =
1263+
super::metrics::EXECUTE_BLOCK_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
12611264

12621265
let mutex = self.client_mutex();
12631266
let _guard = mutex.lock_owned().await;
@@ -2251,7 +2254,8 @@ impl<Env: Environment> ChainClient<Env> {
22512254
&self,
22522255
) -> Result<(Vec<ConfirmedBlockCertificate>, Option<RoundTimeout>), Error> {
22532256
#[cfg(with_metrics)]
2254-
let _latency = super::metrics::PROCESS_INBOX_WITHOUT_PREPARE_LATENCY.measure_latency();
2257+
let _latency = super::metrics::PROCESS_INBOX_WITHOUT_PREPARE_LATENCY
2258+
.measure_latency(MeasurementUnit::Milliseconds);
22552259

22562260
let mut certificates = Vec::new();
22572261
loop {

‎linera-core/src/client/mod.rs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ use futures::{
1414
stream::{self, AbortHandle, FuturesUnordered, StreamExt},
1515
};
1616
#[cfg(with_metrics)]
17-
use linera_base::prometheus_util::MeasureLatency as _;
17+
use linera_base::prometheus_util::{MeasureLatency as _, MeasurementUnit};
1818
use linera_base::{
1919
crypto::{CryptoHash, Signer, ValidatorPublicKey},
2020
data_types::{ArithmeticError, Blob, BlockHeight, ChainDescription, Epoch},
@@ -1210,7 +1210,8 @@ impl<Env: Environment> Client<Env> {
12101210
committee: Committee,
12111211
) -> Result<Box<ChainInfo>, chain_client::Error> {
12121212
#[cfg(with_metrics)]
1213-
let _latency = metrics::SYNCHRONIZE_CHAIN_STATE_LATENCY.measure_latency();
1213+
let _latency =
1214+
metrics::SYNCHRONIZE_CHAIN_STATE_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
12141215

12151216
let validators = self.make_nodes(&committee)?;
12161217
Box::pin(self.fetch_chain_info(chain_id, &validators)).await?;

‎linera-execution/src/evm/revm.rs‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@ use std::{
1111
};
1212

1313
#[cfg(with_metrics)]
14-
use linera_base::prometheus_util::MeasureLatency as _;
14+
use linera_base::prometheus_util::{MeasureLatency as _, MeasurementUnit};
1515
use linera_base::{
1616
crypto::CryptoHash,
1717
data_types::{
@@ -137,7 +137,8 @@ impl UserContractModule for EvmContractModule {
137137
runtime: ContractSyncRuntimeHandle,
138138
) -> Result<UserContractInstance, ExecutionError> {
139139
#[cfg(with_metrics)]
140-
let _instantiation_latency = metrics::CONTRACT_INSTANTIATION_LATENCY.measure_latency();
140+
let _instantiation_latency =
141+
metrics::CONTRACT_INSTANTIATION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
141142

142143
let instance: UserContractInstance = match self {
143144
#[cfg(with_revm)]
@@ -193,7 +194,8 @@ impl UserServiceModule for EvmServiceModule {
193194
runtime: ServiceSyncRuntimeHandle,
194195
) -> Result<UserServiceInstance, ExecutionError> {
195196
#[cfg(with_metrics)]
196-
let _instantiation_latency = metrics::SERVICE_INSTANTIATION_LATENCY.measure_latency();
197+
let _instantiation_latency =
198+
metrics::SERVICE_INSTANTIATION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
197199

198200
let instance: UserServiceInstance = match self {
199201
#[cfg(with_revm)]

‎linera-execution/src/execution_state_actor.rs‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@ use std::collections::{BTreeMap, BTreeSet};
88
use custom_debug_derive::Debug;
99
use futures::{channel::mpsc, StreamExt as _};
1010
#[cfg(with_metrics)]
11-
use linera_base::prometheus_util::MeasureLatency as _;
11+
use linera_base::prometheus_util::{MeasureLatency as _, MeasurementUnit};
1212
use linera_base::{
1313
data_types::{
1414
Amount, ApplicationPermissions, ArithmeticError, BlobContent, BlockHeight, OracleResponse,
@@ -95,7 +95,8 @@ where
9595
id: ApplicationId,
9696
) -> Result<(UserContractCode, ApplicationDescription), ExecutionError> {
9797
#[cfg(with_metrics)]
98-
let _latency = metrics::LOAD_CONTRACT_LATENCY.measure_latency();
98+
let _latency =
99+
metrics::LOAD_CONTRACT_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
99100
let blob_id = id.description_blob_id();
100101
let description = match self.txn_tracker.get_blob_content(&blob_id) {
101102
Some(blob) => bcs::from_bytes(blob.bytes())?,
@@ -120,7 +121,7 @@ where
120121
id: ApplicationId,
121122
) -> Result<(UserServiceCode, ApplicationDescription), ExecutionError> {
122123
#[cfg(with_metrics)]
123-
let _latency = metrics::LOAD_SERVICE_LATENCY.measure_latency();
124+
let _latency = metrics::LOAD_SERVICE_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
124125
let blob_id = id.description_blob_id();
125126
let description = match self.txn_tracker.get_blob_content(&blob_id) {
126127
Some(blob) => bcs::from_bytes(blob.bytes())?,

‎linera-execution/src/wasm/mod.rs‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ use std::path::Path;
2424

2525
use linera_base::data_types::Bytecode;
2626
#[cfg(with_metrics)]
27-
use linera_base::prometheus_util::MeasureLatency as _;
27+
use linera_base::prometheus_util::{MeasureLatency as _, MeasurementUnit};
2828
use thiserror::Error;
2929
use wasm_instrument::{gas_metering, parity_wasm};
3030
#[cfg(with_wasmer)]
@@ -116,7 +116,8 @@ impl UserContractModule for WasmContractModule {
116116
runtime: ContractSyncRuntimeHandle,
117117
) -> Result<UserContractInstance, ExecutionError> {
118118
#[cfg(with_metrics)]
119-
let _instantiation_latency = metrics::CONTRACT_INSTANTIATION_LATENCY.measure_latency();
119+
let _instantiation_latency =
120+
metrics::CONTRACT_INSTANTIATION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
120121

121122
let instance: UserContractInstance = match self {
122123
#[cfg(with_wasmtime)]
@@ -178,7 +179,8 @@ impl UserServiceModule for WasmServiceModule {
178179
runtime: ServiceSyncRuntimeHandle,
179180
) -> Result<UserServiceInstance, ExecutionError> {
180181
#[cfg(with_metrics)]
181-
let _instantiation_latency = metrics::SERVICE_INSTANTIATION_LATENCY.measure_latency();
182+
let _instantiation_latency =
183+
metrics::SERVICE_INSTANTIATION_LATENCY.measure_latency(MeasurementUnit::Milliseconds);
182184

183185
let instance: UserServiceInstance = match self {
184186
#[cfg(with_wasmtime)]

0 commit comments

Comments
 (0)