Handling verbose output efficiently with Godot

By cyberpuffin, 30 June, 2023

Update 04 August 2023

The code presented in the first iteration of this post led to orphaned nodes that weren't being cleaned up properly.  The code has been updated to free the Log nodes appropriately and comments have been updated for auto documentation.

Message queue as an Array

As discussed in the 20230621 dev log Accessible Sudoku uses a messages Array to store and forward the messages to console, whether the one built into the IDE or the in-game console.  Using an Array incurs a re-index penalty when messages are removed.

Messages using array diagram.

Under normal operation, and with a low verbosity setting, this is fine as the message Array buffers the messages and the timer sends them.

It becomes a problem when the verbosity is set too high, developing on a low-resource machine (like a steamdeck), and for long-running tasks (most things to do in the generator).

Linked List

A Linked List is a data structure where each node contains some data and a link to the next node in the list.  Since the data doesn't need to be in a contiguous block of memory, as each node knows where to find the next, there's no re-index penalty.

You got some logging in my global class

For some time now the logging functions have been held in the Global autoload / singleton.  Why?  yes.

Time for a dedicated logger singleton with an inner class for message nodes.

Log.gd singleton

First step is to move all the logging functions and components from Global.gd to the new singleton.  Once complete, adjust all calls like Global.debug("foobar") to Log.debug("foobar").

This makes more sense and aids in maintainability of the code.  Nothing worse than cursing the last dev's sloppy work only to find out it was you.

cyberpuffin@workstation:~/git/godot-sudoku$ grep -R -e 'Global.debug' -e 'Global.verbose' -e 'Global.silly' Scripts/ | wc -l
383

That's a lot of manual edits.  Let's make it a little easier:

cyberpuffin@workstation:~/git/godot-sudoku$ find Scripts/ -iname '*.gd' -exec sed -i -e 's|Global.debug|Log.debug|g' '{}' \;
cyberpuffin@workstation:~/git/godot-sudoku$ grep -R -e 'Global.debug' -e 'Global.verbose' -e 'Global.silly' Scripts/ | wc -l
298
cyberpuffin@workstation:~/git/godot-sudoku$ find Scripts/ -iname '*.gd' -exec sed -i -e 's|Global.verbose|Log.verbose|g' '{}' \;
cyberpuffin@workstation:~/git/godot-sudoku$ find Scripts/ -iname '*.gd' -exec sed -i -e 's|Global.silly|Log.silly|g' '{}' \;
cyberpuffin@workstation:~/git/godot-sudoku$ grep -R -e 'Global.debug' -e 'Global.verbose' -e 'Global.silly' Scripts/ | wc -l
0

Followed by a bit of whack-a-bug with the editor and the debugger finding other pieces that have moved, like Global.error() and Global.message_timer.

Comparing implementations

The issues presented by the old implementation of logging mostly came up in edge cases and with the generator which is still pending conversion to Godot 4.x.

For now, the old code will remain along side the new code and a switch will be added into options to allow for A/B testing.

Linked list: Log.gd

extends Node
## Log
##
## Manage output messages to the user or developer.[br]
## Autoload: 1

## Timer interval for sending messages
const OUTPUT_MIN_INTERVAL: float = 0.075

## Verbosity levels
enum VerbosityLevel {
	Quiet, ## Vital messages only
	Verbose, ## Some system messages
	Debug, ## More messages
	Silly ## All the messages
}

## Timer to send messages on interval
var message_timer: Timer
## Reference to first log message in the list
var msg_first: LogMessage
## Reference to last log message in the list
var msg_last: LogMessage

## Last steps
func _exit_tree() -> void:
	Log.clear_message_queue()
	
	return

## First steps
func _ready() -> void:
	Log.configure_timer()

	return

## Add new messages to the Log queue
func add_msg_to_queue(msg: String = "blank") -> void:
	if msg == "blank":
		Log.error("%s: Can't add blank message to log queue." % [
			"Log: add_msg_to_queue"
		])
		return

	var new_log: LogMessage = LogMessage.new(msg)

	if Log.msg_first:
		Log.msg_last.set_next(new_log)
		Log.msg_last = new_log
	else: # empty queue
		Log.msg_first = new_log
		Log.msg_last = new_log

	return

## Clear the message queue without waiting for the timeout
func clear_message_queue() -> void:
	while Log.msg_first:
		Log.send_message()
	Log.verbose("Message queue cleared.")
	
	return

## Configure the Log message timer
func configure_timer() -> void:
	Log.message_timer = Timer.new()
	Log.message_timer.name = "Message interval"
	add_child(Log.message_timer)
	Log.message_timer.autostart = true
	Log.message_timer.one_shot = false
	Log.message_timer.paused = false
	Log.message_timer.wait_time = Log.OUTPUT_MIN_INTERVAL
	Log.message_timer.start()
	Log.message_timer.connect("timeout", Callable(Log, "send_message"))

	return

## Debug messages
func debug(msg: String):
	if !Config.verbosity:
		msg = "%s: %s" % ["deferred", msg]
		call_deferred("debug", msg)
	elif Config.verbosity >= Log.VerbosityLevel.Debug:
		Log.add_msg_to_queue(msg)
		
	return

## Error messages send regardless of verbosity
func error(msg: String):
	Log.add_msg_to_queue(msg)
	push_error(msg)
	
	return
	
## Non-error messages to send regardless of verbosity
func quiet(msg: String) -> void:
	Log.add_msg_to_queue(msg)

	return

## Send message from queue at timer timeout
func send_message() -> void:
	if !Log.msg_first:
		return

	print(Log.msg_first.message)
	if Config.show_console:
		Global.console.insert_text_at_caret("%s\n" % Log.msg_first.message)
		Global.console.scroll_vertical = INF

	Log.msg_first.queue_free()
	Log.msg_first = Log.msg_first.next_msg

	return

## Silly messages
func silly(msg: String) -> void:
	if !Config.verbosity:
		msg = "%s: %s" % ["deferred", msg]
		call_deferred("silly", msg)
	elif Config.verbosity >= Log.VerbosityLevel.Silly:
		Log.add_msg_to_queue(msg)
		
	return

## Verbose messages
func verbose(msg: String) -> void:
	if !Config.verbosity:
		msg = "%s: %s" % ["deferred", msg]
		call_deferred("verbose", msg)
	elif Config.verbosity >= Log.VerbosityLevel.Verbose:
		Log.add_msg_to_queue(msg)
		
	return

## Log Message node
##
## Nodes in a linked list that carry log messages
class LogMessage:
	extends Node

	## Message data to send to output
	var message: String
	## Link to next message in list
	var next_msg: LogMessage

	## Store message data
	func _init(msg: String = "blank") -> void:
		if msg == "blank":
			Log.error("%s: Can't create empty Log Messages." % [
				"Log: LogMessage: _init"
			])
		else:
			self.message = msg
		self.name = "Log Message"
		
		return

	## Set link to next message in list.
	func set_next(next: LogMessage) -> void:
		if self.next_msg:
			push_error("Next message is already set.")
			return

		self.next_msg = next
		
		return

Here's the final script with the Linked List implementation.  Whether it works where the Array-based message queue failed is yet to be seen.

Reference

Versions

Godot: 4.0.2

Technology
Godot

Comments