Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging improvements #1500

Closed
wants to merge 5 commits into from
Closed

Logging improvements #1500

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
def2fc9
Minor cleanup of unnecessarily full/partially qualified types
nazar-pc Sep 11, 2023
bb29ab5
Allow disabling colors with `NO_COLOR` environment variable
nazar-pc Sep 11, 2023
f075aa1
Print timezone offset next to timestamp in logs
nazar-pc Sep 12, 2023
7b73100
Add `--use-utc-log-time` CLI argument for printing logs in UTC
nazar-pc Sep 12, 2023
93b78fc
Default to disabled colors in logs on Windows
nazar-pc Sep 12, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 9 additions & 0 deletions substrate/client/cli/src/config.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -546,6 +546,11 @@ pub trait CliConfiguration<DCV: DefaultConfigurationValues = ()>: Sized {
Ok(self.shared_params().disable_log_color())
}

/// Should use UTC time in log output?
fn use_utc_log_time(&self) -> Result<bool> {
Ok(self.shared_params().use_utc_log_time())
}

/// Initialize substrate. This must be done only once per process.
///
/// This method:
Expand Down Expand Up @@ -600,6 +605,10 @@ pub trait CliConfiguration<DCV: DefaultConfigurationValues = ()>: Sized {
logger.with_colors(false);
}

if self.use_utc_log_time()? {
logger.with_utc(true);
}

// Call hook for custom profiling setup.
logger_hook(&mut logger, config);

