How Rapid is Rapid? How Quick is Quick?

Over the past year, we’ve been looking at a lot of logging systems:  Free systems, expensive systems, big systems…  anything that seemed related to logging or .NET.  One thing that stuck out was how much most of these systems centered their design around being fast.  The approach to defining fastest varies a bit:

• Fastest to commit to disk.
• Fastest by filtering what messages get logged.
• Fastest by doing everything on another thread.

We didn’t question this much until we were interacting with TheObjectGuy about his logging system and questioned what seemed like a very silly block of code:

/// <summary>
/// Write the String to the file.
/// </summary>
///
<param name="s">The String representing the LogEntry being logged.</param>
/// <returns>true upon success, false upon failure.</returns>
public bool WriteToLog(String s)
{
StreamWriter writer = null;
try
{
writer = GetStreamWriter();
writer.WriteLine(s);
}
catch
{
return false;
}
finally
{
try
{
writer.Close();
}
catch
{
}
}
return true;
}

This is about as non-optimal as you get:  Every log statement is causing the file to be opened, appended to, flushed, and closed.  That’s just crazy! It could be made so much faster!  When we asked about it, the response gave us pause:

…one thing I can say with certainty is that for every application that requires file logging performance greater than, say, 500 log entries per second (the performance I get on my old clunker of opening/closing files on each write), there are hundreds of applications where a user would like to be able to delete or rename a log file while the application is running.

So we set up a unit test to see just how bad it was.  It’s pretty simple code; in one case write all the messages with the file open (calling WriteLine each time) and the second case opens and closes it every time. And the results?  Indeed, the first method is much faster:

Keep File Open: 7.0014ms.  Average duration of 0.0070014ms per message.

Example Code Above: 161.0322ms.  Average duration of 0.1610322ms per message.

That’s an incredible improvement!  23 times faster!  And Faster is always better…. Right?

Well, let’s go back and consider what the point of the system is: It’s a logging system. In the test above it took 161ms  (0.16 seconds) to write 1,000 log messages to disk.  Extrapolating, that would mean this code could write around 6,000 messages per second, whereas the optimized code could go up to 142,000 messages per second.  But think about it:  Under what circumstances should a log system be storing 6,000 messages per second?

• At what level of detail in your code would you have to be logging to generate that many messages?  Practically at the debugger level of detail.
• If you’re logging at that level of detail, how easy would it be to dig out any useful information?  You’ve created a needle in the haystack problem.

The most common reason for generating that volume of messages would be that the code is stuck in a loop generating errors.  In that case, how important is it to be able to go faster?

• In the error loop, faster logging just produces larger log files with more records (because it’s stuck in a loop)
• Eventually the error loop will overwhelm something else:  Memory, disk performance, or disk capacity.

In short, nothing good is happening by being faster.  In the case of the code we were questioning, the author’s point was dead on:  It wasn’t worth loosing the functionality users wanted to for an unnecessary performance gain.

Speed is Seductive

When you think about it, it’s pretty easy to create a logging solution that can handle 100 messages per second all day long, and you should really consider if you’re logging more than that under normal circumstances you probably have a different problem.  Assuming you want to keep the overhead of logging to less than 10% of the total runtime of the process that’d mean you only need about 1000 messages/second capacity.

If performance over 1000 messages/second is all that’s required, why do so many systems pursue performance dramatically in excess of this?  The obvious answer is that it’s an easy metric to make a yardstick from.

• Everyone knows faster is better.
• People rarely put numbers into context.

The problem is that making code faster usually requires trading off something else:

1. It does less: This is the most common way to make something faster - have it do less because the fastest line of code is the one that isn’t there.
2. It’s a lot more complicated: Every tricky optimization adds complexity, whether it’s fancy threading or buffering, it’s all complexity to maintain.

In this case, there’s a more subtle problem at work as well:  As a developer, if you believe that the log system is extraordinarily fast then why worry about what you log?  After all, it isn’t going to slow down the application.   That leads to logging strategies like this where the log is practically a substitute for a debugger.   On the surface, that doesn’t seem all that bad, but what are you really logging for?

Shotgun Logging = Deferred Design

If you’ve got a shotgun logging strategy that has messages for every object you construct or every method you call or a similar level of detail, you’re filling up your log with a lot of information but not much value.  In many cases, any logging pattern that could be autogenerated adds only a minor amount of value because it leaves out the reasons (the why) and consequences (and therefore…).  It’s precisely the effort you put into considering what messages to log and where to log them that adds the value to your logging you’ll need in support.  It’s possible that the shotgun messages can complement your hand-crafted messages to give you a better picture, but without the hand crafted messages when it comes time to actually use the log data to support your application you’ll still feel lost.

Instead of waiting until you’ve got a real problem on your hands to figure out what your log data means, use it throughout your testing and certification process to make sure that you’ve got enough of the right, high value messages to support your application.  Doing a little design work for your log messages as a feature of your application instead of just blanketing your code with generic log statements will pay off in spades.