Archive | Debug Tools RSS for this section

In Game Logging System

I wrote this code not to long ago in C++.  I am using it in a game project I am working on where I want to be able to log information in both Debug and Release mode.  I got this idea looking at the Windows Event Viewer and noticed under applications everything has 3 flags, Error, Warning, Information.  Errors will output what went wrong at the time of the application crash.  Warnings will display something that could become an error. Information is everything else and it fills up the event viewer.  At this time I was also reading ‘Game Engine Architecture’ by Jason Gregory which is a fantastic book.  I was reading about all of the debugging tools Naughty Dog uses in their engine, which leads me to the logging system.

I wanted to make a system that could meet these requirements:

  • Output information in Debug and Release mode
  • Output any remaining information in the event of a crash
  • Simple easy to use interface for other Developers on the team
  • No performance hit
  • Output to a file that can be easily read

This is the system I came up with:

class Logger
{
public:
enum Sevarity
{
LOG_ERROR,
LOG_WARNING,
LOG_INFORMATION,
LOG_INPUT,
LOG_SOUND
};

~Logger(void);

void Log(std::string str, Sevarity s);
static Logger* GetInstance(void);

void Initialize(void);
void Update(float deltaTime);

private:
Logger(void);

ThreadData* td;
CRITICAL_SECTION crit;
HANDLE exitEvent;
HANDLE thread;
std::list outputBuffer;
bool active;

static Logger* logInstance;
};

As you can see the system is very simple.  Every thing that needs to be logged will go through the Log function.  You might notice LOG_INPUT and LOG_SOUND, these were added after I created the system and put it into the engine.  The rest of the class if self explanatory.  One of the important things I should go over is the use of threads in this system.  The way the system works is a thread is running which is responsible for writing to a file and that is all it does.  When the Log function gets called it just buffers the output, when the thread awakens it will check this buffer and copy it over to its own memory, that way it wont hold up any functions with a Critical Section.  After it has completed the copy it will begin working on writing out to a file.  When this is completed it will go back to sleep for a specified amount of time.  In the event of a crash or exit it will grab all of the contents of the buffer, write it out to the file, then clean up any loose ends. Here is the function:

/******************************************************************************/
/*!
\author David James

\brief
Thread function that will be used to process logging events

\param data
Typical data that is passed to the thread, in this case ThreadData type

\return
Return state of the thread
*/
/******************************************************************************/
DWORD WINAPI LogThread(void* data)
{
ThreadData* td = reinterpret_cast<ThreadData*>(data);
std::ofstream fileOut;
std::ostringstream filename;
SYSTEMTIME time;
GetLocalTime(&time);

std::list threadList;

filename << "LogFiles\\" << "Log_" << time.wHour << '-' << time.wMinute << ".csv";
fileOut.open(filename.str());

if(fileOut.good())
{
fileOut << "Time Stamp, Severity, String" << std::endl; while(WaitForSingleObject(td->exitEvent, 0) != WAIT_OBJECT_0)
{
EnterCriticalSection(&(*td->crit));
// Copy what is waiting in the buffer to memory the thread can use
//
threadList = *td->output;
td->output->clear();
LeaveCriticalSection(&(*td->crit));

// Write everything in CSV format
//
for(std::list::iterator it = threadList.begin(); it != threadList.end(); ++it)
{
fileOut << (*it).time.wHour << ':' << (*it).time.wMinute << ':' << (*it).time.wSecond << ':' << (*it).time.wMilliseconds << ',' << (*it).severity << ','<< (*it).str << std::endl; }
// Wait 1 second before next write
//
Sleep(1 * 1000);
}
// This code is called in the event of a crash or exit of the application
//
EnterCriticalSection(&(*td->crit));

// Writes everything remaining in buffer
//
for(std::list::iterator it = td->output->begin(); it != td->output->end(); ++it)
{
SYSTEMTIME time;
GetLocalTime(&time);
fileOut << time.wHour << ':' << time.wMinute << ':' << time.wSecond << ':' << time.wMilliseconds << ',' << (*it).severity << ',' << (*it).str << std::endl; } td->output->clear();

LeaveCriticalSection(&(*td->crit));
}
else
{
DebugBreak();                                                               // File failed to open
}

fileOut.close();

return 0;
}

I output this using the .csv file format, this way I can use the tools provided by Microsoft Excel to filter data, after all when the files are done writing some of them can have thousands of lines of information and 3 lines of errors. When all I care about is the error messages and where it broke. You may notice in the code GOLDEN_BITS, this is a define I have set up in Visual Studio. The Golden build mode is when we are ready to ship we will compile in this mode which, provided all of the other devs have been using them, will remove all of the debug and logging calls.

The rest of the Logger is fairly straight forward to implement.  Post in the comments below if you have any questions I would be happy to answer them.

Adam Estela Programming Bliss

TheMeaningOfLifeIs(){ return The MeaningOfLifeIs(); }

David James Coding Blog

Coding, Simple as that

WordPress.com News

The latest news on WordPress.com and the WordPress community.