Core - Logging Improvements

Logging improvements might not sound as exciting as fancy new graphical features, but sometimes the more boring things are the most important. Keep reading to learn about the existing logger, it's current issues, and the improvements made to alleviate them.

Logging - What's already there?

It wouldn't make sense to talk about improvements to the logging in Peng Engine if you don't know what's already there, so lets go over that briefly first.

Peng Engine has a centralized logging system that allows you to create formatted logs with an API similar to printf. Adding an API for logging instead of relying on user implementations means that logs produced by the user project, the engine, or 3rd party plugins will be much more consistent. I personally find C style printf formatting to be much nicer to use than C++ stream style formatting.

An example of the log output from running Peng Pong.

Additionally, each log has an associated severity assigned to it, which is formatted in the console with different colors. The current severities supported are:

• Log
• Warning
• Error
• Success

Creating a log is then simple:

Logger::warning("HP %f is too high", _hp);

It's worth mentioning that not all consoles (such as the built in cmd) support colored text by default. Other consoles don't have this issue, such as Windows Terminal, which I highly recommend getting and configuring your machine to use by default.

An example of the log output from running Peng Pong with a terminal that doesn't support colored logs by default.

Threading

Internally, Peng Engine uses a dedicated logger thread for dumping the logs to the console. Whenever a log is performed, a job is scheduled to the worker thread via a lock-free queue. The job is then processed to format the log and print it to the console.

This comes with a few key benefits:

• Performance - logging can be quite slow due to the console flushes required to make the logs appear in real-time. This can make profiling harder if the logs skew the execution time of the parent function, and if logs are enabled in distributed builds will worsen the performance of the deliverable.
• Synchronization - if two threads try to naively log to the console at the same time, the logs can become intertwined, leaving a jumbled mess of characters on the console. Since logs are submitted to the queue as a single item, the logger thread guarantees that no logs end up intertwined with each other.

Transient Logs - Why this needs fixing

Currently, all logs in Peng Engine are transient - as soon as the program terminates, the logs are gone unless you explicitly captured the output of the console and routed it to a file. Furthermore, consoles usually have a maximum history size after which they cut-off old logs - if there's a problem causing a log spam every frame, this limit can easily be reached, making the initial (and probably more informative) logs unreachable.

This is particularly problematic when working with external testers, since their logs can be crucial for diagnosing issues they encounter. Having them route the logs to a file every time they run your project increases the friction of having them test it, especially if they're less technically inclined.

Log Files

To fix this, I've improved the logger system to automatically record logs to a log file in addition to the console. Just like the console logging, file I/O operations are performed on the logger thread, so the performance footprint should be minimal. A logfile is automatically created the first time the game attempts to log something, with the file path as shown below:

install_root/logs/YYYY-MM-DD/HH-MM-SS.log

Since the logfile name/directory is based on the timestamp of when it was created, each session of the game should produce a unique logfile. This might be a bit excessive as your logs can easily build up over time, but I thought this would be much better than only having a single logfile as it makes it much harder to accidentally wipe your logs by running the game again; additionally, it makes it easier to look at historical logs when investigating a bug that isn't new, but only recently discovered.

An example log file produced by Peng Pong.

Severity Codes

One problem with the log file is that it has no way of capturing the severity codes assigned to logs. Since the text file has no color, there is no way to see the severity of a log when reading the log file. Whilst good log messages should strive to make it obvious what their severity is, having the severity explicitly encoded into the log makes it fool proof, as well as making it far easier to look for errors/warnings while skimming through.

The workaround for this that I chose to go with was to prepend each log with a severity code.  I went with 3 letter codes over the full names of the log (such as ERR over error) for a few reasons:

• It makes the log lines less long and verbose
• It keeps the severity code the same length for all logs, meaning the log body still lines up line per line, improving readability

Below are the severity codes for all the different log severities:

[LOG] - log
[WRN] - warning
[ERR] - error
[SCS] - success

And finally, an example of the log file with severity codes included.

[LOG] Building window icon 'PengEngine(64x64)'
[LOG] Loading texture data 'resources/textures/core/peng_engine_64.png'
[LOG] Destroying window icon 'PengEngine(64x64)'
[LOG] Loading scene 'resources/scenes/demo/pong.json'
[ERR] Could not load entity '' as the type 'demo::bad_entity' does not exist
[SCS] Loaded scene 'resources/scenes/demo/pong.json'
[LOG] PengPong starting...

An extract of the log file produced by Peng Pong, now with severity codes included for each log. Severity codes aren't added in the live console logger since the colors perform the same job.

Timestamps

The next thing I wanted to add to the logger system was timestamps. Now that we have a logs recorded to a file, adding a timestamp to each log will make it easier to work out when different logs occurred when reading the log later which may come in handy for certain diagnostics or investigations.

I chose  the timestamp format [HH:MM:SS] and for now have decided to only add timestamps to the log file and not to the live logger in the console. I chose this because I didn't want to make the console log overly verbose, and since you can see the logs occurring in real-time I figured the timestamps might be less helpful.

[LOG][12:51:58] Building window icon 'PengEngine(64x64)'
[LOG][12:51:58] Loading texture data 'resources/textures/core/peng_engine_64.png'
[LOG][12:51:58] Destroying window icon 'PengEngine(64x64)'
[LOG][12:51:58] Loading scene 'resources/scenes/demo/pong.json'
[ERR][12:51:58] Could not load entity '' as the type 'demo::bad_entity' does not exist
[SCS][12:51:58] Loaded scene 'resources/scenes/demo/pong.json'
[LOG][12:51:58] PengPong starting...

An extract of the logfile produced by Peng Pong, now with both severity codes and timestamps.

Finally, I added the current frame number to the the log, changing the timestamp format to [HH:MM:SS][F] - the exact frame number can be very helpful for diagnosing behaviours that span over multiple frames, such as async operations or entity lifecycle related operations such as entity creation/destruction.

An unfortunate aspect of this format is that logs aren't always aligned, however I figured that after start-up the number of digits in the frame number should change infrequently enough that it shouldn't be too annoying. Below are some logs with the frame number added.

[LOG][21:26:29][0] Linking shader program
[LOG][21:26:29][0] Extracting uniform information
[SCS][21:26:29][0] PengPong started
[LOG][21:26:32][1480] PengEngine shutdown requested
[LOG][21:26:32][1481] PengEngine shutting down...
[LOG][21:26:32][1481] Destroying all entities

An extract of the logfile produced by Peng Pong with frame numbers, making it clear that shutdown begins the frame after it is requested.

And that's everything for now! As always, there are improvements that can be made that I'd like to experiment with in due time.

• Improved user configuration
  • There's lots of aspects about the logger that the user may want to configure differently to myself, such as whether to include timestamps in the console log, or whether the log file or console logs should be produced at all. Making these decisions configurable allows each user to customise Peng Engine for their projects preference.
• Automatically enabling colored logs
  • As I mentioned earlier, some consoles like cmd don't support colored logs by default. The Windows API provides a way enable colored logs on consoles like this, so ideally Peng Engine would attempt this before producing any logs. If the console still cant display colored logs, then the severity codes used for the log file should also be used in the console log.
• Cleaning up old logs
  • I mentioned earlier that while I definitely want Peng Engine to keep historical logs, it might be a bit overkill if they're never deleted and could end up accumulating in size. Some kind of configurable heuristic to determine when old logs should be flushed would be helpful for this.