Speed up timestamp generation when logging

client/tracing/Cargo.toml

@@ -15,6 +15,7 @@ targets = ["x86_64-unknown-linux-gnu"]
 [dependencies]
 ansi_term = "0.12.1"
 atty = "0.2.13"
+chrono = "0.4.19"
 lazy_static = "1.4.0"
 log = { version = "0.4.8" }
 once_cell = "1.4.1"
@@ -35,3 +36,10 @@ sp-core = { version = "4.0.0-dev", path = "../../primitives/core" }
 sc-client-api = { version = "4.0.0-dev", path = "../api" }
 sc-tracing-proc-macro = { version = "4.0.0-dev", path = "./proc-macro" }
 sc-rpc-server = { version = "4.0.0-dev", path = "../rpc-servers" }
+
+[dev-dependencies]
+criterion = "0.3"
+
+[[bench]]
+name = "bench"
+harness = false

client/tracing/benches/bench.rs

@@ -0,0 +1,49 @@
+// This file is part of Substrate.
+
+// Copyright (C) 2019-2021 Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: Apache-2.0
+
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+use criterion::{criterion_group, criterion_main, Criterion};
+use tracing_subscriber::fmt::time::{ChronoLocal, FormatTime};
+
+fn bench_fast_local_time(c: &mut Criterion) {
+ c.bench_function("fast_local_time", |b| {
+ let mut buffer = String::new();
+ let t = sc_tracing::logging::FastLocalTime { with_fractional: true };
+ b.iter(|| {
+ buffer.clear();
+ t.format_time(&mut buffer).unwrap();
+ })
+ });
+}
+
+// This is here just as a point of comparison.
+fn bench_chrono_local(c: &mut Criterion) {
+ c.bench_function("chrono_local", |b| {
+ let mut buffer = String::new();
+ let t = ChronoLocal::with_format("%Y-%m-%d %H:%M:%S%.3f".to_string());
+ b.iter(|| {
+ buffer.clear();
+ t.format_time(&mut buffer).unwrap();
+ })
+ });
+}
+
+criterion_group! {
+ name = benches;
+ config = Criterion::default();
+ targets = bench_fast_local_time, bench_chrono_local
+}
+criterion_main!(benches);

client/tracing/src/logging/directives.rs

@@ -17,8 +17,7 @@
 use once_cell::sync::OnceCell;
 use parking_lot::Mutex;
 use tracing_subscriber::{
- filter::Directive, fmt as tracing_fmt, fmt::time::ChronoLocal, layer, reload::Handle,
- EnvFilter, Registry,
+ filter::Directive, fmt as tracing_fmt, layer, reload::Handle, EnvFilter, Registry,
 };
 
 // Handle to reload the tracing log filter
