Log4j引起的Performance bottleneck

log4j在Java开发中非常广泛，在企业级应用中，有大量的日志需要记载，我们有一个系统每天记录的日志达到16G，是个庞大的数字。

 

我们在开发过程中发现类似下列的代码：

 

 

public class TTTT extends HttpServlet{

 

private static final Log log = LogFactory.getLog(TTTT.class);

 

     /**
     * Servlet GET request: handles event requests.
     */
    public void doGet(HttpServletRequest request, HttpServletResponse response) throws  ServletException, IOException {

    log.infor("Enter the servlet");

 

    ....

    ....

 

   }

}

 

我们在性能测试中发现，这个servlet运行时间非常长，有点奇怪，我们使用Memcached进行了Cache，为什么会这么慢，后来发现log.infor导致了大并发问题出现，请看log4j源码：

 

 

public
  void callAppenders(LoggingEvent event) {
    int writes = 0;

    for(Category c = this; c != null; c=c.parent) {
      // Protected against simultaneous call to addAppender, removeAppender,...
      synchronized(c) {
    if(c.aai != null) {
      writes += c.aai.appendLoopOnAppenders(event);
    }
    if(!c.additive) {
      break;
    }
      }
    }

    if(writes == 0) {
      repository.emitNoAppenderWarning(this);
    }
  }

 

看这段可以发现，log4j为了保证线程安全，使用了锁机制，synchronized是排它锁，因此在高并发时候，会导致大量的线程只能排队处理，吞吐量下降会非常快。在本例中，log变量是多个线程共享访问的（因为Servlet是单例），为了保证线程安全只能加锁，但是这个如何解决呢，日志总是要记录的，我现在需要做个测试，看看有没有解决方法。

 

[测试结果]

笔者用Jmeter分别测试了是否有可能servlet的共享变量log是不是会引起性能的变化：

 

Servlet1：

public class LogServlet extends HttpServlet{
    Logger logger = Logger.getLogger(LogServlet.class);
    /**
     * Servlet GET request: handles event requests.
     */
    public void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
    }

}

 

Servlet2：

 

public class LogServletNotShare extends HttpServlet{
   
    /**
     * Servlet GET request: handles event requests.
     */
    public void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException {
        Logger logger = Logger.getLogger(LogServletNotShare.class);
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
        logger.info("Test whether the shared logger variable can impact the performance");
    }

}

 

笔者采用Jmeter500个并发测试这两个servelt，吞吐量对比如下：

 

servlet1 第一次 第二次 第三次 第四次 第五次

34.1/sec 36.7/sec 38.7/sec 41.2/sec 40.3/sec

 

servlet2 第一次 第二次 第三次 第四次 第五次

40.5/sec 40.9/sec 41.3/sec 41.7/sec 40.3/sec

 

由此可见，log4j的性能与servlet的共享变量关系不是很明显，应该还是IO有关系