Track HTTP request latencies in nanoseconds (#6470)

- Change the `http_service:request_latency_histogram` to express
latencies in nanoseconds, as a histogram of u64s.
- Update the latency tracking types in `oximeter_instruments::http` to
use new bin type, and clean up some of the documentation.
- Expunged old timeseries schema
- Closes #6443

gateway/src/context.rs

@@ -39,16 +39,18 @@ impl ServerContext {
             OnceLock::new()
         };
 
-        const START_LATENCY_DECADE: i16 = -6;
-        const END_LATENCY_DECADE: i16 = 3;
+        // Track from 1 microsecond == 1e3 nanoseconds
+        const LATENCY_START_POWER: u16 = 3;
+        // To 1000s == 1e9 * 1e3 == 1e12 nanoseconds
+        const LATENCY_END_POWER: u16 = 12;
         let latencies =
-            oximeter_instruments::http::LatencyTracker::with_latency_decades(
+            oximeter_instruments::http::LatencyTracker::with_log_linear_bins(
                 oximeter_instruments::http::HttpService {
                     name: "management-gateway-service".into(),
                     id,
                 },
-                START_LATENCY_DECADE,
-                END_LATENCY_DECADE,
+                LATENCY_START_POWER,
+                LATENCY_END_POWER,
             )
             .expect("start and end decades are hardcoded and should be valid");
 

nexus/src/context.rs

@@ -146,12 +146,14 @@ impl ServerContext {
                 name: name.to_string().into(),
                 id: config.deployment.id,
             };
-            const START_LATENCY_DECADE: i16 = -6;
-            const END_LATENCY_DECADE: i16 = 3;
-            LatencyTracker::with_latency_decades(
+            // Start at 1 microsecond == 1e3 nanoseconds.
+            const LATENCY_START_POWER: u16 = 3;
+            // End at 1000s == (1e9 * 1e3) == 1e12 nanoseconds.
+            const LATENCY_END_POWER: u16 = 12;
+            LatencyTracker::with_log_linear_bins(
                 target,
-                START_LATENCY_DECADE,
-                END_LATENCY_DECADE,
+                LATENCY_START_POWER,
+                LATENCY_END_POWER,
             )
             .unwrap()
         };

oximeter/db/schema/replicated/12/timeseries-to-delete.txt

@@ -0,0 +1 @@
+http_service:request_latency_histogram

oximeter/db/schema/single-node/12/timeseries-to-delete.txt

@@ -0,0 +1 @@
+http_service:request_latency_histogram

oximeter/db/src/model.rs

@@ -45,7 +45,7 @@ use uuid::Uuid;
 /// - [`crate::Client::initialize_db_with_version`]
 /// - [`crate::Client::ensure_schema`]
 /// - The `clickhouse-schema-updater` binary in this crate
-pub const OXIMETER_VERSION: u64 = 11;
+pub const OXIMETER_VERSION: u64 = 12;
 
 // Wrapper type to represent a boolean in the database.
 //

oximeter/instruments/src/http.rs

@@ -24,11 +24,11 @@ pub use http_service::RequestLatencyHistogram;
 impl RequestLatencyHistogram {
     /// Build a new `RequestLatencyHistogram` with a specified histogram.
     ///
-    /// Latencies are expressed in seconds.
+    /// Latencies are expressed in nanoseconds.
     pub fn new(
         operation_id: &str,
         status_code: StatusCode,
-        histogram: Histogram<f64>,
+        histogram: Histogram<u64>,
     ) -> Self {
         Self {
             operation_id: operation_id.to_string().into(),
@@ -37,24 +37,26 @@ impl RequestLatencyHistogram {
         }
     }
 
-    /// Build a `RequestLatencyHistogram` with a histogram whose bins span the given decades.
+    /// Build a histogram whose bins span the given powers of ten.
     ///
-    /// `start_decade` and `end_decade` specify the lower and upper limits of the histogram's
-    /// range, as a power of 10. For example, passing `-3` and `2` results in a histogram with bins
-    /// spanning `[10 ** -3, 10 ** 2)`. There are 10 bins in each decade. See the
-    /// [`Histogram::span_decades`] method for more details.
+    /// `start_power` and `end_power` specify the lower and upper limits of
+    /// the histogram's range, as powers of 10. For example, passing 2 and 4
+    /// results in a histogram with bins from `[10 ** 2, 10 ** 4)`. There are 10
+    /// bins in each power of 10.
     ///
-    /// Latencies are expressed as seconds.
-    pub fn with_latency_decades(
+    /// See the [`Histogram::span_decades`] method for more details.
+    ///
+    /// Latencies are expressed in nanoseconds.
+    pub fn with_log_linear_bins(
         operation_id: &str,
         status_code: StatusCode,
-        start_decade: i16,
-        end_decade: i16,
+        start_power: u16,
+        end_power: u16,
     ) -> Result<Self, MetricsError> {
         Ok(Self::new(
             operation_id,
             status_code,
-            Histogram::span_decades(start_decade, end_decade)?,
+            Histogram::span_decades(start_power, end_power)?,
         ))
     }
 
@@ -71,7 +73,7 @@ impl RequestLatencyHistogram {
 }
 
 /// The `LatencyTracker` is an [`oximeter::Producer`] that tracks the latencies of requests for an
-/// HTTP service, in seconds.
+/// HTTP service, in nanoseconds.
 ///
 /// Consumers should construct one `LatencyTracker` for each HTTP service they wish to instrument.
 /// As requests are received, the [`LatencyTracker::update`] method can be called with the
@@ -94,33 +96,34 @@ pub struct LatencyTracker {
     /// The histogram used to track each request.
     ///
     /// We store it here to clone as we see new requests.
-    histogram: Histogram<f64>,
+    histogram: Histogram<u64>,
 }
 
 impl LatencyTracker {
     /// Build a new tracker for the given `service`, using `histogram` to track latencies.
     ///
     /// Note that the same histogram is used for each tracked timeseries.
-    pub fn new(service: HttpService, histogram: Histogram<f64>) -> Self {
+    pub fn new(service: HttpService, histogram: Histogram<u64>) -> Self {
         Self {
             service,
             latencies: Arc::new(Mutex::new(HashMap::new())),
             histogram,
         }
     }
 
-    /// Build a new tracker for the given `service`, with a histogram that spans the given decades
-    /// (powers of 10). See [`RequestLatencyHistogram::with_latency_decades`] for details on the
+    /// Build a new tracker with log-linear bins.
+    ///
+    /// This creates a tracker for the `service`, using 10 bins per power of 10,
+    /// from `[10 ** start_power, 10 ** end_power)`.
+    ///
+    /// [`RequestLatencyHistogram::with_log_linear_bins`] for details on the
     /// arguments.
-    pub fn with_latency_decades(
+    pub fn with_log_linear_bins(
         service: HttpService,
-        start_decade: i16,
-        end_decade: i16,
+        start_power: u16,
+        end_power: u16,
     ) -> Result<Self, MetricsError> {
-        Ok(Self::new(
-            service,
-            Histogram::span_decades(start_decade, end_decade)?,
-        ))
+        Ok(Self::new(service, Histogram::span_decades(start_power, end_power)?))
     }
 
     /// Update (or create) a timeseries in response to a new request.
@@ -142,7 +145,7 @@ impl LatencyTracker {
                 self.histogram.clone(),
             )
         });
-        entry.datum.sample(latency.as_secs_f64()).map_err(MetricsError::from)
+        entry.datum.sample(latency.as_nanos() as _).map_err(MetricsError::from)
     }
 
     /// Instrument the given Dropshot endpoint handler function.
@@ -218,16 +221,16 @@ mod tests {
     fn test_latency_tracker() {
         let service =
             HttpService { name: "my-service".into(), id: ID.parse().unwrap() };
-        let hist = Histogram::new(&[0.0, 1.0]).unwrap();
+        let hist = Histogram::new(&[100, 1000]).unwrap();
         let tracker = LatencyTracker::new(service, hist);
         let status_code0 = StatusCode::OK;
         let status_code1 = StatusCode::NOT_FOUND;
         let operation_id = "some_operation_id";
         tracker
-            .update(operation_id, status_code0, Duration::from_secs_f64(0.5))
+            .update(operation_id, status_code0, Duration::from_nanos(200))
             .unwrap();
         tracker
-            .update(operation_id, status_code1, Duration::from_secs_f64(0.5))
+            .update(operation_id, status_code1, Duration::from_nanos(200))
             .unwrap();
         let key0 = RequestLatencyHistogram::key_for(operation_id, status_code0);
         let key1 = RequestLatencyHistogram::key_for(operation_id, status_code1);

oximeter/oximeter/schema/http-service.toml

@@ -11,8 +11,8 @@ versions = [
 [[metrics]]
 name = "request_latency_histogram"
 description = "Duration for the server to handle a request"
-units = "seconds"
-datum_type = "histogram_f64"
+units = "nanoseconds"
+datum_type = "histogram_u64"
 versions = [
     { added_in = 1, fields = [ "operation_id", "status_code" ] }
 ]

oximeter/types/src/histogram.rs

@@ -1191,6 +1191,47 @@ where
     }
 }
 
+pub trait Bits: Integer {
+    const BITS: u32;
+    fn next_power(self) -> Option<Self>;
+}
+
+macro_rules! impl_bits {
+    ($type_:ty) => {
+        impl Bits for $type_ {
+            const BITS: u32 = Self::BITS;
+
+            fn next_power(self) -> Option<Self> {
+                self.checked_mul(2)
+            }
+        }
+    };
+}
+
+impl_bits!(u8);
+impl_bits!(u16);
+impl_bits!(u32);
+impl_bits!(u64);
+
+impl<T> Histogram<T>
+where
+    T: Bits + HistogramSupport,
+{
+    /// Create a histogram with logarithmically spaced bins at each power of 2.
+    ///
+    /// This is only available for unsigned integer support types.
+    pub fn power_of_two() -> Self {
+        let mut bins = Vec::with_capacity(T::BITS as _);
+        let mut x = T::one();
+        bins.push(x);
+        while let Some(next) = x.next_power() {
+            bins.push(next);
+            x = next;
+        }
+        Self::new(&bins).expect("Bits is statically known")
+    }
+}
+
 // Helper to ensure all values are comparable, i.e., not NaN.
 fn ensure_finite<T>(value: T) -> Result<(), HistogramError>
 where
@@ -1797,4 +1838,19 @@ mod tests {
             "expected to overflow a u8, since support type is not wide enough",
         );
     }
+
+    #[test]
+    fn test_log_bins_u8() {
+        let (bins, _) = Histogram::<u8>::power_of_two().bins_and_counts();
+        assert_eq!(bins, [0, 1, 2, 4, 8, 16, 32, 64, 128],);
+    }
+
+    #[test]
+    fn test_log_bins_u64() {
+        let (bins, _) = Histogram::<u64>::power_of_two().bins_and_counts();
+        assert_eq!(bins[0], 0);
+        for (i, bin) in bins.iter().skip(1).enumerate() {
+            assert_eq!(*bin, 1u64 << i);
+        }
+    }
 }