Pandemonium

September 19, 2010

Efficient Development – part five

Filed under: Games Development — bittermanandy @ 6:27 pm

So, as promised: a more positive post, and this one also offers something more concrete than recent posts have tended towards: another component in the Kensei.Dev library, about which I have written before.

I recently found myself needing to add logging to Pandemonium, to aid with debugging. The idea of logging is to write text to the output window and/or a file, to explain what the code is doing. It is then possible the examine the logs to see what happened and when, to identify for example why something went wrong. .NET provides Diagnostics.Trace but it is somewhat limited in scope, so a more powerful logging framework can offer much more control over what is logged.

Initially I planned to create my own logging framework from the ground up, but I suspected that I would merely be repeating what is already available – and indeed about five seconds on Google pointed me in the direction of this. DotNetLog (also known as BitFactory.Logging, also known as Termite) is quite an elegant framework: you can send output to any number of loggers of which there are many different types, and each can be formatted individually. It costs $5 but that’s almost as good as being free, so I wasn’t too concerned by that.

If there is one unfortunate restriction to DotNetLog, it is that it doesn’t work on Xbox 360 (you may have gathered I’m not at all bothered about Windows Phone 7) as it isn’t consciously intended for XNA games. Therefore, I decided that rather than litter my code with references to BitFactory.Logger (all surrounded with #if WINDOWS) I would create a Kensei.Dev.Logger static class, which would be the only area of code that would refer to BitFactory at all. There are a number of other advantages to such a facade, such as those mentioned here (an article from which I borrowed a number of ideas).

Within just a few minutes Kensei.Dev.Logger was up and running, and sending log output to both the console (visible in the Output window in Visual Studio), for monitoring while the game is running, and a file, for analysis later. Generally of course, the console logging would be disabled in your Release build, and file logging would also be disabled but with the option of being enabled via a command line switch, so if your players are having technical problems you can tell them to enable logging, play the game until the problem occurs, then send you the logs.

So far so ordinary – nothing new as of yet. But I had a few further ideas of how this logging framework could be extended to be more useful.

FrameCount and LocalFrameCount

By default, DotNetLog writes out each log entry in a format similar to the following:

[Pandemonium] -- {Kensei} --<Info> -- 19/09/2010 17:13:44 -- Initialised logger.

That’s the application name, followed by the log category, then the log level, then the time of the log entry, and finally the actual log message itself. It’s really easy to write a Formatter of your own (derived from BitFactory.LogEntryFormatter) to display this in a more pleasing format, but what really bugged me was that the time shown just isn’t very useful. A Windows service might want to know the date and time to the nearest second, but for a game such information is simply not very helpful. It would usually be much more useful to track the number of frames since the game was started (or the most recent level change) and log that, instead of the time.

Initially it seemed there was no way to do this, but a quick email to the framework’s authors (and an equally quick reply) showed the way forward. First, I had to define my own FrameBasedLogEntry type, derived from LogEntry:

private class FrameBasedLogEntry : LogEntry

{

    // Constructors not shown

    public uint FrameCount { get; set; }

    public uint LocalFrameCount { get; set; }

}

Then, I had to create my own Logger and override the function that normally created a LogEntry, getting it to create a FrameBasedLogEntry instead, filling in the FrameCount and LocalFrameCount values (with the total number of frames since the game started, and the number of frames since the last level change, respectively).

private class FrameBasedCompositeLogger : CompositeLogger

{

    protected override LogEntry CreateLogEntry

        ( LogSeverity aSeverity, object aCategory, object anObject )

    {

        return new FrameBasedLogEntry(

            aSeverity, Application, aCategory, anObject.ToString(),

            Logger.FrameCount, Logger.LocalFrameCount );

    }

}

Finally, I had to create my own FrameBasedLogEntryFormatter derived from LogEntryFormatter, and tell the various Loggers I was using, to use it for formatting.

private class FrameBasedLogEntryFormatter : LogEntryFormatter

{

    protected override string AsString( LogEntry aLogEntry )

    {

        FrameBasedLogEntry frameLogEntry = aLogEntry as FrameBasedLogEntry;

 

        if ( frameLogEntry != null )

        {

            return String.Format( “[{0}/{1}] [{2}] [{3}] {4}”,

                frameLogEntry.FrameCount,

                frameLogEntry.LocalFrameCount,

                frameLogEntry.SeverityString,

                frameLogEntry.Category ?? “”,

                frameLogEntry.Message ?? “” );

        }

        else

        {

            return String.Format( “{0} – [{1}] [{2}] {3}”,

                aLogEntry.Date.ToShortTimeString(),

                aLogEntry.SeverityString,

                aLogEntry.Category ?? “”,

                aLogEntry.Message ?? “” );

        }

    }

}

Easy! Now all log entries were formatted with the frame count instead of the time, something like as follows:

[47563/1489] [Info] [Kensei] Silver star 42 collected.

LoggerForm

The really clever bit was still to come. You may remember from my earlier discussion of Kensei.Dev.Options and Kensei.Dev.Command that these components offer dialog boxes, so that changing an option is as simple as clicking a checkbox, and entering a command simply involves typing it and hitting Return – all while minimally affecting the game itself. I wanted to do the same for Kensei.Dev.Logger, and furthermore to easily allow the option to disable certain categories from displaying in the logger at all (so you know if the bug you are looking for is in your audio code, for example, you can disable all logging except from the “Audio” category).

You can view my code later to see exactly how I built up the form (using the standard form designer as a basis, of course) but the interesting part was to create a new DialogBoxLogger type, derived from BitFactory.Logging.Logger. Instead of overriding the WriteToLog function, which would only allow me to modify a preformatted string, I overrode the DoLog function, to enable me to work with the LogEntry object itself (really of course a FrameBasedLogEntry). This sent the LogEntry to the form, where I was able to use the Category information to populate a CheckedListBox, and only output the log entry if the corresponding category was checked; and also to change the colour of the log entry to make errors more obvious.
 The Logger dialog shows all logging and allows different categories to be enabled.

I confess, some of the above logging is not completely genuine; but hopefully this screenshot is enough to demonstrate what a powerful and clever tool this is. The whole time I’m debugging my game, I can have the logger dialog running alongside it so I can see exactly what is happening in the game at any one moment. At the same time, logging is still being routed to a log file in the executable folder, so if everything falls apart I can go back and work out what went wrong at my leisure:

[0/0] [Info] [Kensei] Starting LegendsOfXaerolyte version 1.0.0.0 at 19/09/2010 17:50:56.
[0/0] [Info] [Xaerolyte] Hello!
[987/987] [Info] [Kensei] New severity threshold: Debug
[2872/2872] [Debug] [Kensei] Beginning writing Pandemonium blog
[4129/4129] [Debug] [Kensei] Adding links to blog
[6359/6359] [Info] [Pandemonium] Loading game
[8124/8124] [Info] [Pandemonium] Changing level: The River Styx
[8688/8688] [Info] [Kensei] CommandResetLocalFrameCount
[8688/8688] [Info] [Kensei] Resetting local frame count at 19/09/2010 17:53:24
[10315/1627] [Info] [Pandemonium] Loaded level The River Styx
[12559/3871] [Error] [Audio] No sounds available!
[14088/5400] [Info] [AI] Calculating pi...
[18000/9312] [Info] [AI] Calculated pi to three trillion decimal places. Result: 3.14159265358979323846264338327950288419716939937510 ...
[21484/12796] [Debug] [Physics] Player bounced off rock

One possible improvement to the Dev Logger dialog would be to use a tab control, and enable different combinations of categories (and levels) on each tab. Thus you could have the first tab showing all normal logging, the second showing only the “AI” category but including verbose (Debug) logging, the third showing only errors from all categories, and so forth. I chose not to do that at this time, though may come back to it later.

Conclusion

It should be pretty obvious what a useful feature logging is. The DotNetLog logging framework is not only complete in its own right, and easy to wrap in a facade, it is also easily extensible and deliberately structured in such a way that users (eg. me!) can use it in ways that the original authors never expected. Judicious use of inheritance allowed me to take the framework and remould it in a way more appropriate for me, without needing (or indeed, being able) to rebuild the assembly itself.

I make Logger.cs available for download for you to do with as you will, in fact, you can officially do what the fuck you want with it. If you downloaded the rest of the Kensei.Dev code I made available previously it should fit right in with minimal effort (I have tweaked Kensei.Dev a bit since then, but not in any major way as far as I can recall); if not, it should be fairly simple to strip out the references to other Kensei.Dev components and/or replace them with your own equivalents as you see fit. Enjoy, and as always, please leave a comment if you have any feedback, questions or suggestions!

About these ads

3 Comments »

  1. Hi Andy, nice post. Good to have you back! :-)

    Comment by Kostas — September 20, 2010 @ 6:15 pm | Reply

  2. Hi Andy,

    I absolutely love your blog, it has been quite some time between posts. What have you been up to?? Are you still working on your XNA project?

    Please, post more!

    From, a friendly developer.

    Comment by bostelk — December 15, 2010 @ 6:06 pm | Reply

    • Yes, it’s been a while… the blog is sleeping but not dead, one day it will reawaken. I am still dabbling with XNA but it’s multiple projects, not just one project – which is a bit of a problem because none of them are getting finished. One day! One day…

      Comment by bittermanandy — December 15, 2010 @ 7:26 pm | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

The Rubric Theme Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: