Avoiding the Logging Performance Hit

Sometimes you have a function or a method which more often throws away its arguments than actually uses them. Quite possibly the most common example of this situation is logging. Often you'll see a snippet like this:

log.Debug("Processing " + index + " of " + count);

It's just the way things are that debug log statements are used more liberally than error statements. Even if log.debug(...) doesn't actually log it's argument, your program will still pay the penalty of doing the string concatenation continuously. As a result many programmers are forced to write code that looks like this:

if (log.IsDebug()
{
    log.Debug("Processing " + index + " of " + count);
}

Now the internal state of the logger must be examined externally for every debug statement. D solves this issue through lazily evaluated functional arguments. In D you can change the signature of your function to look like this:

void Debug(lazy char[] entry)
{
   if (debug)
     fwritefln(logfile, entry());
}

This is really just syntactic sugar around D's delegate parameters in which you can pass a function as an argument. The end result, though, is that the statement that composed the argument won't be evaluated until it is actually used.

Titanium and Kroll are written in C++ though, which doesn't have the same kind of syntactic niceties that D does. Recently, when putting the first bits of the logging system into Kroll, I decided that I wasn't satisfied with the Java-style debugging which I wrote above. I wanted to fully encapsulate the behavior of the logger and avoid paying the penalty of uneeded string processing. One common approach for C/C++ is to use macros, but as Walter Bright explains in his essay on lazy argument evaluation, this isn't the best solution.

Luckily, C and C++ have variadic arguments which allow us to create both easy-to-read logging code and to avoid paying a penalty for those statements which should essentially be no-ops. I harnessed the power of a seldom-used friend from the C library for this task: vsnprintf. vsnprintf operates much like snprintf, except that instead of taking a variable list of arguments it takes a va_list (basically a variadic list of arguments that can be passed forward to other functions). Here is the resulting code from Kroll:

  std::string Logger::Format(const char* format, va_list args)
  {
    // Protect the buffer
    Poco::Mutex::ScopedLock lock(this->mutex);
 
    vsnprintf(Logger::buffer, LOGGER_MAX_ENTRY_SIZE - 1, format, args);
    Logger::buffer[LOGGER_MAX_ENTRY_SIZE - 1] = '\0';
    std::string text = buffer;
    return text;
  }

  void Logger::Log(Level level, const char* format, va_list args)
  {
    Poco::Logger& loggerImpl = Poco::Logger::get(name);
 
    // Don't do formatting when this logger filters the message.
    // This prevents unecessary string manipulation.
    if (level >= (Level) loggerImpl.getLevel())
    {
      std::string messageText = Logger::Format(format, args);
      this->Log(level, messageText);
    }
  }

  void Logger::Debug(const char* format, ...)
  {
    va_list args;
    va_start(args, format);
    this->Log(LDEBUG, format, args);
  }

A typical logging statement looks like this:

log.Debug("Processing %i of %i", index, count);