sc_tracing/logging/
fast_local_time.rs

1// This file is part of Substrate.
2
3// Copyright (C) Parity Technologies (UK) Ltd.
4// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
5
6// This program is free software: you can redistribute it and/or modify
7// it under the terms of the GNU General Public License as published by
8// the Free Software Foundation, either version 3 of the License, or
9// (at your option) any later version.
10
11// This program is distributed in the hope that it will be useful,
12// but WITHOUT ANY WARRANTY; without even the implied warranty of
13// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
14// GNU General Public License for more details.
15
16// You should have received a copy of the GNU General Public License
17// along with this program. If not, see <https://www.gnu.org/licenses/>.
18
19use chrono::{Datelike, Timelike};
20use std::{cell::RefCell, fmt::Write, time::SystemTime};
21use tracing_subscriber::fmt::{format, time::FormatTime};
22
23/// A structure which, when `Display`d, will print out the current local time.
24#[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
25pub struct FastLocalTime {
26	/// Decides whenever the fractional timestamp with be included in the output.
27	///
28	/// If `false` the output will match the following `chrono` format string:
29	///   `%Y-%m-%d %H:%M:%S`
30	///
31	/// If `true` the output will match the following `chrono` format string:
32	///   `%Y-%m-%d %H:%M:%S%.3f`
33	pub with_fractional: bool,
34}
35
36// This is deliberately slightly larger than we actually need, just in case.
37const TIMESTAMP_MAXIMUM_LENGTH: usize = 32;
38
39#[derive(Default)]
40struct InlineString {
41	buffer: [u8; TIMESTAMP_MAXIMUM_LENGTH],
42	length: usize,
43}
44
45impl Write for InlineString {
46	fn write_str(&mut self, s: &str) -> std::fmt::Result {
47		let new_length = self.length + s.len();
48		assert!(
49			new_length <= TIMESTAMP_MAXIMUM_LENGTH,
50			"buffer overflow when formatting the current timestamp"
51		);
52
53		self.buffer[self.length..new_length].copy_from_slice(s.as_bytes());
54		self.length = new_length;
55		Ok(())
56	}
57}
58
59impl InlineString {
60	fn as_str(&self) -> &str {
61		// SAFETY: this is safe since the only place we append to the buffer
62		//         is in `write_str` from an `&str`
63		unsafe { std::str::from_utf8_unchecked(&self.buffer[..self.length]) }
64	}
65}
66
67#[derive(Default)]
68struct CachedTimestamp {
69	buffer: InlineString,
70	last_regenerated_at: u64,
71	last_fractional: u32,
72}
73
74thread_local! {
75	static TIMESTAMP: RefCell<CachedTimestamp> = Default::default();
76}
77
78impl FormatTime for FastLocalTime {
79	fn format_time(&self, w: &mut format::Writer<'_>) -> std::fmt::Result {
80		const TIMESTAMP_PARTIAL_LENGTH: usize = "0000-00-00 00:00:00".len();
81
82		let elapsed = SystemTime::now()
83			.duration_since(SystemTime::UNIX_EPOCH)
84			.expect("system time is never before UNIX epoch; qed");
85		let unix_time = elapsed.as_secs();
86
87		TIMESTAMP.with(|cache| {
88			let mut cache = cache.borrow_mut();
89
90			// Regenerate the timestamp only at most once each second.
91			if cache.last_regenerated_at != unix_time {
92				let ts = chrono::Local::now();
93				let fractional = (ts.nanosecond() % 1_000_000_000) / 1_000_000;
94				cache.last_regenerated_at = unix_time;
95				cache.last_fractional = fractional;
96				cache.buffer.length = 0;
97
98				write!(
99					&mut cache.buffer,
100					"{:04}-{:02}-{:02} {:02}:{:02}:{:02}.{:03}",
101					ts.year(),
102					ts.month(),
103					ts.day(),
104					ts.hour(),
105					ts.minute(),
106					ts.second(),
107					fractional
108				)?;
109			} else if self.with_fractional {
110				let fractional = elapsed.subsec_millis();
111
112				// Regenerate the fractional part at most once each millisecond.
113				if cache.last_fractional != fractional {
114					cache.last_fractional = fractional;
115					cache.buffer.length = TIMESTAMP_PARTIAL_LENGTH + 1;
116					write!(&mut cache.buffer, "{:03}", fractional)?;
117				}
118			}
119
120			let mut slice = cache.buffer.as_str();
121			if !self.with_fractional {
122				slice = &slice[..TIMESTAMP_PARTIAL_LENGTH];
123			}
124
125			w.write_str(slice)
126		})
127	}
128}
129
130impl std::fmt::Display for FastLocalTime {
131	fn fmt(&self, mut w: &mut std::fmt::Formatter) -> std::fmt::Result {
132		self.format_time(&mut format::Writer::new(&mut w))
133	}
134}
135
136#[test]
137fn test_format_fast_local_time() {
138	assert_eq!(
139		chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string().len(),
140		FastLocalTime { with_fractional: false }.to_string().len()
141	);
142	assert_eq!(
143		chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f").to_string().len(),
144		FastLocalTime { with_fractional: true }.to_string().len()
145	);
146
147	// A simple trick to make sure this test won't randomly fail if we so happen
148	// to land on the exact moment when we tick over to the next second.
149	let now_1 = FastLocalTime { with_fractional: false }.to_string();
150	let expected = chrono::Local::now().format("%Y-%m-%d %H:%M:%S").to_string();
151	let now_2 = FastLocalTime { with_fractional: false }.to_string();
152
153	assert!(
154		now_1 == expected || now_2 == expected,
155		"'{}' or '{}' should have been equal to '{}'",
156		now_1,
157		now_2,
158		expected
159	);
160}
sc_tracing/logging/fast_local_time.rs

sc_tracing/logging/
fast_local_time.rs
