diff --git a/Cargo.lock b/Cargo.lock index 622b52591b90d..1d23e8814bb04 100644 --- a/Cargo.lock +++ b/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", diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 3e314a82aa583..445718d6306f8 100644 --- a/client/tracing/Cargo.toml +++ b/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 diff --git a/client/tracing/benches/bench.rs b/client/tracing/benches/bench.rs new file mode 100644 index 0000000000000..ee218958be9b3 --- /dev/null +++ b/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); diff --git a/client/tracing/src/logging/directives.rs b/client/tracing/src/logging/directives.rs index 5aaeb4d17e7d3..16f68654de1eb 100644 --- a/client/tracing/src/logging/directives.rs +++ b/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) { // Used in the reload `Handle`. type SCSubscriber< N = tracing_fmt::format::DefaultFields, - E = crate::logging::EventFormat, + E = crate::logging::EventFormat, W = fn() -> std::io::Stderr, > = layer::Layered, Registry>; diff --git a/client/tracing/src/logging/event_format.rs b/client/tracing/src/logging/event_format.rs index 61d7fe77aec68..5a21192d69c4d 100644 --- a/client/tracing/src/logging/event_format.rs +++ b/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 . +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 { +pub struct EventFormat { /// Use the given timer for log message timestamps. pub timer: T, /// Sets whether or not an event's target is displayed. diff --git a/client/tracing/src/logging/fast_local_time.rs b/client/tracing/src/logging/fast_local_time.rs new file mode 100644 index 0000000000000..288e44aa5e3af --- /dev/null +++ b/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 . + +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 = 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 + ); +} diff --git a/client/tracing/src/logging/mod.rs b/client/tracing/src/logging/mod.rs index dd4830fe89752..dd0f7a5d8ae49 100644 --- a/client/tracing/src/logging/mod.rs +++ b/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( profiling_targets: Option<&str>, force_colors: Option, builder_hook: impl Fn( - SubscriberBuilder< - format::DefaultFields, - EventFormat, - EnvFilter, - fn() -> std::io::Stderr, - >, + SubscriberBuilder std::io::Stderr>, ) -> SubscriberBuilder, ) -> Result 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,