Performance

One of the often-cited arguments against logging is its computational cost. This is a legitimate concern as even moderately sized applications can generate thousands of log requests. Much effort was spent measuring and tweaking logging performance. Log4net claims to be fast and flexible: speed first, flexibility second.

The user should be aware of the following performance issues.

1. Logging performance when logging is turned off.

   When logging is turned off entirely or just for a set of levels, the cost of a log request consists of a method invocation plus an integer comparison.

   However, The method invocation involves the "hidden" cost of parameter construction.

   For example, for some logger log, writing,

   log.Debug("Entry number: " + i + " is " + entry[i].ToString());

   incurs the cost of constructing the message parameter, i.e. converting both integer i and entry[i] to strings, and concatenating intermediate strings, regardless of whether the message will be logged or not. This cost of parameter construction can be quite high and it depends on the number and type of the parameters involved.

   To avoid the parameter construction cost write:

   if(log.IsDebugEnabled)
   {
       log.Debug("Entry number: " + i + " is " + entry[i].ToString());
   }

   This will not incur the cost of parameter construction if debugging is disabled. On the other hand, if the logger is debug-enabled, it will incur twice the cost of evaluating whether the logger is enabled or not: once in IsDebugEnabled and once in Debug. This is an insignificant overhead because evaluating a logger takes about 1% of the time it takes to actually log.

   Certain users resort to pre-processing or compile-time techniques to compile out all log statements. This leads to perfect performance efficiency with respect to logging. However, since the resulting application binary does not contain any log statements, logging cannot be turned on for that binary. In many people's opinion this is a disproportionate price to pay in exchange for a small performance gain.

2. The performance of deciding whether to log or not to log when logging is turned on.

   This is essentially the performance of walking the logger hierarchy. When logging is turned on, log4net still needs to compare the level of the log request with the level of the request logger. However, loggers may not have an assigned level; they can inherit them from the logger hierarchy. Thus, before inheriting a level, the logger may need to search its ancestors.

   There has been a serious effort to make this hierarchy walk to be as fast as possible. For example, child loggers link only to their existing ancestors. In the BasicConfigurator example shown earlier, the logger named Com.Foo.Bar is linked directly to the root logger, thereby circumventing the nonexistent Com or Com.Foo loggers. This significantly improves the speed of the walk, especially in "sparse" hierarchies.

   The typical cost of walking the hierarchy is typically 3 times slower than when logging is turned off entirely.

3. Actually outputting log messages

   This is the cost of formatting the log output and sending it to its target destination. Here again, a serious effort was made to make layouts (formatters) perform as quickly as possible. The same is true for appenders.

Although log4net has many features, its first design goal was speed. Some log4net components have been rewritten many times to improve performance. Nevertheless, contributors frequently come up with new optimizations. You should be pleased to know that when configured with the SimpleLayout performance tests have shown log4net to log within an order of magnitude of System.Console.WriteLine.

Logging Event Flow

The following is the series of steps and checks that a messages goes through while being logged. For the purposes of this example we will document an INFO level message being logged on logger ConsoleApp.LoggingExample. This logger is configured to use the log4net.Appender.ConsoleAppender. The repository used in this example is a log4net.Repository.Hierarchy object.

1. The user logs a message using the ILog.Info method on the logger obtained using a call to log4net.LogManager.GetLogger("ConsoleApp.LoggingExample"). For example: log4net.LogManager.GetLogger("ConsoleApp.LoggingExample").Info("Application Start"); The ILog interface is actually an extension to log4net that provides level specific logging methods (i.e. Debug, Info, Warn, Error, and Fatal).

2. The message is then logged through to the ILogger.Log method on the appropriate log4net.Repository.Hierarchy.Logger object. The ILogger.Log method takes the Level to log at as a parameter and therefore works for all levels.

3. The repository threshold level is compared to the message level to determine if the message can be logged. If the message level is below the threshold level the message is not logged. In this case the repository is a log4net.Repository.Hierarchy object.

4. The Logger level is compared to the message level to determine if the message can be logged. Note that the Logger level is inherited from a parent Logger if not specified explicitly for this Logger. If the message level is below the Logger level the message is not logged.

5. A LoggingEvent instance is created to encapsulate the message being logged.

6. The list of appenders for the Logger is built. This includes appenders attached to parent Loggers except where excluded by the Logger.Additivity property.

7. The LoggingEvent object is passed to the IAppender.DoAppend method for each appender.

For Each Appender that the LoggingEvent is delivered to the following actions take place:

1. The appender threshold level is compared to the message level to determine if the message can be logged. If the message level is below the threshold level the message is not logged.

2. If the appender has a filter chain the LoggingEvent is passed down the filter chain which can decide if the message can be logged or not.

3. Next an appender specific check is performed. Usually this check will verify that all the required properties are set for the appender (e.g. a Layout is set if required).

4. The LoggingEvent is passed to the appender specific Append method. What happens now is specific to the appender.

The following actions take place in the ConsoleAppender.Append method:

1. The ConsoleAppender uses a Layout to format the message as a string for display.

2. The Layout uses the LoggingEvent.RenderedMessage property to get the string for the message object. This uses the registered IObjectRenderer for the type of the message object.

3. The message text is displayed on the console using the Console.WriteLine method.