Exception Logging In Production

Topics: Exception Handling Application Block, Logging Application Block
Jul 16, 2012 at 4:14 PM
Edited Jul 16, 2012 at 4:14 PM

Hello,

I have a suite of WCF services that have been moved into production which use EntLib5 Exception Handling and Logging.

I am currently looking at ways of increasing server throughput and have noted that if I switch off all logging via the LoggingEnabled filter I get better service performance and less CPU used. Before doing this I was using a priority filter which was set at a level where only exceptions should get through.

My question is - how should logging be set in production where I only want exceptions to be logged and require minimal performance instrusion from the logging block?

Many Thanks

Andy

Jul 18, 2012 at 12:50 AM

The first rule of performance optimization is to measure the performance so I would recommend doing that to verify what the performance issues are and where they occur.  For example, I've seen instances where objects were being serialized for logging and that was causing performance degradation.  Also, sometimes creating the logging data objects is time consuming even if the data is not logged.

In terms of Enterprise Library logging performance I would recommend turning off activity tracing if it is not required.  I also found that not specifying a formatter seems to result in slower performance.  This is counter-intuitive to me and I'm not sure why I saw those results so I'm hesitant to make it a recommendation (but as I said measure for yourself).  Another step to take is to enable the errors & warnings special source to determine if there are any errors occur during logging because any exceptions thrown and swallowed will definitely hurt performance.  If you are retrieving a LogWriter instance for every write operation then consider saving that instance for later use (that would save some cycles but not much).

The (almost) quickest way to short circuit the logging block is to use a filter since it is executed early in the processing steps.  The downside can be that filters are global (depending on your needs).

What I find interesting is that you say the Logging Enabled Filter had a different performance impact than a Priority Filter.  I wonder if the priority filter was executing properly?  In my testing, the performance of a priority filter is equivalent to the logging enabled filter.

Now if this is still not fast enough you can move some of the logging logic into your code (perhaps not as clean but you have to weigh elegance vs. performance).  For example by moving the filter check into my code I was able to almost halve the time taken to log.  For example:

var logWriter = EnterpriseLibraryContainer.Current.GetInstance<LogWriter>();
var filter = logWriter.GetFilter<PriorityFilter>();

if (filter.ShouldLog(11))
{
    logWriter.Write(i, "General");
}

And for the ultimate in speed (but with a loss of flexibility) then you could initialize a static readonly variable to determine what logging level is set (you can use whatever criteria you want) and the JITter will optimize out all code within the if statements if the value is false.  The downside is that this only occurs when the JITter compiles the IL initially. For example this code executes virtually instantly on my machine (~4ms) when compiled in release mode and isLoggingEnabled is set to false:

    class Program
    {
        private static readonly bool isLoggingEnabled;

        static Program()
        {
            var logWriter = EnterpriseLibraryContainer.Current.GetInstance<LogWriter>();
            var filter = logWriter.GetFilter<PriorityFilter>();
            isLoggingEnabled = filter.ShouldLog(1);
        }

        static void Main(string[] args)
        {
            int i = 0;

            var logWriter = EnterpriseLibraryContainer.Current.GetInstance<LogWriter>();
            var filter = logWriter.GetFilter<PriorityFilter>();

            for (i = 0; i < 10000000; i++)
            {
                if (isLoggingEnabled)
                {
                    logWriter.Write(i, "General");
                }
            }
        }
    }

--
Randy Levy
Enterprise Library support engineer
entlib.support@live.com