Speed up timestamp generation when logging (#9933)

* Speed up timestamp generation when logging

* Align to review comments.

* Correct a typo

substrate/Cargo.lock

@@ -8537,6 +8537,8 @@ version = "4.0.0-dev"
 dependencies = [
  "ansi_term 0.12.1",
  "atty",
+ "chrono",
+ "criterion",
  "lazy_static",
  "log 0.4.14",
  "once_cell",

substrate/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

substrate/client/tracing/benches/bench.rs

@@ -0,0 +1,49 @@
+// This file is part of Substrate.
+
+// Copyright (C) 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);

substrate/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>;

substrate/client/tracing/src/logging/event_format.rs

@@ -16,6 +16,7 @@
 // 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};
@@ -23,16 +24,13 @@ 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.

substrate/client/tracing/src/logging/fast_local_time.rs

@@ -0,0 +1,160 @@
+// This file is part of Substrate.
+
+// Copyright (C) 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,
+}
+
+// This is deliberately slightly larger than we actually need, just in case.
+const TIMESTAMP_MAXIMUM_LENGTH: usize = 32;
+
+#[derive(Default)]
+struct InlineString {
+	buffer: [u8; TIMESTAMP_MAXIMUM_LENGTH],
+	length: usize,
+}
+
+impl Write for InlineString {
+	fn write_str(&mut self, s: &str) -> std::fmt::Result {
+		let new_length = self.length + s.len();
+		assert!(
+			new_length <= TIMESTAMP_MAXIMUM_LENGTH,
+			"buffer overflow when formatting the current timestamp"
+		);
+
+		self.buffer[self.length..new_length].copy_from_slice(s.as_bytes());
+		self.length = new_length;
+		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 is never before UNIX epoch; qed");
+		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 = 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
+	);
+}

substrate/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,8 +35,8 @@ 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,
@@ -43,6 +44,7 @@ use tracing_subscriber::{
 };
 
 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,