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有关系

 

 

 

 

 

 

评论

19 楼 watermud 2010-05-17  

1.应用服务器上 “Enter the servlet”这个信息有什么意义，全部检查一下没用的信息删掉。
2.文件太大。

18 楼 tomyz0223 2010-05-15  

这篇文章title不是很合适，今天上javaeye把我吓一跳，怎么这么多回复，赶紧把title改了，以避免浪费大家的时间，log4j的性能问题，是我的同事遇到的这个问题，IO确实最大的问题，他当时把日志的大小设置成1G，当然并发访问锁也是有可能造成这类问题的，我过段时间会测试这个问题。

17 楼 SeanHe 2010-05-15  

建议改成异步日志

16 楼 whaosoft 2010-05-15  

shijian0306 写道

晕啊，我看成了~
Log4j引起的性功能障碍

好么 现在严厉扫黄打黑啊

15 楼 freish 2010-05-15  

这些地方需要这种级别的日志么？！

14 楼 nwangwei 2010-05-15  

<div class="quote_title">tomyz0223 写道</div>
<div class="quote_div">
<p>log4j在Java开发中非常广泛，在企业级应用中，有大量的日志需要记载，我们有一个系统每天记录的日志达到16G，是个庞大的数字。</p>
<p> </p>
<p>我们在开发过程中发现类似下列的代码：</p>
<p> </p>
<p> </p>
<p>public class TTTT extends HttpServlet{</p>
<p> </p>
<p>private static final Log log = LogFactory.getLog(TTTT.class);</p>
<p> </p>
<p>     /**<br>     * Servlet GET request: handles event requests.<br>     */<br>    public void doGet(HttpServletRequest request, HttpServletResponse response) throws  ServletException, IOException {</p>
<p>    log.infor("Enter the servlet");</p>
<p> </p>
<p>    ....</p>
<p>    ....</p>
<p> </p>
<p>   }</p>
<p>}</p>
<p> </p>
<p>我们在性能测试中发现，这个servlet运行时间非常长，有点奇怪，我们使用Memcached进行了Cache，为什么会这么慢，后来发现log.infor导致了大并发问题出现，请看log4j源码：</p>
<p> </p>
<p> </p>
<p>public<br>  void callAppenders(LoggingEvent event) {<br>    int writes = 0;<br><br>    for(Category c = this; c != null; c=c.parent) {<br>      // Protected against simultaneous call to addAppender, removeAppender,...<br>     <strong> synchronized(c) {</strong> <br>    if(c.aai != null) {<br>      writes += c.aai.appendLoopOnAppenders(event);<br>    }<br>    if(!c.additive) {<br>      break;<br>    }<br>      }<br>    }<br><br>    if(writes == 0) {<br>      repository.emitNoAppenderWarning(this);<br>    }<br>  }</p>
<p> </p>
<p>看这段可以发现，log4j为了保证线程安全，使用了锁机制，synchronized是排它锁，因此在高并发时候，会导致大量的线程只能排队处理，吞吐量下降会非常快。在本例中，log变量是多个线程共享访问的（因为Servlet是单例），为了保证线程安全只能加锁，但是这个如何解决呢，日志总是要记录的，我现在需要做个测试，看看有没有解决方法</p>
</div>
<p>你的这个servlet并发多少呢？1000以内的不用考虑log4j的问题。</p>

13 楼 tsxm 2010-05-15  

log基本上不存在修改，不存在你说的线程安全

12 楼 teclogid 2010-05-15  

引用

log变量是多个线程共享访问的（因为Servlet是单例）

???

11 楼 bughammer 2010-05-15  

hatedance 写道

icanfly 写道

shijian0306 写道

晕啊，我看成了~
Log4j引起的性功能障碍

这位仁兄太潮了

我也看错了，还怀疑这样的帖子斑竹为啥不删。

1星级的兄弟，你自己有投票权的吧？为啥不投？

10 楼 nenyalanye_1 2010-05-15  

似乎没碰到过这样的问题，应该不是log4j的性能问题吧。毕竟开源的东西部会太烂

9 楼 spyker 2010-05-15  

对你的原因不是很清楚
但是 如果真是log4j的性能问题的话
推荐试试logback
移植性是没问题的

8 楼 hatedance 2010-05-15  

icanfly 写道

shijian0306 写道

晕啊，我看成了~
Log4j引起的性功能障碍

这位仁兄太潮了

我也看错了，还怀疑这样的帖子斑竹为啥不删。

7 楼 JE帐号 2010-05-15  

log.info("Enter the servlet") ???

我觉得这句日志的级别应该是debug.

if(log.isDebugEnable()){
  log.debug("Enter the servlet");
}

Servlet 如此重要的入口类,日志应该小心翼翼的使用

另外可以考虑异步日志.

6 楼 berlou 2010-05-14  

shijian0306 写道

晕啊，我看成了~
Log4j引起的性功能障碍

今天第二次吐血
今天哥们在路上看见一美女开辆轿子， 一看车牌号乐吐血了。
J8995

5 楼 icanfly 2010-05-14  

shijian0306 写道

晕啊，我看成了~
Log4j引起的性功能障碍

这位仁兄太潮了

4 楼 sw1982 2010-05-14  

这里不是因为同步的问题，而是I/O瓶颈了！

那个块依赖于appdner数量+写操作的时间

3 楼 shijian0306 2010-05-14  

shijian0306 写道

晕啊，我看成了~
Log4j引起的性功能障碍

是不是我太XE了

2 楼 shijian0306 2010-05-14  

晕啊，我看成了~
Log4j引起的性功能障碍

1 楼 wilddonkey 2010-05-14  

log4j支持按照时间戳记录日志，比如一个小时一个文件，否则，写入一个16g的文本文件，卖糕的。。。。。。