Sign in to follow this  
Zerox Millienium

Logging and debugging without performance impact

Recommended Posts

I would like to know if there are tips to good practices when it concerns logging and debugging when writing a program. What sort of performance impact will it have on a program if I created and used classes that provides logging and debugging facilities. Such as displaying some output in the output window of Visual Studio and logging messages to a file?

Share this post


Link to post
Share on other sites
ToohrVyk    1596
My main tip would be to use a debugger when debugging, instead of a debugging class. I would use a log for non-buggy output (such as notifying the user of errors encountered that were due to the user's computer, and not the program). Typically, I would output everything to std::clog, and if necessary provide an option to redirect std::clog to a file.

Share this post


Link to post
Share on other sites
Telastyn    3777
As with pretty much all performance questions, don't worry about it. Make the program work, then make it fast. Clear, pervasive debugging info will only help you getting the program to work.

Share this post


Link to post
Share on other sites
Excors    715
Quote:
displaying some output in the output window of Visual Studio
My experience is that VS2005's output window (as used by OutputDebugString) is incredibly slow, to an extent that is hard to comprehend; so don't use it for any per-frame logging.

Share this post


Link to post
Share on other sites
scottdewald    163
Create a threaded logger class. When you initialize it, it creates a helper thread that performs all the logging. When you call its log function, it simply adds the log string to the logging queue, signals the logging thread, and returns to the function that called it. The logging thread logs the output using std::clog or anything you want.

This will offload the performance hit of writing to disk to another thread so your performance critical threads can still write debug statements.

Share this post


Link to post
Share on other sites
Guest Anonymous Poster   
Guest Anonymous Poster
To one up on scottdewald's idea, make the class with some static data members (files you can write too if you need more then one, current logging levels, etc if you need those). Then write the class. Then write global Log(..) functions in a namespace that just reference the class for you. So you don't have any...

Logger Log;
Log.Write(...);

Or worse (singleton...):

Log::Get().Write(...);

Just nice simple:

Log(...);

It's easier to use, so you will use it. The threaded idea is great and even with limited knowledge of threads, quick to implement.

Share this post


Link to post
Share on other sites
ApochPiQ    23061
Don't worry about fast logging. Worry about logging you can turn off, preferably at compile time. For example:

void Log(const char* line)
{
#ifdef LOGOUTPUT_ENABLED
// ...
#endif
}

Log("foo");



When making a release build/performance-critical build, just don't specify LOGOUTPUT_ENABLED, and the compiler will automatically strip any calls to Log() since it is a no-op (assuming you have optimizations turned on).

In general, any logging system will have some performance overhead at some point. What you need is a strategy for coping with that overhead, not a way to make it disappear.

Another good option is the use of debug masks, where you have a bitmask that controls what output is logged. For example:

enum LogBitmask
{
Log_Graphics = 0x001,
Log_Audio = 0x002,
Log_Input = 0x004,
Log_Whatever = 0x008,
};

void Log(LogBitmask mask, const char* line)
{
#ifdef LOGOUTPUT_ENABLED
if(LogFilterSetting & mask)
{
// ...
}
#endif
}

// In various places in code
Log(Log_Graphics, "foo from graphics code");
Log(Log_Audio, "foo from audio code");
Log(Log_Input, "foo from input code");


Then you just change the value of the LogFilterSetting variable to control what is actually output to the logs. If you clear the bit that corresponds to Log_Graphics, for instance, no calls that specify Log_Graphics as the filter mask will have any effect. You can obviously tweak the bitmask logic a little bit to get specific semantics, but that's the overall principle. A function call and if() will be much less overhead than, say, file I/O or OutputDebugString.

Share this post


Link to post
Share on other sites
Bregma    9214
You have to pay for what you use. You cannot avoind a performance hit when you log stuff or debug stuff.

If you use a separate logger thread as discussed above, you're taking advantage of asynchronous I/O and you can adjust thread priorities to try to minimize impact, but thread synchronization also has a price and the context switching requirements don't disappear, they just get a lower priority on the logging thread.

No, just prepare to pay the cost and swallow it.

You can disable the use of the logging output fairly simply at runtime by having a variable you check before performing output. Like the following, for example.

if (gDebug) clog << logLevel(kLOG_WARNING) << logFacility("AI") << "actor has wandered out of bounds << actor->dump() << '\n';

If the global gDebug variable is not set, absolutely none of the following line is executed. Zero runtime cost if you've not enabled debugging at runtime. Not only that but you can read the above code and know exactly what it's doing: if debugging is enabled, it's logging a message at a certain log level marked for a certain facility and dumping some object.

Ok, you say, you want to disable this debug logging at compile time. Well, this is your lucky day. You don't need to change a thing. See, any modern compiler wriiten since the beginning of the centure has this cool optimization feature in which it will remoce unreachable code. So, all you need to do is set the global variable to false. No need for nasty preprocessor commands riddled through your code like mould through the cheese at the back of your fridge. The code you test in your debug build is the code you test in your release build. Um, yeah, you'll probably need an ifdef at the gDebug definition. The rest of your code, though, is what-you-see-is-what-you-get.

--smw

Share this post


Link to post
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now

Sign in to follow this