From ca22007f2f17eff17c0e71b513b3e6ed04dbb024 Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 14:06:27 +0200 Subject: [PATCH 1/8] add timer guard --- objectstore-metrics/src/lib.rs | 100 +++++++++++++++++++++++++++++++- objectstore-metrics/src/mock.rs | 53 +++++++++++++++++ 2 files changed, 151 insertions(+), 2 deletions(-) diff --git a/objectstore-metrics/src/lib.rs b/objectstore-metrics/src/lib.rs index 094b9751..56a78d62 100644 --- a/objectstore-metrics/src/lib.rs +++ b/objectstore-metrics/src/lib.rs @@ -2,7 +2,7 @@ //! //! This crate provides three things: //! -//! 1. [`count!`], [`gauge!`], and [`record!`] macros with rustfmt-friendly +//! 1. [`count!`], [`gauge!`], [`record!`], and [`timer!`] macros with rustfmt-friendly //! expression-based syntax. //! 2. [`MetricsConfig`] and [`init`] for wiring up a DogStatsD exporter. //! 3. [`with_capturing_test_client`] for asserting on emitted metrics in tests. @@ -11,7 +11,7 @@ //! //! ```rust //! use std::time::Duration; -//! use objectstore_metrics::{count, gauge, record}; +//! use objectstore_metrics::{count, gauge, record, timer}; //! //! let stored_size: u64 = 1024; //! let elapsed = Duration::from_secs(1); @@ -82,6 +82,66 @@ impl AsF64 for std::time::Duration { } } +/// A guard that measures elapsed time and records it as a distribution metric. +/// +/// Created by the [`timer!`] macro. Records with `success:true` when +/// [`record()`](TimerGuard::record) is called, or `success:false` when dropped +/// without calling `record()`. +/// Call [`success()`](TimerGuard::success) to override this behavior and record +/// with `success:true` even on drop. +#[must_use = "timer! returns a guard that records the metric on guard.record() or on drop, bind it to a variable"] +pub struct TimerGuard { + start: std::time::Instant, + success_histogram: metrics::Histogram, + failure_histogram: metrics::Histogram, + record_failure_on_drop: bool, + recorded: bool, +} + +impl TimerGuard { + #[doc(hidden)] + pub fn new( + success_histogram: metrics::Histogram, + failure_histogram: metrics::Histogram, + ) -> Self { + Self { + start: std::time::Instant::now(), + success_histogram, + failure_histogram, + record_failure_on_drop: true, + recorded: false, + } + } + + /// Changes the behavior of this guard to always record the metric + /// with `success:true`, even on drop. + pub fn success(mut self) -> Self { + self.record_failure_on_drop = false; + self + } + + /// Consumes the guard, and records the elapsed time with `success:true`. + pub fn record(mut self) { + self.recorded = true; + self.success_histogram + .record(AsF64::as_f64(self.start.elapsed())); + } +} + +impl Drop for TimerGuard { + fn drop(&mut self) { + if !self.recorded { + if self.record_failure_on_drop { + self.failure_histogram + .record(AsF64::as_f64(self.start.elapsed())); + } else { + self.success_histogram + .record(AsF64::as_f64(self.start.elapsed())); + } + } + } +} + /// Re-exports used by macro expansion. Not part of the public API. #[doc(hidden)] pub mod _macro_support { @@ -343,3 +403,39 @@ macro_rules! record { .record($crate::_macro_support::AsF64::as_f64($value)); }; } + +/// Starts a timer that records elapsed time in fractional seconds as a +/// distribution metric. +/// +/// Returns a [`TimerGuard`] that captures `Instant::now()` at creation. +/// Call [`.record()`](TimerGuard::record) to record the metric with the +/// tag `success:true`, or let it drop to record with `success:false`. +/// +/// If you want to override this behavior and record the metric with +/// `success:true` even on drop, call [`.success()`](TimerGuard::success) +/// on the guard. +/// +/// # Syntax +/// +/// ```rust +/// use objectstore_metrics::timer; +/// +/// let guard = timer!("server.requests.duration"); +/// let guard = timer!("server.requests.duration", route = "/v1/test"); +/// // ... do work ... +/// guard.record(); // records elapsed time with success:true +/// ``` +/// +/// Tag keys are identifiers; tag values must implement `Into`. +#[macro_export] +macro_rules! timer { + ($name:literal $(, $tag:ident = $tv:expr)* $(,)?) => {{ + let success_histogram = $crate::_macro_support::metrics::histogram!( + $name $(, stringify!($tag) => $tv)*, "success" => "true" + ); + let failure_histogram = $crate::_macro_support::metrics::histogram!( + $name $(, stringify!($tag) => $tv)*, "success" => "false" + ); + $crate::TimerGuard::new(success_histogram, failure_histogram) + }}; +} diff --git a/objectstore-metrics/src/mock.rs b/objectstore-metrics/src/mock.rs index 43061861..1c7631d1 100644 --- a/objectstore-metrics/src/mock.rs +++ b/objectstore-metrics/src/mock.rs @@ -208,4 +208,57 @@ mod tests { assert_eq!(captured.len(), 1); assert_eq!(captured[0], "test.latency:2|d|#route:/v1/test,method:GET"); } + + #[test] + fn timer_record_emits_success_true() { + let captured = with_capturing_test_client(|| { + let guard = crate::timer!("test.timer"); + guard.record(); + }); + assert_eq!(captured.len(), 1); + assert!(captured[0].starts_with("test.timer:")); + assert!(captured[0].contains("|d|#success:true")); + } + + #[test] + fn timer_drop_emits_success_false() { + let captured = with_capturing_test_client(|| { + let _guard = crate::timer!("test.timer"); + }); + assert_eq!(captured.len(), 1); + assert!(captured[0].starts_with("test.timer:")); + assert!(captured[0].contains("|d|#success:false")); + } + + #[test] + fn timer_drop_with_success_emits_success_true() { + let captured = with_capturing_test_client(|| { + let _guard = crate::timer!("test.timer").success(); + }); + assert_eq!(captured.len(), 1); + assert!(captured[0].starts_with("test.timer:")); + assert!(captured[0].contains("|d|#success:true")); + } + + #[test] + fn timer_with_tags() { + let captured = with_capturing_test_client(|| { + let guard = crate::timer!("test.timer", route = "/v1/test"); + guard.record(); + }); + assert_eq!(captured.len(), 1); + assert!(captured[0].starts_with("test.timer:")); + assert!(captured[0].contains("route:/v1/test")); + assert!(captured[0].contains("success:true")); + } + + #[test] + fn timer_drop_with_tags() { + let captured = with_capturing_test_client(|| { + let _guard = crate::timer!("test.timer", op = "put"); + }); + assert_eq!(captured.len(), 1); + assert!(captured[0].contains("op:put")); + assert!(captured[0].contains("success:false")); + } } From f028523161892137aa9e4d6c03c7f1edc7e06c4d Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 14:43:22 +0200 Subject: [PATCH 2/8] improve --- objectstore-metrics/src/lib.rs | 86 ++++++++++---- objectstore-metrics/src/mock.rs | 79 +++++++++++++ objectstore-service/src/backend/tiered.rs | 132 +++++++++++----------- 3 files changed, 205 insertions(+), 92 deletions(-) diff --git a/objectstore-metrics/src/lib.rs b/objectstore-metrics/src/lib.rs index 56a78d62..ff44c7cd 100644 --- a/objectstore-metrics/src/lib.rs +++ b/objectstore-metrics/src/lib.rs @@ -89,30 +89,42 @@ impl AsF64 for std::time::Duration { /// without calling `record()`. /// Call [`success()`](TimerGuard::success) to override this behavior and record /// with `success:true` even on drop. +/// +/// Tags can be added after creation via [`tag()`](TimerGuard::tag). #[must_use = "timer! returns a guard that records the metric on guard.record() or on drop, bind it to a variable"] pub struct TimerGuard { start: std::time::Instant, - success_histogram: metrics::Histogram, - failure_histogram: metrics::Histogram, + name: &'static str, + module_path: &'static str, + labels: Vec, record_failure_on_drop: bool, recorded: bool, } impl TimerGuard { #[doc(hidden)] - pub fn new( - success_histogram: metrics::Histogram, - failure_histogram: metrics::Histogram, - ) -> Self { + pub fn new(name: &'static str, module_path: &'static str, labels: Vec) -> Self { Self { start: std::time::Instant::now(), - success_histogram, - failure_histogram, + name, + module_path, + labels, record_failure_on_drop: true, recorded: false, } } + /// Returns the time elapsed since the guard was created. + pub fn elapsed(&self) -> std::time::Duration { + self.start.elapsed() + } + + /// Adds a tag to the metric. + pub fn tag(mut self, key: &'static str, value: impl Into) -> Self { + self.labels.push(metrics::Label::new(key, value)); + self + } + /// Changes the behavior of this guard to always record the metric /// with `success:true`, even on drop. pub fn success(mut self) -> Self { @@ -120,24 +132,40 @@ impl TimerGuard { self } - /// Consumes the guard, and records the elapsed time with `success:true`. + /// Consumes the guard, recording the elapsed time with `success:true`. pub fn record(mut self) { self.recorded = true; - self.success_histogram - .record(AsF64::as_f64(self.start.elapsed())); + let mut labels = std::mem::take(&mut self.labels); + labels.push(metrics::Label::new("success", "true")); + Self::emit(self.name, self.module_path, labels, self.start); + } + + fn emit( + name: &'static str, + module_path: &'static str, + labels: Vec, + start: std::time::Instant, + ) { + let key = metrics::Key::from_parts(name, labels); + let metadata = metrics::Metadata::new(module_path, metrics::Level::INFO, Some(module_path)); + metrics::with_recorder(|rec| { + rec.register_histogram(&key, &metadata) + .record(AsF64::as_f64(start.elapsed())); + }); } } impl Drop for TimerGuard { fn drop(&mut self) { if !self.recorded { - if self.record_failure_on_drop { - self.failure_histogram - .record(AsF64::as_f64(self.start.elapsed())); + let success = if self.record_failure_on_drop { + "false" } else { - self.success_histogram - .record(AsF64::as_f64(self.start.elapsed())); - } + "true" + }; + let mut labels = std::mem::take(&mut self.labels); + labels.push(metrics::Label::new("success", success)); + Self::emit(self.name, self.module_path, labels, self.start); } } } @@ -415,6 +443,10 @@ macro_rules! record { /// `success:true` even on drop, call [`.success()`](TimerGuard::success) /// on the guard. /// +/// Tags can also be added after creation via [`.tag()`](TimerGuard::tag), +/// which is useful when some tag values depend on the outcome of the +/// timed operation. +/// /// # Syntax /// /// ```rust @@ -426,16 +458,22 @@ macro_rules! record { /// guard.record(); // records elapsed time with success:true /// ``` /// +/// ```rust +/// use objectstore_metrics::timer; +/// +/// let guard = timer!("server.requests.duration", route = "/v1/test"); +/// // ... determine backend ... +/// let guard = guard.tag("backend", "gcs"); +/// guard.record(); +/// ``` +/// /// Tag keys are identifiers; tag values must implement `Into`. #[macro_export] macro_rules! timer { ($name:literal $(, $tag:ident = $tv:expr)* $(,)?) => {{ - let success_histogram = $crate::_macro_support::metrics::histogram!( - $name $(, stringify!($tag) => $tv)*, "success" => "true" - ); - let failure_histogram = $crate::_macro_support::metrics::histogram!( - $name $(, stringify!($tag) => $tv)*, "success" => "false" - ); - $crate::TimerGuard::new(success_histogram, failure_histogram) + let labels = vec![ + $($crate::_macro_support::metrics::Label::new(stringify!($tag), $tv),)* + ]; + $crate::TimerGuard::new($name, module_path!(), labels) }}; } diff --git a/objectstore-metrics/src/mock.rs b/objectstore-metrics/src/mock.rs index 1c7631d1..653a6aee 100644 --- a/objectstore-metrics/src/mock.rs +++ b/objectstore-metrics/src/mock.rs @@ -261,4 +261,83 @@ mod tests { assert!(captured[0].contains("op:put")); assert!(captured[0].contains("success:false")); } + + #[test] + fn timer_deferred_tag_on_record() { + let captured = with_capturing_test_client(|| { + let guard = crate::timer!("test.timer", usecase = "test"); + guard.tag("backend", "gcs").record(); + }); + assert_eq!(captured.len(), 1); + assert!(captured[0].contains("usecase:test")); + assert!(captured[0].contains("backend:gcs")); + assert!(captured[0].contains("success:true")); + } + + #[test] + fn timer_deferred_tag_on_drop() { + let captured = with_capturing_test_client(|| { + let _guard = crate::timer!("test.timer", usecase = "test").tag("backend", "gcs"); + }); + assert_eq!(captured.len(), 1); + assert!(captured[0].contains("usecase:test")); + assert!(captured[0].contains("backend:gcs")); + assert!(captured[0].contains("success:false")); + } + + #[test] + fn timer_metadata_matches_record_macro() { + use std::sync::Mutex; + + type Entries = Vec<(String, Option)>; + + struct MetadataRecorder(Arc>); + + impl Recorder for MetadataRecorder { + fn describe_counter(&self, _: KeyName, _: Option, _: SharedString) {} + fn describe_gauge(&self, _: KeyName, _: Option, _: SharedString) {} + fn describe_histogram(&self, _: KeyName, _: Option, _: SharedString) {} + fn register_counter(&self, _: &Key, _: &Metadata<'_>) -> Counter { + Counter::noop() + } + fn register_gauge(&self, _: &Key, _: &Metadata<'_>) -> Gauge { + Gauge::noop() + } + fn register_histogram(&self, _: &Key, metadata: &Metadata<'_>) -> Histogram { + self.0.lock().unwrap().push(( + metadata.target().to_owned(), + metadata.module_path().map(str::to_owned), + )); + Histogram::noop() + } + } + + let captured = Arc::new(Mutex::new(Vec::new())); + let recorder = MetadataRecorder(Arc::clone(&captured)); + + metrics::with_local_recorder(&recorder, || { + // record! expands metrics::histogram! which sets module_path!() at the call site + crate::record!("from_record" = 1.0f64); + // timer! captures module_path!() in the macro and passes it to TimerGuard + crate::timer!("from_timer").record(); + }); + + let entries = captured.lock().unwrap(); + assert_eq!( + entries.len(), + 2, + "expected one entry from record! and one from timer!" + ); + + let (record_target, record_module) = &entries[0]; + let (timer_target, timer_module) = &entries[1]; + assert_eq!( + record_target, timer_target, + "timer! target should match record! target" + ); + assert_eq!( + record_module, timer_module, + "timer! module_path should match record! module_path" + ); + } } diff --git a/objectstore-service/src/backend/tiered.rs b/objectstore-service/src/backend/tiered.rs index a78f22a6..542f3de0 100644 --- a/objectstore-service/src/backend/tiered.rs +++ b/objectstore-service/src/backend/tiered.rs @@ -99,7 +99,7 @@ use std::sync::Arc; use std::sync::atomic::{AtomicU64, Ordering}; -use std::time::{Duration, Instant, SystemTime}; +use std::time::{Duration, SystemTime}; use base64::Engine as _; use bytes::Bytes; @@ -375,14 +375,14 @@ impl Backend for TieredStorage { metadata: &Metadata, stream: ClientStream, ) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!("put.latency", usecase = id.usecase().to_owned(),); if metadata.origin.is_none() { objectstore_metrics::count!("put.origin_missing", usecase = id.usecase().to_owned()); } let peeked = SizedPeek::new(stream, BACKEND_SIZE_THRESHOLD).await?; objectstore_metrics::record!( - "put.first_chunk.latency" = start.elapsed(), + "put.first_chunk.latency" = timer.elapsed(), usecase = id.usecase().to_owned(), complete = if peeked.is_exhausted() { "yes" } else { "no" }, ); @@ -399,12 +399,10 @@ impl Backend for TieredStorage { }; let backend_ty = self.backend_type(&backend_choice); - objectstore_metrics::record!( - "put.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - backend_choice = backend_choice.as_str(), - backend_type = backend_ty, - ); + timer + .tag("backend_choice", backend_choice.as_str()) + .tag("backend_type", backend_ty) + .record(); objectstore_metrics::record!( "put.size" = stored_size, usecase = id.usecase().to_owned(), @@ -417,7 +415,10 @@ impl Backend for TieredStorage { } async fn get_object(&self, id: &ObjectId) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!( + "get.latency.pre-response", + usecase = id.usecase().to_owned(), + ); let hv_result = self.inner.high_volume.get_tiered_object(id).await?; let (result, backend_choice) = match hv_result { @@ -432,12 +433,10 @@ impl Backend for TieredStorage { }; let backend_type = self.backend_type(&backend_choice); - objectstore_metrics::record!( - "get.latency.pre-response" = start.elapsed(), - usecase = id.usecase().to_owned(), - backend_choice = backend_choice.as_str(), - backend_type = backend_type, - ); + timer + .tag("backend_choice", backend_choice.as_str()) + .tag("backend_type", backend_type) + .record(); if let Some((ref metadata, _)) = result { if let Some(size) = metadata.size { @@ -456,7 +455,7 @@ impl Backend for TieredStorage { } async fn get_metadata(&self, id: &ObjectId) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!("head.latency", usecase = id.usecase().to_owned(),); let hv_result = self.inner.high_volume.get_tiered_metadata(id).await?; let (result, backend_choice) = match hv_result { @@ -468,18 +467,17 @@ impl Backend for TieredStorage { ), }; - objectstore_metrics::record!( - "head.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - backend_choice = backend_choice.as_str(), - backend_type = self.backend_type(&backend_choice), - ); + timer + .tag("backend_choice", backend_choice.as_str()) + .tag("backend_type", self.backend_type(&backend_choice)) + .record(); Ok(result) } async fn delete_object(&self, id: &ObjectId) -> Result { - let start = Instant::now(); + let timer = + objectstore_metrics::timer!("delete.latency", usecase = id.usecase().to_owned(),); let mut backend_choice = BackendChoice::HighVolume; @@ -507,12 +505,10 @@ impl Backend for TieredStorage { guard.advance(ChangePhase::compare_and_write(deleted)); } - objectstore_metrics::record!( - "delete.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - backend_choice = backend_choice.as_str(), - backend_type = self.backend_type(&backend_choice), - ); + timer + .tag("backend_choice", backend_choice.as_str()) + .tag("backend_type", self.backend_type(&backend_choice)) + .record(); Ok(()) } @@ -605,7 +601,10 @@ impl MultipartUploadBackend for TieredStorage { id: &ObjectId, metadata: &Metadata, ) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!( + "multipart.initiate.latency", + usecase = id.usecase().to_owned(), + ); let physical = new_long_term_revision(id); let upload_id = self @@ -614,10 +613,7 @@ impl MultipartUploadBackend for TieredStorage { .initiate_multipart(&physical, metadata) .await?; - objectstore_metrics::record!( - "multipart.initiate.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - ); + timer.record(); let id = TieredUploadId { revision: physical.key, @@ -635,7 +631,10 @@ impl MultipartUploadBackend for TieredStorage { content_md5: Option<&str>, body: ClientStream, ) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!( + "multipart.upload_part.latency", + usecase = id.usecase().to_owned(), + ); let tiered: TieredUploadId = upload_id.try_into()?; let physical = ObjectId { @@ -643,7 +642,7 @@ impl MultipartUploadBackend for TieredStorage { key: tiered.revision, }; - let result = self + let etag = self .inner .long_term .upload_part( @@ -654,18 +653,15 @@ impl MultipartUploadBackend for TieredStorage { content_md5, body, ) - .await; + .await?; - objectstore_metrics::record!( - "multipart.upload_part.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - ); + timer.record(); objectstore_metrics::record!( "multipart.upload_part.size" = content_length, usecase = id.usecase().to_owned(), ); - result + Ok(etag) } async fn list_parts( @@ -675,7 +671,10 @@ impl MultipartUploadBackend for TieredStorage { max_parts: Option, part_number_marker: Option, ) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!( + "multipart.list_parts.latency", + usecase = id.usecase().to_owned(), + ); let tiered: TieredUploadId = upload_id.try_into()?; let physical = ObjectId { @@ -683,18 +682,14 @@ impl MultipartUploadBackend for TieredStorage { key: tiered.revision, }; - let result = self + let response = self .inner .long_term .list_parts(&physical, &tiered.upload_id, max_parts, part_number_marker) - .await; - - objectstore_metrics::record!( - "multipart.list_parts.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - ); + .await?; - result + timer.record(); + Ok(response) } async fn abort_multipart( @@ -702,7 +697,10 @@ impl MultipartUploadBackend for TieredStorage { id: &ObjectId, upload_id: &UploadId, ) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!( + "multipart.abort.latency", + usecase = id.usecase().to_owned(), + ); let tiered: TieredUploadId = upload_id.try_into()?; let physical = ObjectId { @@ -710,18 +708,13 @@ impl MultipartUploadBackend for TieredStorage { key: tiered.revision, }; - let result = self - .inner + self.inner .long_term .abort_multipart(&physical, &tiered.upload_id) - .await; - - objectstore_metrics::record!( - "multipart.abort.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - ); + .await?; - result + timer.record(); + Ok(()) } async fn complete_multipart( @@ -730,7 +723,10 @@ impl MultipartUploadBackend for TieredStorage { upload_id: &UploadId, parts: Vec, ) -> Result { - let start = Instant::now(); + let timer = objectstore_metrics::timer!( + "multipart.complete.latency", + usecase = id.usecase().to_owned(), + ); let part_count = parts.len(); let tiered: TieredUploadId = upload_id.try_into()?; @@ -742,7 +738,10 @@ impl MultipartUploadBackend for TieredStorage { // 1. Read current HV revision to establish the write precondition. let current = match self.inner.high_volume.get_tiered_metadata(id).await? { // Optimization: a previous attempt already finalized this revision and tombstone -- report success. - TieredMetadata::Tombstone(t) if t.target == physical => return Ok(None), + TieredMetadata::Tombstone(t) if t.target == physical => { + timer.record(); + return Ok(None); + } TieredMetadata::Tombstone(t) => Some(t.target), _ => None, }; @@ -830,10 +829,7 @@ impl MultipartUploadBackend for TieredStorage { // Update guard and let it schedule cleanup in the background. guard.advance(ChangePhase::compare_and_write(written)); - objectstore_metrics::record!( - "multipart.complete.latency" = start.elapsed(), - usecase = id.usecase().to_owned(), - ); + timer.record(); objectstore_metrics::record!( "multipart.complete.part_count" = part_count as u64, usecase = id.usecase().to_owned(), From 386b1a75fa87fa1151328f55c789591104974feb Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 14:49:06 +0200 Subject: [PATCH 3/8] improve --- objectstore-metrics/src/lib.rs | 26 ++++++++++---------------- 1 file changed, 10 insertions(+), 16 deletions(-) diff --git a/objectstore-metrics/src/lib.rs b/objectstore-metrics/src/lib.rs index ff44c7cd..083c45d4 100644 --- a/objectstore-metrics/src/lib.rs +++ b/objectstore-metrics/src/lib.rs @@ -134,23 +134,19 @@ impl TimerGuard { /// Consumes the guard, recording the elapsed time with `success:true`. pub fn record(mut self) { - self.recorded = true; - let mut labels = std::mem::take(&mut self.labels); - labels.push(metrics::Label::new("success", "true")); - Self::emit(self.name, self.module_path, labels, self.start); + self.emit("true"); } - fn emit( - name: &'static str, - module_path: &'static str, - labels: Vec, - start: std::time::Instant, - ) { - let key = metrics::Key::from_parts(name, labels); - let metadata = metrics::Metadata::new(module_path, metrics::Level::INFO, Some(module_path)); + fn emit(&mut self, success: &'static str) { + self.recorded = true; + let mut labels = std::mem::take(&mut self.labels); + labels.push(metrics::Label::new("success", success)); + let key = metrics::Key::from_parts(self.name, labels); + let metadata = + metrics::Metadata::new(self.module_path, metrics::Level::INFO, Some(self.module_path)); metrics::with_recorder(|rec| { rec.register_histogram(&key, &metadata) - .record(AsF64::as_f64(start.elapsed())); + .record(AsF64::as_f64(self.start.elapsed())); }); } } @@ -163,9 +159,7 @@ impl Drop for TimerGuard { } else { "true" }; - let mut labels = std::mem::take(&mut self.labels); - labels.push(metrics::Label::new("success", success)); - Self::emit(self.name, self.module_path, labels, self.start); + self.emit(success); } } } From c391bbae96c454cb2b4e7fbbedf896360ee379cc Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 14:58:52 +0200 Subject: [PATCH 4/8] clippy --- objectstore-metrics/src/lib.rs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/objectstore-metrics/src/lib.rs b/objectstore-metrics/src/lib.rs index 083c45d4..6f950906 100644 --- a/objectstore-metrics/src/lib.rs +++ b/objectstore-metrics/src/lib.rs @@ -142,8 +142,11 @@ impl TimerGuard { let mut labels = std::mem::take(&mut self.labels); labels.push(metrics::Label::new("success", success)); let key = metrics::Key::from_parts(self.name, labels); - let metadata = - metrics::Metadata::new(self.module_path, metrics::Level::INFO, Some(self.module_path)); + let metadata = metrics::Metadata::new( + self.module_path, + metrics::Level::INFO, + Some(self.module_path), + ); metrics::with_recorder(|rec| { rec.register_histogram(&key, &metadata) .record(AsF64::as_f64(self.start.elapsed())); From b0c64b578509705ca87ca9e7935193b2f16d038b Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 15:04:13 +0200 Subject: [PATCH 5/8] simplify --- objectstore-metrics/src/mock.rs | 56 --------------------------------- 1 file changed, 56 deletions(-) diff --git a/objectstore-metrics/src/mock.rs b/objectstore-metrics/src/mock.rs index 653a6aee..62b61d91 100644 --- a/objectstore-metrics/src/mock.rs +++ b/objectstore-metrics/src/mock.rs @@ -284,60 +284,4 @@ mod tests { assert!(captured[0].contains("backend:gcs")); assert!(captured[0].contains("success:false")); } - - #[test] - fn timer_metadata_matches_record_macro() { - use std::sync::Mutex; - - type Entries = Vec<(String, Option)>; - - struct MetadataRecorder(Arc>); - - impl Recorder for MetadataRecorder { - fn describe_counter(&self, _: KeyName, _: Option, _: SharedString) {} - fn describe_gauge(&self, _: KeyName, _: Option, _: SharedString) {} - fn describe_histogram(&self, _: KeyName, _: Option, _: SharedString) {} - fn register_counter(&self, _: &Key, _: &Metadata<'_>) -> Counter { - Counter::noop() - } - fn register_gauge(&self, _: &Key, _: &Metadata<'_>) -> Gauge { - Gauge::noop() - } - fn register_histogram(&self, _: &Key, metadata: &Metadata<'_>) -> Histogram { - self.0.lock().unwrap().push(( - metadata.target().to_owned(), - metadata.module_path().map(str::to_owned), - )); - Histogram::noop() - } - } - - let captured = Arc::new(Mutex::new(Vec::new())); - let recorder = MetadataRecorder(Arc::clone(&captured)); - - metrics::with_local_recorder(&recorder, || { - // record! expands metrics::histogram! which sets module_path!() at the call site - crate::record!("from_record" = 1.0f64); - // timer! captures module_path!() in the macro and passes it to TimerGuard - crate::timer!("from_timer").record(); - }); - - let entries = captured.lock().unwrap(); - assert_eq!( - entries.len(), - 2, - "expected one entry from record! and one from timer!" - ); - - let (record_target, record_module) = &entries[0]; - let (timer_target, timer_module) = &entries[1]; - assert_eq!( - record_target, timer_target, - "timer! target should match record! target" - ); - assert_eq!( - record_module, timer_module, - "timer! module_path should match record! module_path" - ); - } } From 89d3aa3cf827c00bc2ec297825ea2aea066825f7 Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 15:23:50 +0200 Subject: [PATCH 6/8] cleanup --- objectstore-service/src/backend/tiered.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/objectstore-service/src/backend/tiered.rs b/objectstore-service/src/backend/tiered.rs index 542f3de0..4684047d 100644 --- a/objectstore-service/src/backend/tiered.rs +++ b/objectstore-service/src/backend/tiered.rs @@ -375,7 +375,7 @@ impl Backend for TieredStorage { metadata: &Metadata, stream: ClientStream, ) -> Result { - let timer = objectstore_metrics::timer!("put.latency", usecase = id.usecase().to_owned(),); + let timer = objectstore_metrics::timer!("put.latency", usecase = id.usecase().to_owned()); if metadata.origin.is_none() { objectstore_metrics::count!("put.origin_missing", usecase = id.usecase().to_owned()); } @@ -455,7 +455,7 @@ impl Backend for TieredStorage { } async fn get_metadata(&self, id: &ObjectId) -> Result { - let timer = objectstore_metrics::timer!("head.latency", usecase = id.usecase().to_owned(),); + let timer = objectstore_metrics::timer!("head.latency", usecase = id.usecase().to_owned()); let hv_result = self.inner.high_volume.get_tiered_metadata(id).await?; let (result, backend_choice) = match hv_result { @@ -477,7 +477,7 @@ impl Backend for TieredStorage { async fn delete_object(&self, id: &ObjectId) -> Result { let timer = - objectstore_metrics::timer!("delete.latency", usecase = id.usecase().to_owned(),); + objectstore_metrics::timer!("delete.latency", usecase = id.usecase().to_owned()); let mut backend_choice = BackendChoice::HighVolume; From 1c6c375992272797726394a60ca39ed3804d032a Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 15:28:59 +0200 Subject: [PATCH 7/8] improve --- objectstore-service/src/backend/tiered.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/objectstore-service/src/backend/tiered.rs b/objectstore-service/src/backend/tiered.rs index 4684047d..8ed95674 100644 --- a/objectstore-service/src/backend/tiered.rs +++ b/objectstore-service/src/backend/tiered.rs @@ -708,7 +708,8 @@ impl MultipartUploadBackend for TieredStorage { key: tiered.revision, }; - self.inner + let () = self + .inner .long_term .abort_multipart(&physical, &tiered.upload_id) .await?; From a86a6e2021576a81a485ad0bb95b8117d93641b0 Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 5 Jun 2026 15:39:20 +0200 Subject: [PATCH 8/8] fix --- objectstore-service/src/backend/tiered.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/objectstore-service/src/backend/tiered.rs b/objectstore-service/src/backend/tiered.rs index 8ed95674..121e0a4f 100644 --- a/objectstore-service/src/backend/tiered.rs +++ b/objectstore-service/src/backend/tiered.rs @@ -613,13 +613,14 @@ impl MultipartUploadBackend for TieredStorage { .initiate_multipart(&physical, metadata) .await?; - timer.record(); - let id = TieredUploadId { revision: physical.key, upload_id, }; - id.try_into() + let id = id.try_into()?; + + timer.record(); + Ok(id) } async fn upload_part(