Expand Down
14 changes: 12 additions & 2 deletions substrate/client/cli/src/params/shared_params.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,9 +53,14 @@ pub struct SharedParams {
pub detailed_log_output: bool,

/// Disable log color output.
#[arg(long)]
#[cfg_attr(not(windows), arg(long))]
#[cfg_attr(windows, arg(long, default_value_t = true, action = clap::ArgAction::Set))]
pub disable_log_color: bool,

/// Use UTC time in log output.
#[arg(long)]
pub use_utc_log_time: bool,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, I'd probably prefer to have this take a parameter, e.g. --timestamp-format=$format where $format can be local (default) or iso8601 (since what you've done is not just to force UTC timestamps - you've changed the format of the timestamp to be like iso8601). It's also more forward compatible if we'd want to add other formats, or make the timestamp format fully configurable with an strftime-like string.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like that, but ISO 8601 is not just UTC, so I it seems like there should still be a distinction between UTC and non-UTC in logs if you really want to have local time there (I suspect that is current expectation from Substrate users that would be undesirable to change).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well then, it could be iso8601-utc I guess?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, I read about ISO 8601, what a mess... There are so many way to compose valid ISO 8601 date and time that it is hardly helpful to name an option like that. Technically both local and UTC time in PR description are valid RFC 3339 formats, so the only difference between them is local vs UTC time and T vs between date and time (both valid).

What about something like this?:

  • --timestamp-format=default
  • --timestamp-format=tracing-subscriber

default is the current default of Substrate, tracing-subscriber is format used in that crate. Standard doesn't say anything about number of digits for fractional seconds, so both 3 and 6 is valid according to RFC 3339.

Here is helpful visualization: https://ijmacd.github.io/rfc3339-iso8601/


/// Enable feature to dynamically update and reload the log filter.
/// Be aware that enabling this feature can lead to a performance decrease up to factor six or
/// more. Depending on the global logging level the performance decrease changes.
Expand Down Expand Up @@ -114,7 +119,12 @@ impl SharedParams {

/// Should the log color output be disabled?
pub fn disable_log_color(&self) -> bool {
self.disable_log_color
std::env::var("NO_COLOR").map_or(self.disable_log_color, |no_color| no_color == "1")
}

/// Should use UTC time in log output?
pub fn use_utc_log_time(&self) -> bool {
self.use_utc_log_time
}

/// Is log reloading enabled
Expand Down
12 changes: 10 additions & 2 deletions substrate/client/tracing/benches/bench.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,9 +19,17 @@ 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| {
c.bench_function("fast_local_time/local", |b| {
let mut buffer = String::new();
let t = sc_tracing::logging::FastLocalTime { with_fractional: true };
let t = sc_tracing::logging::FastLocalTime { utc: false, with_fractional: true };
b.iter(|| {
buffer.clear();
t.format_time(&mut buffer).unwrap();
})
});
c.bench_function("fast_local_time/utc", |b| {
let mut buffer = String::new();
let t = sc_tracing::logging::FastLocalTime { utc: true, with_fractional: true };
b.iter(|| {
buffer.clear();
t.format_time(&mut buffer).unwrap();
Expand Down
4 changes: 2 additions & 2 deletions substrate/client/tracing/src/logging/event_format.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ where
pub(crate) fn format_event_custom<'b, S, N>(
&self,
ctx: CustomFmtContext<'b, S, N>,
writer: &mut dyn fmt::Write,
writer: &mut dyn Write,
event: &Event,
) -> fmt::Result
where
Expand Down Expand Up @@ -127,7 +127,7 @@ where
fn format_event(
&self,
ctx: &FmtContext<S, N>,
writer: &mut dyn fmt::Write,
writer: &mut dyn Write,
event: &Event,
) -> fmt::Result {
if self.dup_to_stdout &&
Expand Down
135 changes: 99 additions & 36 deletions substrate/client/tracing/src/logging/fast_local_time.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,19 +17,28 @@
// 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 std::{cell::RefCell, fmt, fmt::Write, time::SystemTime};
use tracing_subscriber::fmt::time::FormatTime;

/// A structure which, when `Display`d, will print out the current local time.
/// A structure which, when `Display`d, will print out the current time either in local timezone or
/// in UTC.
#[derive(Debug, Clone, Copy, Eq, PartialEq, Default)]
pub struct FastLocalTime {
/// Decides whenever to use UTC timezone instead.
///
/// If `true` the output will match the following `chrono` format string:
/// `%Y-%m-%dT%H:%M:%S%.6fZ`
///
/// This is the same format used by [`tracing_subscriber`] by default, `with_fractional` has no
/// effect when this option is set to `true`.
pub utc: bool,
/// 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`
/// `%Y-%m-%d %H:%M:%S%:z`
///
/// If `true` the output will match the following `chrono` format string:
/// `%Y-%m-%d %H:%M:%S%.3f`
/// `%Y-%m-%d %H:%M:%S%.3f%:z`
pub with_fractional: bool,
}

Expand All @@ -43,7 +52,7 @@ struct InlineString {
}

impl Write for InlineString {
fn write_str(&mut self, s: &str) -> std::fmt::Result {
fn write_str(&mut self, s: &str) -> fmt::Result {
let new_length = self.length + s.len();
assert!(
new_length <= TIMESTAMP_MAXIMUM_LENGTH,
Expand All @@ -66,8 +75,10 @@ impl InlineString {

#[derive(Default)]
struct CachedTimestamp {
timezone_offset: InlineString,
buffer: InlineString,
last_regenerated_at: u64,
last_utc: bool,
last_fractional: u32,
}

Expand All @@ -76,7 +87,8 @@ thread_local! {
}

impl FormatTime for FastLocalTime {
fn format_time(&self, w: &mut dyn Write) -> std::fmt::Result {
fn format_time(&self, w: &mut dyn Write) -> fmt::Result {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you rewrite this so that:

  1. There are two timestamp caches, one for local time and another for UTC. (This will make CachedTimestamp::last_utc unnecessary.)
  2. The body of this function would essentially be something like this:
// Outside:
fn format_time_local(...) { ... }
fn format_time_utc(...) { ... }
// ...
// Inside::
let unix_time = ...;
if self.utc {
    format_time_utc(...)
} else {
    format_time_local(...)
}

This way there will only be a single toplevel if self.utc check.

const TIMESTAMP_PARTIAL_UTC_LENGTH: usize = "0000-00-00T00:00:00".len();
const TIMESTAMP_PARTIAL_LENGTH: usize = "0000-00-00 00:00:00".len();

let elapsed = SystemTime::now()
Expand All @@ -88,24 +100,59 @@ impl FormatTime for FastLocalTime {
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
)?;
if cache.last_regenerated_at != unix_time || cache.last_utc != self.utc {
cache.last_utc = self.utc;

if self.utc {
let ts = chrono::Utc::now();
let fractional = (ts.nanosecond() % 1_000_000_000) / 1_000;
cache.last_regenerated_at = unix_time;
cache.last_fractional = fractional;
cache.buffer.length = 0;

write!(
&mut cache.buffer,
"{:04}-{:02}-{:02}T{:02}:{:02}:{:02}.{:06}Z",
ts.year(),
ts.month(),
ts.day(),
ts.hour(),
ts.minute(),
ts.second(),
fractional
)?;
} else {
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
)?;

if cache.timezone_offset.length == 0 {
write!(&mut cache.timezone_offset, "{}", ts.offset())?;
}
Comment on lines +143 to +145
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In theory the current timezone can change, so this should not assume that the timezone stays constant.

This is only done once per second, so its fine to do this unconditionally.

}
} else if self.utc {
let fractional = elapsed.subsec_micros();

// Regenerate the fractional part at most once each millisecond.
if cache.last_fractional != fractional {
cache.last_fractional = fractional;
cache.buffer.length = TIMESTAMP_PARTIAL_UTC_LENGTH + 1;
write!(&mut cache.buffer, "{:06}Z", fractional)?;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

6 digits for the fractional part seems somewhat excessive; why not use 3 like in the non-UTC case?

The logger's asynchronous anyway so this much precision is practically useless. It'll just take extra space in the logs for no real benefit.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The reason is to make it identical to what tracing-subscriber does by default. We use Substrate as a library in a bigger application, so having various logging formats interleaved is awkward and undesirable.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, that's reasonable if that's the tracing-subscriber default.

}
} else if self.with_fractional {
let fractional = elapsed.subsec_millis();

Expand All @@ -118,37 +165,53 @@ impl FormatTime for FastLocalTime {
}

let mut slice = cache.buffer.as_str();
if !self.with_fractional {
slice = &slice[..TIMESTAMP_PARTIAL_LENGTH];

if self.utc {
w.write_str(slice)?;
} else {
Comment on lines +169 to +171
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The with_fractional should not be silently ignored when using UTC timestamps.

Either we make it obey with_fractional, or the timestamp format should be an enum (so then in the UTC case there just wouldn't be with_fractional)

if !self.with_fractional {
slice = &slice[..TIMESTAMP_PARTIAL_LENGTH];
}

w.write_str(slice)?;
w.write_str(cache.timezone_offset.as_str())?;
}

w.write_str(slice)
Ok(())
})
}
}

impl std::fmt::Display for FastLocalTime {
fn fmt(&self, w: &mut std::fmt::Formatter) -> std::fmt::Result {
impl fmt::Display for FastLocalTime {
fn fmt(&self, w: &mut fmt::Formatter) -> 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()
chrono::Local::now().format("%Y-%m-%d %H:%M:%S%:z").to_string().len(),
FastLocalTime { utc: false, with_fractional: false }.to_string().len()
);
assert_eq!(
chrono::Local::now().format("%Y-%m-%d %H:%M:%S%.3f%:z").to_string().len(),
FastLocalTime { utc: false, with_fractional: true }.to_string().len()
);
assert_eq!(
chrono::Utc::now().format("%Y-%m-%dT%H:%M:%S%.6fZ").to_string().len(),
FastLocalTime { utc: true, 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()
chrono::Utc::now().format("%Y-%m-%dT%H:%M:%S%.6fZ").to_string().len(),
FastLocalTime { utc: true, 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();
let now_1 = FastLocalTime { utc: false, with_fractional: false }.to_string();
let expected = chrono::Local::now().format("%Y-%m-%d %H:%M:%S%:z").to_string();
let now_2 = FastLocalTime { utc: false, with_fractional: false }.to_string();

assert!(
now_1 == expected || now_2 == expected,
Expand Down
Loading