Friday, March 20, 2009

Log4Net logging from a web farm

We have a asp.net web handler that we use to process web survey submissions. We have been using log4net for debug and error logging for awhile now and recently have been having some severe performance issues with it.

When we profiled the code we found that the initialization of the Logging component was spending a fair amount of time reading in the XML configuration. We were initializing the component on each page request but it didn't need to be. We figured we could put it inside of an object that we get from Cache and share it accross multiple requests. 
public static ConfigurationManager GetInstance(Cache webCache, string configPath) {
    ConfigurationManager configManager = (ConfigurationManager) webCache[CACHE_KEY];
    if (configManager == null) {
        // Create a new manager from the stored config information.
        configManager = new ConfigurationManager(configPath);
    }
    return configManager;
}

Sure enough that worked but there were still times when under heavy load it was taking longer than expected to load. One of the team members found a article which helped identify the next problem, too many requests trying to initialize the ConfigurationManager at the same time. Time to apply some locking:
private static readonly object locker = new object();
public static ConfigurationManager GetInstance(Cache webCache, string configPath) {
    ConfigurationManager configManager = (ConfigurationManager) webCache[CACHE_KEY];
    if (configManager == null) {
        lock(locker) {
            ConfigurationManager configManager = (ConfigurationManager) webCache[CACHE_KEY];
            if (configManager == null) {
                // Create a new manager from the stored config information.
                configManager = new ConfigurationManager(configPath);
            }
        }
    }
    return configManager;
}

That's better but still one more thing we need to ensure. We are using a RollingFileAppender to log errors to a single log file. By default the FileAppender and RollingFileAppender establish exclusive locks on the output file when they are created. They also support another locking model call MinimalLock which only locks the file when its being written to. In a web scenario you should almost never use the default exclusive lock especially if the log compoent is being cached for multiple requests.

No comments: