diff --git a/gotham/Cargo.toml b/gotham/Cargo.toml index 29f3924c..bc2976cc 100644 --- a/gotham/Cargo.toml +++ b/gotham/Cargo.toml @@ -33,7 +33,6 @@ anyhow = "1.0" base64 = "0.13" bincode = { version = "1.0", optional = true } bytes = "1.0" -chrono = { version = "0.4", features = ["clock"], default-features = false } cookie = "0.15" futures-util = "0.3.14" httpdate = "1.0" @@ -50,6 +49,7 @@ rand_chacha = "0.3" regex = "1.0" serde = { version = "1.0", features = ["derive"] } thiserror = "1.0" +time = {version = "0.3.4", default-features = false, features = ["std", "formatting", "macros"]} tokio = { version = "1.11.0", features = ["net", "rt-multi-thread", "time", "fs", "io-util"] } tokio-rustls = { version = "0.23", optional = true } uuid = { version = "0.8", features = ["v4"] } diff --git a/gotham/src/helpers/timing.rs b/gotham/src/helpers/timing.rs index 4fb16156..ebd46577 100644 --- a/gotham/src/helpers/timing.rs +++ b/gotham/src/helpers/timing.rs @@ -1,6 +1,8 @@ //! Defines types for timing requests and emitting timing information. -use chrono::prelude::*; use std::fmt::{self, Display, Formatter}; +use std::time::{Duration, Instant}; + +use time::OffsetDateTime; /// Timer struct used to record execution times of requests. /// @@ -8,56 +10,76 @@ use std::fmt::{self, Display, Formatter}; /// suitable for use with requset logging middlewares. #[derive(Clone, Copy)] pub(crate) struct Timer { - start: DateTime, + // We use 2 start fields + // because we want formattable time to print start time + // but we cannot use it to calculate duration because it is not monotonic. + // + // It is possible that we spent a lot of time between initialization of fields, + // for example, if current thread unscheduled by OS but it should be very rare. + // On the other hand, adjusting system clock by NTP is much more possible. + start_monotonic: Instant, + start_formattable: OffsetDateTime, } impl Timer { /// Begins measuring from the current time. pub(crate) fn new() -> Timer { - Timer { start: Utc::now() } + Timer { + start_monotonic: Instant::now(), + start_formattable: OffsetDateTime::now_utc(), + } } /// Finishes measuring, and returns the elapsed time as a `Timing` value. pub(crate) fn elapsed(&self) -> Timing { - let duration = Utc::now() - .signed_duration_since(self.start) - .num_microseconds(); - - match duration { - Some(dur) => Timing::Microseconds(dur), - None => Timing::Invalid, - } + let duration = self.start_monotonic.elapsed(); + Timing(duration) } /// Retrieves the start time of this timer. - pub(crate) fn start_time(&self) -> &DateTime { - &self.start + pub(crate) fn start_time(&self) -> &OffsetDateTime { + &self.start_formattable } } /// Represents an elapsed time measured by `Timer`. #[derive(Clone, Copy)] -pub(crate) enum Timing { - /// A number of microseconds measured by `Timer`. - Microseconds(i64), - - /// An invalid state, where the amount of time elapsed was unable to be measured. - Invalid, -} +pub(crate) struct Timing(Duration); impl Display for Timing { fn fmt(&self, f: &mut Formatter) -> fmt::Result { - match *self { - Timing::Microseconds(i) => { - if i < 1000 { - write!(f, "{}µs", i) - } else if i < 1_000_000 { - write!(f, "{:.2}ms", (i as f32) / 1000.0) - } else { - write!(f, "{:.2}s", (i as f32) / 1_000_000.0) - } + let duration = self.0; + match duration.as_micros() { + i if i < 1000 => { + write!(f, "{}µs", i) + } + i if i < 1_000_000 => { + write!(f, "{:.2}ms", (i as f64) / 1000.0) + } + _ => { + write!(f, "{:.2}s", duration.as_secs_f32()) } - Timing::Invalid => f.write_str("invalid"), } } } + +#[cfg(test)] +mod tests { + use std::time::Duration; + + use super::Timing; + + #[test] + fn test_durations() { + let microsecond = Duration::from_micros(1); + + let t0 = Timing(microsecond * 555); + assert_eq!(t0.to_string(), "555µs"); + + let t1 = Timing(microsecond * 666_444); + assert_eq!(t1.to_string(), "666.44ms"); + + let t2 = Timing(microsecond * 777_444_333); + assert_eq!(t2.to_string(), "777.44s"); + } +} diff --git a/gotham/src/middleware/logger.rs b/gotham/src/middleware/logger.rs index 3a4b1bca..622ceb84 100644 --- a/gotham/src/middleware/logger.rs +++ b/gotham/src/middleware/logger.rs @@ -62,8 +62,16 @@ impl Middleware for RequestLogger { // hook onto the end of the request to log the access let f = chain(state).and_then(move |(state, response)| { + // format the start time to the CLF formats - let datetime = timer.start_time().format("%d/%b/%Y:%H:%M:%S %z"); + let datetime = { + use time::format_description::FormatItem; + use time::macros::format_description; + const DT_FORMAT: &[FormatItem<'static>] + = format_description!("[day]/[month repr:short]/[year]:[hour repr:24]:[minute]:[second] [offset_hour][offset_minute]"); + + timer.start_time().format(&DT_FORMAT).expect("Failed to format time") + }; // grab the ip address from the state let ip = client_addr(&state).unwrap().ip();