Engine Log Output ----------------------------------------
Engine.cpp(277) : Initializing Rendering System
Renderer.cpp(135): Loaded shader "bloom"
Renderer.cpp(135): Loaded shader "blur"
Renderer.cpp(116): Can't load shader "hdr"
Renderer.cpp(170): Renderer initialized
Engine.cpp(278) : Initializing Physics System
.....
Engine.cpp(278) : Physics system failed to initialize!
Obviously you would want much more information that this, but that should give you an idea of what a simple log could look like. It's important to color-code the log because later on when the log has tens of thousands of entries, looking for specific colors can be a very quick way to get the information you need.
Let's make a quick list of features that the Qi logger should support:
- User friendly
- Threadsafe
- Automatically add information to the log about where the message came from
- Logging channels
- Per-channel event registering
- Automatically log all messages to a file in case the engine crashes
I'd like the logger to be able to work as simply as this:
Qi_LogInfo("Initializing screen size (%u x %u)", screen_width, screen_height);
Let's break down each of the points above and talk about how Qi addresses them.
User Friendly
If the logging system is complicated to use, nobody will ever, ever use it...it'll just be too much of a hassle. There are multiple way to address this. First and foremost, how is the logger accessed? Is it some kind of object stored in your engine? If so, how does somebody get to it? Does every bit of code that wants to log a message have to obtain a reference to the main engine object containing the logger?
These kinds of situations usually call for the use of a singleton. I don't really take this decision lightly as singletons introduce statics into the code which can cause issues crossing dynamic library boundaries. There are cases though where sometimes it's necessary to deal with these issues in the interest of being user friendly and I feel like this is one of them. Therefor, the Qi logger is a singleton which is accessible via a getInstance() function.
Singletons are great at solving the problem of needing a global object to access anywhere. But alone they don't fully solve the ease-of-use problem. It's cumbersome to write code like this all the time:
Logger::getInstance().logMessage("My message");
Especially later on when we add more features to the logger. This is a great case where a simple macro can come to the rescue! A macro defined in the logger header file that abstracts away the complexities of logging a message would make the system very easy to use indeed:
#define Qi_LogMessage(message) Logger::getInstance().logMessage(message);
Qi_LogMessage("My message");
Additionally, it makes the code very readable on the user side. It is very obvious after using the macro that a message is being logged. The user no longer has to worry about the fact that the logger is a singleton and therefore get access to an instance of it. In fact, the user doesn't need to know anything about how the logger is implemented at all!Finally, the user is going to want to report the values of variables within a message. Without this feature, the uses of a logging system would be pretty slim. Personally I've always liked to use printf-style syntax for parsing messages. It's an easy way to pass along all of the needed info for printing and the user likely already understands how to do this very well. Therefore, the logging function definition as well as the logging macro would have to change slightly to accommodate this:
#define Qi_LogMessage(message, ...) \
Logger::getInstance().logMessage(message, ##__VA_ARGS__);
...
void logMessage(const char *message, ...);
...
Threadsafe
One of the main features of Qi is a job-based execution model (we'll get to that in a later post). This means that any part of the engine can be executing at any time on any number of threads. The logging system is designed to be a central place where all messages are logged. For now, Qi uses a simple mutex around all log file writing to ensure that messages don't get jumbled. I expect most debug logging to be disabled at runtime so this shouldn't be much of a performance penalty. If profiling later on shows this to be an issue, using an asynchronous file writing system would alleviate this issue.
Auto-add Information to the Log
Looking at a log without any context can be just as useless as not looking at any log at all. Your user could write unhelpful messages such as "initialized system" or "loaded asset" but these messages don't really help you understand where these messages are coming from. You may note that the example log file above pre-pended a filename and a line number to each message. These can be invaluable pieces of information that help you understand where a message is coming from so that you can immediately go to the reporting code and inspect the logic. Therefore, we could modify our message logging functions to accept both a filename and a line number along with each message:
#define Qi_LogMessage(message, ...) \
Logger::getInstance().logMessage(__LINE__, __FILE__, message, ##__VA_ARGS__);
...
void logMessage(int line_number,
const char *filename,
const char *message, ...);
...
Logging Channels
The simple logger we've created so far will go a long way in helping to understand the flow of events in the engine. However, it can be nice to classify the "type" of message being logged so that we can perform some more advanced operations. Types could include things like information, debug, warnings, errors, etc. Each goes into it's own "channel" which the user can decide to turn on and off or subscribe to. Additionally, different channels can have either different output files or different color codes within the main log file. For example, let's say a user wants to only get error messages. Everything except the error channel in the logger could be disabled, effectively filtering out the unwanted messages.
A simple channel system should start with a per-channel identifier. I've elected to use a simple enum:
enum Channel
{
kInfo,
kDebug,
kWarning,
kError,
...
};
void logMessage(Channel channel,
int line_number,
const char *filename,
const char *message, ...);
The logMessage() function would make a check against the currently enabled channels and respond with the message accordingly. Assuming this message should be reported, a color table can be used to lookup the proper coloring to use for the message output.
To make life easier on the user, we could now define several macros for logging (one per channel) instead of the singular macro we had before:
#define Qi_LogInfo(message, ...) \
Logger::getInstance().logMessage(Qi::Logger::kInfo, \
__LINE__, \
__FILE__, \
message, \
##__VA_ARGS__);
#define Qi_LogWarning(message, ...) \
Logger::getInstance().logMessage(Qi::Logger::kWarning, \
__LINE__, \
__FILE__, \
message, \
##__VA_ARGS__);
...
Channels can be a little less narrow as well. Perhaps you want a channel dedicated to just the rendering system. Seeing only messages logged by the rendering system can be helpful when trying to track down a specific bug.
Per-channel Event Registering
In a previous post I briefly mentioned FastDelegates and their use-cases. We can use them here to allow any system in Qi to get messages and deal with them as they see fit. This situation can arise in the case where the engine is being used inside of an editor where all warnings and errors need to be quickly reported to a user. Additionally, a game may want to use an in-game console which reports the current status of messages in the system. Therefore, an easy registering system which can call into any registered object would address this need. Any object could declare a delegate and register it with the logger.
Qi supports registering for messages per channel. That way, an object would only get invoked with messages it cares about and ignore all others. Pseudo-code for message logging could look like this:
if (channel is enabled by filter)
colorCodeMessage(message, channel)
foreach channelHandler
foreach channelHandler
invokeHandler(message)
Automatically Log All Messages to a File
This might not sound like such a big deal but if you don't log your messages to a file, how will you trace event flow offline? What happens if the engine crashes? How do you remotely debug a user's problem? Mirroring all messages to a log file is a great way to track down any unexpected issues.
Qi mirrors all messages to an engine-controlled file. The message is always written regardless of the current channel filter in order to preserve an accurate history of engine events. The file is written with color-encoding (currently ascii colors) based on the specific channel being logged to. Upon logging each message, the log file is flushed to ensure that the data is written. If you don't do this, the engine may crash causing you to lose valuable information that's still sitting in buffered memory.
Flushing the buffer for each file write can become costly on performance yet is sometimes necessary when debugging crashes. Therefore, Qi allows the user to determine which behavior they want via the engine configuration object (more on this later).
Flushing the buffer for each file write can become costly on performance yet is sometimes necessary when debugging crashes. Therefore, Qi allows the user to determine which behavior they want via the engine configuration object (more on this later).
-----------
This should give you a good overview of the logging system implemented by Qi, maybe even some ideas to implement your own :) You can take a look at the latest source for Qi's logging system here.
No comments:
Post a Comment