Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-1644

Inefficient locking in AbstractLoggerAdapter

    XMLWordPrintableJSON

Details

    • Improvement
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 2.6.1
    • 2.8
    • API
    • Patch

    Description

      In org.apache.logging.log4j.spi.AbstractLoggerAdapter, the getLoggersInContext method has a synchronize block to prevent concurrent destructive access to the registry, a java.util.WeakHashMap:

          public ConcurrentMap<String, L> getLoggersInContext(final LoggerContext context) {
              synchronized (registry) {
                  ConcurrentMap<String, L> loggers = registry.get(context);
                  if (loggers == null) {
                      loggers = new ConcurrentHashMap<>();
                      registry.put(context, loggers);
                  }
                  return loggers;
              }
          }

      However, in the case when loggers are already in the map, the large synchronize block means that two threads cannot simultaneously read from the map, which hurts performance in highly multi-threaded applications that constantly re-instantiate loggers.

      In our application, we have modified this method to use a ReadWriteLock instead, providing unlimited concurrent get() operations but blocking put() operations by using a double-checked locking idiom:

      import java.util.concurrent.locks.ReadWriteLock;
      import java.util.concurrent.locks.ReentrantReadWriteLock;
      
      (...)
      
          private final ReadWriteLock lock = new ReentrantReadWriteLock (true);
      
      (...)
      
          public ConcurrentMap<String, L> getLoggersInContext(final LoggerContext context) {
              ConcurrentMap<String, L> loggers;
              lock.readLock ().lock ();
              try {
                  loggers = registry.get (context);
              } finally {
                  lock.readLock ().unlock ();
              }
      
              if (loggers != null) {
                  return loggers;
              } else {
                  lock.writeLock ().lock ();
                  try {
                      loggers = registry.get (context);
                      if (loggers == null) {
                          loggers = new ConcurrentHashMap<> ();
                          registry.put (context, loggers);
                      }
                      return loggers;
                  } finally {
                      lock.writeLock ().unlock ();
                  }
              }
          }

      The ReadWriteLock interface and the ReentrantReadWriteLock implementation have been available since Java 5. The performance gains from using read locks have so far been considerable.

      Why are we constantly re-instantiating loggers instead of, for example, keeping a static final Logger in our classes? In many cases it's because the class which holds the logger is a base class, and it can't use a static logger in case a different outlet has been specified for the actual derived class which has been instantiated. Some of these objects, for example AbstractMediaTypeExpression in the Spring framework, are constantly being destroyed and reconstructed. Where reasonable for our application, we've also patched those other classes to just use static final Loggers, but there are a lot of them and it is ultimately better to solve this problem at the source.

      Attachments

        1. LoggerAdapterTest.java
          4 kB
          Tim Gokcen
        2. AbstractLoggerAdapter.patch
          2 kB
          Tim Gokcen

        Activity

          People

            ggregory Gary D. Gregory
            HeXetic Tim Gokcen
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: