From the very beginning of Portable, logging is always a four-tiered simple idea: We assemble a formatted String with a designated log level to dictate the importance of this message, call a specific function to send this data over standard output or error.

It’s quite simple in the old bash days, both in terms of caller and worker:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
function pecho() {
	if [[ "$1" = "debug" ]] && [[ "${PORTABLE_LOGGING}" = "debug" ]]; then
		echo "[Debug] $2" &
	elif [[ "$1" = "info" ]] && [[ "${PORTABLE_LOGGING}" = "info" || "${PORTABLE_LOGGING}" = "debug" ]]; then
		echo "[Info] $2" &
	elif [[ "$1" = "warn" ]]; then
		echo "[Warn] $2" &
	elif [[ "$1" = "crit" ]]; then
		echo "[Critical] $2"
	fi
}


if [[ "${_portalConfig}" ]]; then
	export _portableConfig="${_portalConfig}"
	pecho warn "Using legacy configuration variable!"
fi

Caller just call pecho and it spawns a worker in thread, simple as that.

This idea of tiered logging became a lineage of Portable, with its foundation preserved to this very day with many later additions.

Asynchronous logging in Portable 13

After the switch to Go and ultimately Rust, we found out that logging can be very “hot”, especially when running in debug mode because Portable would output a lot of debugging messages. As such, we decided to move on and create an asynchronous version of the logger. It unblocks the working thread (goroutine) from writing potentially slow OS standard output / error. The idea is still very simple: a single Go / Rust struct represents a “String” of message combined with a level associated. We just send them along the channel.

The move to Rust also liberated the logger from comparing “String”s to comparing a Rust enum, which dramatically reduces the size of logging messages sent on the channel by 23 bytes and makes match arms faster:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
fn main() {
    println!(
        "size of LogLevel: {}",
        std::mem::size_of::<LogLevel>(),
    );
    
    println!(
        "size of String: {}",
        std::mem::size_of::<String>(),
    );
}

pub enum LogLevel {
	Debug,
	Info,
	Warn,
	Fatal,
}

pub struct LogMessage {
	pub level:		LogLevel,
	pub message:		String,
}
1
2
3
4
➜  ~ rustc old.rs
➜  ~ ./old
size of LogLevel: 1
size of String: 24

This brings even higher throughput since every single log message is reduced in byte size. That works, but each producer still has to decide how to turn its data into text before the message even reaches the output thread. The whole LogMessage is 32 byte in memory, but there is still room for improvement and size is not always the biggest bottleneck.

Understanding the data types

String, Enumerator, Integers and Arc pointers. These are some of the most used data types used to construct a Portable logging message. Portable usually calls the Debug trait via format specifiers to present them, but it is not strictly right since Display is meant to fit this job and it would clutter the calling thread’s code. To implement the “right way” of displaying (pun intended) types, we can write a simple code block and expand as variants are added:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
impl std::fmt::Display for InfoMessage {
	fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
		match self {
			Self::DaemonVersion			=> {
				f.write_fmt(
					format_args!(
						"Portable daemon, version {}",
						env!("CARGO_PKG_VERSION_MAJOR"),
					)
				)
			}
		}
	}
}

Another blocking work is that, each and every logging invocation needs to call format! and allocate a String on the heap. The main performance opportunity is on the producer side. If we can defer formatting and String allocation to the logging thread, the main thread can start up faster, wasting less time and reach a useable state sooner.

The next generation logging infrastructure employs those design principles at the very beginning. It defines a new LogMessage enum that holds 4 sub-enums:

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
pub mod debug;
pub mod fatal;
pub mod info;
pub mod warn;

/**
	The central LogMessage implementation.

	It implements the std::fmt::Display trait for presentation
*/
pub enum LogMessage {
	#[cfg(debug_assertions)]
	Debug(debug::DebugMessage),

	Info(info::InfoMessage),

	Warn(warn::WarnMessage),

	Fatal(fatal::FatalMessage),
}

impl std::fmt::Display for LogMessage {
	fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
		match self {
			#[cfg(debug_assertions)]
			LogMessage::Debug(v)	=> {
				v.fmt(f)
			}
			LogMessage::Info(v)	=> {
				v.fmt(f)
			}
			LogMessage::Warn(v)	=> {
				v.fmt(f)
			}
			LogMessage::Fatal(v)	=> {
				v.fmt(f)
			}
		}
	}
}

The core idea is still simple. Send this public LogMessage enum over a multi-producer single consumer channel and the logging thread takes over everything. Every sub-variation implements the std::fmt::Display trait for user presentation. The gain, however, is avoiding eager string construction, not speeding up the channel itself. Because the channel is nearly unbounded, producers don’t wait for the logger to catch up. That keeps sending simple, but it also means a sustained logging burst can still build a queue. Typed events may reduce the cost of creating each message, while moving formatting work to the logger. As we use format! quite often, this can be quite a benefit.

Another benefit comes with this new design too. Marking the entire debug variant debug_assertions only makes sure we don’t do debug logging in release profile and it uncovered some of those oversights in migration.

Other optimisations, internationalisation

First and foremost, while the new enum may look large in size because it wraps several external types, Portable doesn’t have enough logging work to overrun the tokio channel. What matters more in production is formatting directly on main. And we can always box large types if they ever cause trouble.

With the introduction of asynchronous logging thread, a specific issue has plagued Portable since 13: sometimes the entire program just exits early without logger draining it’s queue, causing dropped messages that might just be important.

For example, when you revoke a certain app’s permission, these lines should show: 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
PORTABLE_CONF=org.example.App portable --revoke-permissions

[Debug]:	Using logger configuration: Console {
	colour: Normal,
}
[Info]:		Portable daemon, version 21
[Warn]:		Build type is debug, expect slowdown and verbose logging
[Debug]:	Selected configuration: "/usr/lib/portable/info/org.example.App/config.toml"
[Debug]:	Reset permission: table screenshot ID screenshot
[Debug]:	Reset permission: table location ID location
[Debug]:	Reset permission: table notifications ID notification
[Debug]:	Reset permission: table top.kimiblock.Portable ID expose-rw
[Debug]:	Reset permission: table top.kimiblock.Portable ID expose-ro
[Debug]:	Reset permission: table top.kimiblock.Portable ID expose-device
[Debug]:	Reset permission: table top.kimiblock.Portable ID dynamic-permissions
[Info]:		Permissions for org.example.App has been revoked

But if the logging thread is behind, you may not see Permissions for org.example.App has been revoked. This also happens for critical errors, which may often mislead users and leave important debugging message in the void. The duct-tape fix before is to just use biased tokio::select! when looping to prefer processing log events:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
let msg = tokio::select! {
	biased;
	log_msg = log_rx.recv()			=> {
		match log_msg {
			Some(v)	=> v,
			None	=> {
				return;
			}
		}
	}
	_	= stop_token.cancelled()	=> {
		return ;
	}
};

But it does not rectify the root cause: if stop_token gets cancelled while someone was trying to send a message or the channel is not ready for whatever reason, it would break instantly. Judging from tokio documents, a “clean shutdown” is needed to avoid said issue:

When the Receiver is dropped, it is possible for unprocessed messages to remain in the channel. Instead, it is usually desirable to perform a “clean” shutdown. To do this, the receiver first calls close, which will prevent any further messages to be sent into the channel. Then, the receiver consumes the channel to completion, at which point the receiver can be dropped.

As part of the logger renovation, we also fixed this racing issue leveraging improved termination in Portable. Notably, the stop_object containing a pre_parent cancellation token will be passed into logger and it would close the receiving end of mpsc log channel, finish what still remains and then exits. Since it only gets cancelled when the wrapped run function returns, it’s safe to assume all send parties have finished their jobs:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
loop {
	let msg = tokio::select! {
		biased;
		msg	=	log_rx.recv()			=> {msg}
		_	=	stop.pre_parent.cancelled()	=> {return;}
	};

	let msg = match msg {
		Some(v)	=> {v}
		None	=> {return;}
	};

	log(
		msg,
		#[cfg(debug_assertions)]
		debug_fmt,
		info_fmt,
		warn_fmt,
		fatal_fmt,
	);
}

main also waits for log_task to prevent exiting early. This should fix missing log messages once and for all.

While fixing bugs is important, this new architecture may also allow us to implement internationalisation in the logging infrastructure elegantly, since changing the Display trait implementation centrally is a lot easier than doing scattered i18n translation all over the code base.

More performance oriented changes are also on the way, notably the GPU subsystem. It’s very important for us to squeeze every cycle, since Portable starts in such little time, down in the micros.