PatternFormatter lock the local time cacher only once

Author: SpriteOvO

spdlog/benches/spdlog-rs/pattern.rs

@@ -22,13 +22,13 @@ include!(concat!(
 ));
 use test_utils::*;
 
-struct BenchSink<F> {
+struct BenchSink<'a, F> {
     formatter: F,
     buffer: RefCell<StringBuf>,
-    ctx: RefCell<FormatterContext>,
+    ctx: RefCell<FormatterContext<'a>>,
 }
 
-impl<F: Formatter> BenchSink<F> {
+impl<F: Formatter> BenchSink<'_, F> {
     fn new(formatter: F) -> Self {
         Self {
             formatter,
@@ -40,9 +40,9 @@ impl<F: Formatter> BenchSink<F> {
 
 // I think we're just testing benchmarks here, and they should not be executed
 // in parallel, so the data race from `buffer` shouldn't be an problem?
-unsafe impl<F> Sync for BenchSink<F> {}
+unsafe impl<F> Sync for BenchSink<'_, F> {}
 
-impl<F: Formatter> Sink for BenchSink<F> {
+impl<F: Formatter> Sink for BenchSink<'_, F> {
     fn log(&self, record: &Record) -> spdlog::Result<()> {
         self.formatter.format(
             record,

spdlog/src/formatter/full_formatter.rs

@@ -5,7 +5,7 @@ use std::fmt::{self, Write};
 use cfg_if::cfg_if;
 
 use crate::{
-    formatter::{Formatter, FormatterContext, LOCAL_TIME_CACHER},
+    formatter::{fmt_with_time, Formatter, FormatterContext, TimeDate},
     Error, Record, StringBuf, __EOL,
 };
 
@@ -62,15 +62,14 @@ impl FullFormatter {
             }
         }
 
-        {
-            let mut local_time_cacher = LOCAL_TIME_CACHER.lock();
-            let mut time = local_time_cacher.get(record.time());
+        fmt_with_time(ctx, record, |mut time: TimeDate| {
             dest.write_str("[")?;
             dest.write_str(time.full_second_str())?;
             dest.write_str(".")?;
             write!(dest, "{:03}", time.millisecond())?;
             dest.write_str("] [")?;
-        }
+            Ok(())
+        })?;
 
         if let Some(logger_name) = record.logger_name() {
             dest.write_str(logger_name)?;

spdlog/src/formatter/local_time_cacher.rs

@@ -1,13 +1,24 @@
-use std::time::SystemTime;
+use std::{fmt, time::SystemTime};
 
 use chrono::prelude::*;
 use once_cell::sync::Lazy;
 
-use crate::sync::*;
+use crate::{formatter::FormatterContext, sync::*, Record};
 
-pub(crate) static LOCAL_TIME_CACHER: Lazy<SpinMutex<LocalTimeCacher>> =
+static LOCAL_TIME_CACHER: Lazy<SpinMutex<LocalTimeCacher>> =
     Lazy::new(|| SpinMutex::new(LocalTimeCacher::new()));
 
+pub(crate) fn fmt_with_time<R, F>(ctx: &mut FormatterContext, record: &Record, mut callback: F) -> R
+where
+    F: FnMut(TimeDate) -> R,
+{
+    if let Some(time_date) = ctx.locked_time_date.as_mut() {
+        callback(time_date.get())
+    } else {
+        callback(LOCAL_TIME_CACHER.lock().get(record.time()))
+    }
+}
+
 #[derive(Clone)]
 pub(crate) struct LocalTimeCacher {
     stored_key: CacheKey,
@@ -91,11 +102,11 @@ impl LocalTimeCacher {
             self.stored_key = cache_key;
         }
 
-        TimeDate::new(
-            self.cache_values.as_mut().unwrap(),
-            reduced_nanosecond,
+        TimeDate {
+            cached: self.cache_values.as_mut().unwrap(),
+            nanosecond: reduced_nanosecond,
             millisecond,
-        )
+        }
     }
 }
 
@@ -128,15 +139,6 @@ macro_rules! impl_cache_fields_str_getter {
 }
 
 impl<'a> TimeDate<'a> {
-    #[must_use]
-    fn new(cached: &'a mut CacheValues, nanosecond: u32, millisecond: u32) -> Self {
-        Self {
-            cached,
-            nanosecond,
-            millisecond,
-        }
-    }
-
     #[must_use]
     pub(crate) fn full_second_str(&mut self) -> &str {
         if self.cached.full_second_str.is_none() {
@@ -361,6 +363,52 @@ impl CacheValues {
     }
 }
 
+struct TimeDateLocked<'a> {
+    cached: SpinMutexGuard<'a, LocalTimeCacher>,
+    nanosecond: u32,
+    millisecond: u32,
+}
+
+pub(crate) struct TimeDateLazyLocked<'a> {
+    time: SystemTime,
+    locked: Option<TimeDateLocked<'a>>,
+}
+
+impl<'a> TimeDateLazyLocked<'a> {
+    #[must_use]
+    pub(crate) fn new(time: SystemTime) -> Self {
+        Self { time, locked: None }
+    }
+
+    #[must_use]
+    pub(crate) fn get(&mut self) -> TimeDate<'_> {
+        let locked = self.locked.get_or_insert_with(|| {
+            let mut cached = LOCAL_TIME_CACHER.lock();
+            let time_date = cached.get(self.time);
+            let (nanosecond, millisecond) = (time_date.nanosecond, time_date.millisecond);
+            TimeDateLocked {
+                cached,
+                nanosecond,
+                millisecond,
+            }
+        });
+
+        TimeDate {
+            cached: locked.cached.cache_values.as_mut().unwrap(),
+            nanosecond: locked.nanosecond,
+            millisecond: locked.millisecond,
+        }
+    }
+}
+
+impl fmt::Debug for TimeDateLazyLocked<'_> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        f.debug_struct("TimeDateLazyLocked")
+            .field("time", &self.time)
+            .finish()
+    }
+}
+
 #[cfg(test)]
 mod tests {
     use super::*;

spdlog/src/formatter/mod.rs

@@ -95,15 +95,20 @@ clone_trait_object!(Formatter);
 
 /// Provides context for formatters.
 #[derive(Debug, Default)]
-pub struct FormatterContext {
+pub struct FormatterContext<'a> {
     style_range: Option<Range<usize>>,
+    // Set to `Some` if the cached date time is locked in the upper caller.
+    locked_time_date: Option<TimeDateLazyLocked<'a>>,
 }
 
-impl FormatterContext {
+impl FormatterContext<'_> {
     /// Constructs a `FormatterContext`.
     #[must_use]
     pub fn new() -> Self {
-        Self { style_range: None }
+        Self {
+            style_range: None,
+            locked_time_date: None,
+        }
     }
 
     /// Sets style range (in bytes) of the formatted text.

spdlog/src/formatter/pattern_formatter/mod.rs

@@ -12,7 +12,7 @@ use dyn_clone::*;
 pub use runtime::*;
 
 use crate::{
-    formatter::{Formatter, FormatterContext},
+    formatter::{Formatter, FormatterContext, TimeDate, TimeDateLazyLocked},
     Error, Record, StringBuf,
 };
 
@@ -381,8 +381,12 @@ where
             }
         };
 
-        let mut pat_ctx = PatternContext::new(fmt_ctx);
-        self.pattern.format(record, dest, &mut pat_ctx)?;
+        fmt_ctx.locked_time_date = Some(TimeDateLazyLocked::new(record.time()));
+        {
+            let mut pat_ctx = PatternContext { fmt_ctx };
+            self.pattern.format(record, dest, &mut pat_ctx)?;
+        }
+        fmt_ctx.locked_time_date = None;
         Ok(())
     }
 }
@@ -391,15 +395,14 @@ where
 ///
 /// There is nothing to set up here at the moment, reserved for future use.
 #[derive(Debug)]
-pub struct PatternContext<'a> {
-    fmt_ctx: &'a mut FormatterContext,
+pub struct PatternContext<'a, 'b> {
+    fmt_ctx: &'a mut FormatterContext<'b>,
 }
 
-impl<'a> PatternContext<'a> {
-    /// Creates a new `PatternContext` object.
+impl PatternContext<'_, '_> {
     #[must_use]
-    fn new(fmt_ctx: &'a mut FormatterContext) -> Self {
-        Self { fmt_ctx }
+    fn time_date(&mut self) -> TimeDate {
+        self.fmt_ctx.locked_time_date.as_mut().unwrap().get()
     }
 }
 
@@ -1221,10 +1224,12 @@ pub mod tests {
         let record = get_mock_record();
         let mut output = StringBuf::new();
         let mut fmt_ctx = FormatterContext::new();
-        let mut pat_ctx = PatternContext::new(&mut fmt_ctx);
-
-        let format_result = pattern.format(&record, &mut output, &mut pat_ctx);
-        assert!(format_result.is_ok());
+        fmt_ctx.locked_time_date = Some(TimeDateLazyLocked::new(record.time()));
+        let mut pat_ctx = PatternContext {
+            fmt_ctx: &mut fmt_ctx,
+        };
+        pattern.format(&record, &mut output, &mut pat_ctx).unwrap();
+        fmt_ctx.locked_time_date = None;
 
         assert_eq!(output.as_str(), formatted.as_ref());
         assert_eq!(fmt_ctx.style_range(), style_range);