Skip to content
This repository has been archived by the owner on Nov 15, 2023. It is now read-only.

Commit

Permalink
Speed up timestamp generation when logging (#9933)
Browse files Browse the repository at this point in the history
* Speed up timestamp generation when logging

* Align to review comments.

* Correct a typo
  • Loading branch information
koute authored Oct 5, 2021
1 parent a30f0d1 commit ddf8992
Show file tree
Hide file tree
Showing 7 changed files with 230 additions and 21 deletions.
2 changes: 2 additions & 0 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

8 changes: 8 additions & 0 deletions client/tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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
49 changes: 49 additions & 0 deletions client/tracing/benches/bench.rs
Original file line number Diff line number Diff line change
@@ -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);
5 changes: 2 additions & 3 deletions client/tracing/src/logging/directives.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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>;
8 changes: 3 additions & 5 deletions client/tracing/src/logging/event_format.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
160 changes: 160 additions & 0 deletions client/tracing/src/logging/fast_local_time.rs
Original file line number Diff line number Diff line change
@@ -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
);
}
19 changes: 6 additions & 13 deletions client/tracing/src/logging/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@

mod directives;
mod event_format;
mod fast_local_time;
mod layers;

pub use directives::*;
Expand All @@ -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.
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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,
Expand Down

0 comments on commit ddf8992

Please sign in to comment.