Logging In C++

A Little Trick

So far, the framework has shown good returns on only minor investments: It offers some nice formatting rules (the tabs according with the logging level and final std::endl) in a small, easy-to-use package. However, the current Log has an efficiency problem: If the logging level is set to actually do nothing, Log accumulates the data internally—just to notice later, during destruction, that no output is required! This single issue is big enough to be a showstopper against Log's use in a production system.

You can use a little trick that makes the code, when logging is not necessary, almost as fast as the code with no logging at all. Logging will have a cost only if it actually produces output; otherwise, the cost is low (and actually immeasurable in most cases). This lets you control the trade-off between fast execution and detailed logging.

Let's move the check from the destructor to the earliest possible time, which is just before the construction of the Log object. In this way, if the logging level says you should discard the logged data, you won't even create the Log object.

#define LOG(level) \
if (level > Log::ReportingLevel()) ; \
else Log().Get(level)

Now the first example becomes:

LOG(logINFO) << "Hello " << username;

and is expanded by the preprocessor to (new lines added for clarity):

if (logINFO > Log::ReportingLevel())
;
else
Log().Get(logINFO) << "Hello " << username;

Consequently, the Log class becomes simpler as the messageLevel member and the test in the destructor are not needed anymore:

Log::~Log()
{
   os << std::endl;
   fprintf(stderr, "%s", os.str().c_str());
   fflush(stderr);
}

Logging is much more efficient now. You can add logging liberally to your code without having serious efficiency concerns. The only thing to remember is to pass higher (that is, more detailed) logging levels to code that's more heavily executed.

After applying this trick, macro-related dangers should be avoided—we shouldn't forget that the logging code might not be executed at all, subject to the logging level in effect. This is what we actually wanted, and is actually what makes the code efficient. But as always, "macro-itis" can introduce subtle bugs. In this example:

LOG(logINFO) << "A number of " << NotifyClients() << " were notified.";

the clients will be notified only if the logging level detail will be logINFO and lower. Probably not what was intended! The correct code should be:

const int notifiedClients = NotifyClients();
LOG(logINFO) << "A number of " << notifiedClients << " were notified.";