@@ -109,6 +108,6 @@ pub(crate) fn set_reload_handle(handle: Handle<EnvFilter, SCSubscriber>) {
 // Used in the reload `Handle`.
 type SCSubscriber<
  N = tracing_fmt::format::DefaultFields,
- E = crate::logging::EventFormat<ChronoLocal>,
+ E = crate::logging::EventFormat,
  W = fn() -> std::io::Stderr,
 > = layer::Layered<tracing_fmt::Layer<Registry, N, E, W>, Registry>;

client/tracing/src/logging/event_format.rs

@@ -16,23 +16,21 @@
 // You should have received a copy of the GNU General Public License
 // along with this program. If not, see <https://www.gnu.org/licenses/>.
 
+use crate::logging::fast_local_time::FastLocalTime;
 use ansi_term::Colour;
 use regex::Regex;
 use std::fmt::{self, Write};
 use tracing::{Event, Level, Subscriber};
 use tracing_log::NormalizeEvent;
 use tracing_subscriber::{
  field::RecordFields,
- fmt::{
- time::{FormatTime, SystemTime},
- FmtContext, FormatEvent, FormatFields,
- },
+ fmt::{time::FormatTime, FmtContext, FormatEvent, FormatFields},
  layer::Context,
  registry::{LookupSpan, SpanRef},
 };
 
 /// A pre-configured event formatter.
-pub struct EventFormat<T = SystemTime> {
+pub struct EventFormat<T = FastLocalTime> {
  /// Use the given timer for log message timestamps.
  pub timer: T,
  /// Sets whether or not an event's target is displayed.

client/tracing/src/logging/fast_local_time.rs

@@ -0,0 +1,152 @@
+// This file is part of Substrate.
+
+// Copyright (C) 2020-2021 Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+use chrono::{Datelike, Timelike};
+use std::{cell::RefCell, fmt::Write, time::SystemTime};
+use tracing_subscriber::fmt::time::FormatTime;
+
+/// A structure which, when `Display`d, will print out the current local time.
+#[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
+pub struct FastLocalTime {
+ /// Decides whenever the fractional timestamp with be included in the output.
+ ///
+ /// If `false` the output will match the following `chrono` format string:
+ /// `%Y-%m-%d %H:%M:%S`
+ ///
+ /// If `true` the output will match the following `chrono` format string:
+ /// `%Y-%m-%d %H:%M:%S%.3f`
+ pub with_fractional: bool,
+}
+
+#[derive(Default)]
+struct InlineString {
+ buffer: [u8; 32],
+ length: usize,
+}
+
+impl Write for InlineString {
+ fn write_str(&mut self, s: &str) -> std::fmt::Result {
+ self.buffer[self.length..self.length + s.len()].copy_from_slice(s.as_bytes());
+ self.length += s.len();
+ Ok(())
+ }
+}
+
+impl InlineString {
+ fn as_str(&self) -> &str {
+ // SAFETY: this is safe since the only place we append to the buffer
+ // is in `write_str` from an `&str`
+ unsafe { std::str::from_utf8_unchecked(&self.buffer[..self.length]) }
+ }
+}
+
+#[derive(Default)]
+struct CachedTimestamp {
+ buffer: InlineString,
+ last_regenerated_at: u64,
+ last_fractional: u32,
+}
+
+thread_local! {
+ static TIMESTAMP: RefCell<CachedTimestamp> = Default::default();
+}
+
+impl FormatTime for FastLocalTime {
+ fn format_time(&self, w: &mut dyn Write) -> std::fmt::Result {
+ const TIMESTAMP_PARTIAL_LENGTH: usize = "0000-00-00 00:00:00".len();
+
+ let elapsed = SystemTime::now()
+ .duration_since(SystemTime::UNIX_EPOCH)
+ .expect("system time should never be before UNIX epoch");
+ let unix_time = elapsed.as_secs();
+
+ TIMESTAMP.with(|cache| {
+ let mut cache = cache.borrow_mut();
+
+ // Regenerate the timestamp only at most once each second.
+ if cache.last_regenerated_at != unix_time {
+ let ts = chrono::Local::now();
+ let fractional = (ts.nanosecond() % 1_000_000_000) / 1_000_000;
+ cache.last_regenerated_at = unix_time;
+ cache.last_fractional = fractional;
+ cache.buffer.length = 0;
+
+ write!(
+ &mut cache.buffer,
+ "{:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03}",
+ ts.year(),
+ ts.month(),
+ ts.day(),
+ ts.hour(),
+ ts.minute(),
+ ts.second(),
+ fractional
+ )?;
+ } else if self.with_fractional {
+ let fractional = elapsed.subsec_millis();
+
+ // Regenerate the fractional part at most once each millisecond.
+ if cache.last_fractional != fractional {
+ cache.last_fractional = fractional;
+ cache.buffer.length =
+ std::cmp::min(cache.buffer.length, TIMESTAMP_PARTIAL_LENGTH + 1);
+ write!(&mut cache.buffer, "{:03}", fractional)?;
+ }
+ }
+
+ let mut slice = cache.buffer.as_str();
+ if !self.with_fractional {
+ slice = &slice[..TIMESTAMP_PARTIAL_LENGTH];
+ }
+
+ w.write_str(slice)
+ })
+ }
+}
+
+impl std::fmt::Display for FastLocalTime {
+ fn fmt(&self, w: &mut std::fmt::Formatter) -> std::fmt::Result {
+ self.format_time(w)
+ }
+}
+
+#[test]
+fn test_format_fast_local_time() {
+ assert_eq!(
+ chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string().len(),
+ FastLocalTime { with_fractional: false }.to_string().len()
+ );
+ assert_eq!(
+ chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f").to_string().len(),
+ FastLocalTime { with_fractional: true }.to_string().len()
+ );
+
+ // A simple trick to make sure this test won't randomly fail if we so happen
+ // to land on the exact moment when we tick over to the next second.
+ let now_1 = FastLocalTime { with_fractional: false }.to_string();
+ let expected = chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string();
+ let now_2 = FastLocalTime { with_fractional: false }.to_string();
+
+ assert!(
+ now_1 == expected || now_2 == expected,
+ "'{}' or '{}' should have been equal to '{}'",
+ now_1,
+ now_2,
+ expected
+ );
+}

client/tracing/src/logging/mod.rs

@@ -24,6 +24,7 @@
 
 mod directives;
 mod event_format;
+mod fast_local_time;
 mod layers;
 
 pub use directives::*;
@@ -34,15 +35,16 @@ use tracing::Subscriber;
 use tracing_subscriber::{
  filter::LevelFilter,
  fmt::{
- format, time::ChronoLocal, FormatEvent, FormatFields, Formatter, Layer as FmtLayer,
- MakeWriter, SubscriberBuilder,
+ format, FormatEvent, FormatFields, Formatter, Layer as FmtLayer, MakeWriter,
+ SubscriberBuilder,
  },
  layer::{self, SubscriberExt},
  registry::LookupSpan,
  EnvFilter, FmtSubscriber, Layer, Registry,
 };
 
 pub use event_format::*;
+pub use fast_local_time::FastLocalTime;
 pub use layers::*;
 
 /// Logging Result typedef.
@@ -89,12 +91,7 @@ fn prepare_subscriber<N, E, F, W>(
  profiling_targets: Option<&str>,
  force_colors: Option<bool>,
  builder_hook: impl Fn(
- SubscriberBuilder<
- format::DefaultFields,
- EventFormat<ChronoLocal>,
- EnvFilter,
- fn() -> std::io::Stderr,
- >,
+ SubscriberBuilder<format::DefaultFields, EventFormat, EnvFilter, fn() -> std::io::Stderr>,
  ) -> SubscriberBuilder<N, E, F, W>,
 ) -> Result<impl Subscriber + for<'a> LookupSpan<'a>>
 where
@@ -161,11 +158,7 @@ where
  };
 
  let enable_color = force_colors.unwrap_or_else(|| atty::is(atty::Stream::Stderr));
- let timer = ChronoLocal::with_format(if simple {
- "%Y-%m-%d %H:%M:%S".to_string()
- } else {
- "%Y-%m-%d %H:%M:%S%.3f".to_string()
- });
+ let timer = fast_local_time::FastLocalTime { with_fractional: !simple };
 
  let event_format = EventFormat {
  timer,