Lazy Logging Parameter Evaluation With Variadic Macros

This entry is not rocket science, and probably won't be that informative to experienced programmers, but I've seen commercial code bases get something as simple as this wrong. It requires compiler support for variadic macros, which have been in Visual C++ for a while and are also supported by later versions of GCC.  

Most games have some sort of logging system. Debugging by printf is one of the first debugging tools most programmers learn. While there are many other tools in the debugging toolbox, this particular one is usually not that far out of reach. Some problems just lend themselves to being solved by logging.

We want to minimize the performance impact of logging code, without having to limit the number of logging statements we place in code. We do not want to constantly recompile different configurations of the game with or without logging enabled. While compile time stripping of logging during development will have the least performance impact, there are many times when you may be at a tester, designer or artist's desk and need to log key information. Providing them with a custom build is a productivity hit for everyone involved. 

There are two main performance hits for logging:

1. The cost of the logging itself (writing to the debug window, to a file, to a console, etc)

2. The cost of parameter evaluation

Anyone who has put a log statement in a piece of code executed many times a frame knows it can absolutely kill performance, just by the fact that logging to a file or debug output can be time consuming itself. This first cost can be solved by a channel system that can selectively enable logging. Even beyond the performance cost, it is useful to enable different types of logging at different times. If you're debugging AI code, you are probably not interested in logging from the streaming system.  Log statements specify which channel they are on (say, by integer ID), and the logging code checks if that channel is enabled.

Where should this check occur? I've seen some code bases that do this in the logging function itself. This is a mistake, because even if you do not actually output anything, you are still paying the second cost, the cost of parameter evaluation.

Logging, by nature, is very string-intensive. Often you will output human-readable debug names for various assets and entities when logging. Strings computed as parameters to log statements often incur performance penalties - memory allocations, string operations, etc. In addition to string overhead, some information you may wish to log may not be particularly cheap to calculate.

float ThisFunctionIsVeryExpensiveToEvaluate()

LogPrintf(LOG_INFO, "Expensive but precious debug info: %g\n", ThisFunctionIsVeryExpensiveToEvaluate());

What we want is for the expensive function to only be evaluated if the LOG_INFO channel is enabled.

The way to do this is to put the channel check in the macro itself, and only call the log function if the check succeeds. Here's some sample code that accomplishes this using variadic macros:


// Define this to 0 to disable logging
#define ENABLE_LOGGING 1

const int LOG_ERROR=0x1;
const int LOG_WARNING=0x2;
const int LOG_INFO=0x4;

#if ENABLE_LOGGING
   // Simple channel system (you want IsLoggingChannelEnabled to be cheap,
   // but there are other ways to implement something like this)
   static int GlobalEnabledLogChannels;

   // Make sure your compiler inlines this function, as it will be called many
   // times
   // You may want to force it to be inlined using whatever compiler-specific
   // syntax is available to you.
   inline bool IsLoggingChannelEnabled(int channel)
   {
       return 0 != (GlobalEnabledLogChannels & channel);
   }

   // This overload is present to handle the case where the channel argument
   // is optional
   inline bool IsLoggingChannelEnabled(const char*)
   {
       return true;
   }

   // Note: I've seen many logging systems which make the log channel optional.
   // I'm going to handle this case to show how it is done, but if you always
   // require a log channel, this code becomes simpler (for instance, you can
   // make format a required argument to the macro, and not need the ## handling)
   void MyLogPrintf(const char* format, ...);
   void MyLogPrintf(int channel, const char * format,...);

   // The ## is some syntax magic to make GCC ignore the preceding
   // comma if no arguments after channel are present
   // This can happen if no channel is specified in the log print, as it is optional
   #define LogPrintf(channel, ...) \
      if(!IsLoggingChannelEnabled(channel)) {} else MyLogPrintf(channel, ##__VA_ARGS__)


#else

   #if _MSC_VER
      // __noop is Visual C++ specific syntax for "do nothing".
      #define LogPrintf(...) __noop
   #else
      // Compiler should strip this out - but always look at the disassembly to make sure!      inline void Noop()
     {
     }

      #define LogPrintf(...) Noop()
   #endif

#endif

// example log statements
void SomeFunction()
{
    LogPrintf("Hello world!\n");
    LogPrintf(LOG_ERROR, "You should see this very important error\n");
    LogPrintf(LOG_INFO, "Expensive info: %s\n",
    ThisFunctionIsVeryExpensiveToEvaluate().c_str());
}

Hopefully blogger didn't mangle the formatting of all that.

The key concept is to call IsLoggingChannelEnabled() in the macro itself. The if syntax it uses is specially constructed -- done this way it will not change the semantics of an if statement without braces. For example:

if (rand()%2 == 0)
    LogPrintf(LOG_INFO,"Rand was even\n");
else
    LogPrintf(LOG_INFO, "Rand was odd\n");

If we did something like this:

#define LogPrintf(channel, ...) \
if(IsLoggingChannelEnabled(channel)) MyLogPrintf(channel, ##__VA_ARGS__)

that would change the meaning of the above if statement, and the else case would be on if(IsLoggingChannelEnabled(channel)), not the original rand check!

A note on why I made the channel optional: In a particular legacy code base I was dealing with, the channel argument was optional on logging statements, and I had to handle that case without changing every log statement in the application. I wanted to show how you could support something like that.

The main drawback with this approach is an increase in executable size due to all the log channel checks being inlined and the performance hit of the check itself on each log statement. It really depends on your particular game whether you are willing to pay these costs in your development/in-house build or not.