1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
// This file is part of Substrate.

// Copyright (C) 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/>.

//! This module contains a buffered semi-asynchronous stderr writer.
//!
//! Depending on how we were started writing to stderr can take a surprisingly long time.
//!
//! If the other side takes their sweet sweet time reading whatever we send them then writing
//! to stderr might block for a long time, since it is effectively a synchronous operation.
//! And every time we write to stderr we need to grab a global lock, which affects every thread
//! which also tries to log something at the same time.
//!
//! Of course we *will* be ultimately limited by how fast the recipient can ingest our logs,
//! but it's not like logging is the only thing we're doing. And we still can't entirely
//! avoid the problem of multiple threads contending for the same lock. (Well, technically
//! we could employ something like a lock-free circular buffer, but that might be like
//! killing a fly with a sledgehammer considering the complexity involved; this is only
//! a logger after all.)
//!
//! But we can try to make things a little better. We can offload actually writing to stderr
//! to another thread and flush the logs in bulk instead of doing it per-line, which should
//! reduce the amount of CPU time we waste on making syscalls and on spinning waiting for locks.
//!
//! How much this helps depends on a multitude of factors, including the hardware we're running on,
//! how much we're logging, from how many threads, which exact set of threads are logging, to what
//! stderr is actually connected to (is it a terminal emulator? a file? an UDP socket?), etc.
//!
//! In general this can reduce the real time execution time as much as 75% in certain cases, or it
//! can make absolutely no difference in others.

use parking_lot::{Condvar, Mutex, Once};
use std::{
	io::Write,
	sync::atomic::{AtomicBool, Ordering},
	time::Duration,
};
use tracing::{Level, Metadata};

/// How many bytes of buffered logs will trigger an async flush on another thread?
const ASYNC_FLUSH_THRESHOLD: usize = 16 * 1024;

/// How many bytes of buffered logs will trigger a sync flush on the current thread?
const SYNC_FLUSH_THRESHOLD: usize = 768 * 1024;

/// How many bytes can be buffered at maximum?
const EMERGENCY_FLUSH_THRESHOLD: usize = 2 * 1024 * 1024;

/// If there isn't enough printed out this is how often the logs will be automatically flushed.
const AUTOFLUSH_EVERY: Duration = Duration::from_millis(50);

/// The least serious level at which a synchronous flush will be triggered.
const SYNC_FLUSH_LEVEL_THRESHOLD: Level = Level::ERROR;

/// The amount of time we'll block until the buffer is fully flushed on exit.
///
/// This should be completely unnecessary in normal circumstances.
const ON_EXIT_FLUSH_TIMEOUT: Duration = Duration::from_secs(5);

/// A global buffer to which we'll append all of our logs before flushing them out to stderr.
static BUFFER: Mutex<Vec<u8>> = parking_lot::const_mutex(Vec::new());

/// A spare buffer which we'll swap with the main buffer on each flush to minimize lock contention.
static SPARE_BUFFER: Mutex<Vec<u8>> = parking_lot::const_mutex(Vec::new());

/// A conditional variable used to forcefully trigger asynchronous flushes.
static ASYNC_FLUSH_CONDVAR: Condvar = Condvar::new();

static ENABLE_ASYNC_LOGGING: AtomicBool = AtomicBool::new(true);

fn flush_logs(mut buffer: parking_lot::lock_api::MutexGuard<parking_lot::RawMutex, Vec<u8>>) {
	let mut spare_buffer = SPARE_BUFFER.lock();
	std::mem::swap(&mut *spare_buffer, &mut *buffer);
	std::mem::drop(buffer);

	let stderr = std::io::stderr();
	let mut stderr_lock = stderr.lock();
	let _ = stderr_lock.write_all(&spare_buffer);
	std::mem::drop(stderr_lock);

	spare_buffer.clear();
}

fn log_autoflush_thread() {
	let mut buffer = BUFFER.lock();
	loop {
		ASYNC_FLUSH_CONDVAR.wait_for(&mut buffer, AUTOFLUSH_EVERY);
		loop {
			flush_logs(buffer);

			buffer = BUFFER.lock();
			if buffer.len() >= ASYNC_FLUSH_THRESHOLD {
				// While we were busy flushing we picked up enough logs to do another flush.
				continue
			} else {
				break
			}
		}
	}
}

#[cold]
fn initialize() {
	std::thread::Builder::new()
		.name("log-autoflush".to_owned())
		.spawn(log_autoflush_thread)
		.expect("thread spawning doesn't normally fail; qed");

	// SAFETY: This is safe since we pass a valid pointer to `atexit`.
	let errcode = unsafe { libc::atexit(on_exit) };
	assert_eq!(errcode, 0, "atexit failed while setting up the logger: {}", errcode);
}

extern "C" fn on_exit() {
	ENABLE_ASYNC_LOGGING.store(false, Ordering::SeqCst);

	if let Some(buffer) = BUFFER.try_lock_for(ON_EXIT_FLUSH_TIMEOUT) {
		flush_logs(buffer);
	}
}

/// A drop-in replacement for [`std::io::stderr`] for use anywhere
/// a [`tracing_subscriber::fmt::MakeWriter`] is accepted.
pub struct MakeStderrWriter {
	// A dummy field so that the structure is not publicly constructible.
	_dummy: (),
}

impl Default for MakeStderrWriter {
	fn default() -> Self {
		static ONCE: Once = Once::new();
		ONCE.call_once(initialize);
		MakeStderrWriter { _dummy: () }
	}
}

impl tracing_subscriber::fmt::MakeWriter<'_> for MakeStderrWriter {
	type Writer = StderrWriter;

	fn make_writer(&self) -> Self::Writer {
		StderrWriter::new(false)
	}

	// The `tracing-subscriber` crate calls this for every line logged.
	fn make_writer_for(&self, meta: &Metadata<'_>) -> Self::Writer {
		StderrWriter::new(*meta.level() <= SYNC_FLUSH_LEVEL_THRESHOLD)
	}
}

pub struct StderrWriter {
	buffer: Option<parking_lot::lock_api::MutexGuard<'static, parking_lot::RawMutex, Vec<u8>>>,
	sync_flush_on_drop: bool,
	original_len: usize,
}

impl StderrWriter {
	fn new(mut sync_flush_on_drop: bool) -> Self {
		if !ENABLE_ASYNC_LOGGING.load(Ordering::Relaxed) {
			sync_flush_on_drop = true;
		}

		// This lock isn't as expensive as it might look, since this is only called once the full
		// line to be logged is already serialized into a thread-local buffer inside of the
		// `tracing-subscriber` crate, and basically the only thing we'll do when holding this lock
		// is to copy that over to our global shared buffer in one go in `Write::write_all` and be
		// immediately dropped.
		let buffer = BUFFER.lock();
		StderrWriter { original_len: buffer.len(), buffer: Some(buffer), sync_flush_on_drop }
	}
}

#[cold]
fn emergency_flush(buffer: &mut Vec<u8>, input: &[u8]) {
	let stderr = std::io::stderr();
	let mut stderr_lock = stderr.lock();
	let _ = stderr_lock.write_all(buffer);
	buffer.clear();

	let _ = stderr_lock.write_all(input);
}

impl Write for StderrWriter {
	fn write(&mut self, input: &[u8]) -> Result<usize, std::io::Error> {
		let buffer = self.buffer.as_mut().expect("buffer is only None after `drop`; qed");
		if buffer.len() + input.len() >= EMERGENCY_FLUSH_THRESHOLD {
			// Make sure we don't blow our memory budget. Normally this should never happen,
			// but there are cases where we directly print out untrusted user input which
			// can potentially be megabytes in size.
			emergency_flush(buffer, input);
		} else {
			buffer.extend_from_slice(input);
		}
		Ok(input.len())
	}

	fn write_all(&mut self, input: &[u8]) -> Result<(), std::io::Error> {
		self.write(input).map(|_| ())
	}

	fn flush(&mut self) -> Result<(), std::io::Error> {
		Ok(())
	}
}

impl Drop for StderrWriter {
	fn drop(&mut self) {
		let buf = self.buffer.take().expect("buffer is only None after `drop`; qed");
		if self.sync_flush_on_drop || buf.len() >= SYNC_FLUSH_THRESHOLD {
			flush_logs(buf);
		} else if self.original_len < ASYNC_FLUSH_THRESHOLD && buf.len() >= ASYNC_FLUSH_THRESHOLD {
			ASYNC_FLUSH_CONDVAR.notify_one();
		}
	}
}