能不能让log4j跑的“更快”，对业务总体执行时间影响更小？

 

最近事情不多，翻了一下log4j的源代码，发现这个一直跟随左右的“小伙伴”设计还是很棒的，但实现上就显得非常朴素，加上年岁已高，身上补丁可真不少。

 

尤其是发现其pom.xml的这段，更感觉其“厚重”：

 

      <plugin>
        <artifactId>maven-compiler-plugin</artifactId>
        <version>2.1</version>
        <configuration>
          <source>1.3</source>
          <target>1.1</target>
          <encoding>UTF-8</encoding>
        </configuration>
      </plugin>

 

 

试想一下，在座几乎没人用JDK1.3了吧，更不用说1.1.

 

大家知道，按照log4j的说法，他们关心两个东西：性能第一、扩展第二。

其实性能还是OK的，在一般情况下，我们根本就可以忽略不计，考虑到logger.debug("a" + "b" + "c")导致的字符串连接性能，我们完全可以用slf4j作为我们logging的facade，以避免这种性能消耗（没用过就要考虑一下了），或者加上logger.isDebugEnabled()之类的简单判断。

 

但能不能让log4j跑的“更快”，影响更小呢？

 

出于好奇+好玩，下面我做了一些有点“无理取闹”的尝试。

 

我们知道，日志必须根据时间序列进行FIFO的输出，想想java.util.concurrent.BlockingQueue不就是干这个的吗，于是尝试了一下。

思路是：

1、不是真正的写日志，而是把LoggingEvent put到queue里；

2、启用另一个线程去take queue里面的Event，再真正写到我们的文件里去（真正要提高性能，可定运用于生成环境中，没人在生成环境中用ConsoleAppender吧？）。

 

 

基于FileAppender编写一个自定义的Appender，我叫BlockingQueueAppender。

代码如下：

 

package bright.zheng;

import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;

import org.apache.log4j.FileAppender;
import org.apache.log4j.Logger;
import org.apache.log4j.spi.LoggingEvent;

/**
 * 
 * @author bright_zheng
 *
 */
public class BlockingQueueAppender extends FileAppender {
	private final BlockingQueue<LoggingEvent> queue;
	private final Thread dispatcher;

	public BlockingQueueAppender() {
		queue = new LinkedBlockingQueue<LoggingEvent>(10000);
		dispatcher = new Thread(new Dispatcher());
		dispatcher.setName("BlockingQueueAppender-" + dispatcher.getName());
		dispatcher.start();
	}

	/**
	 * We don't write to the file directly 
	 * but just put the <code>LoggingEvent</code> to the queue
	 */
	public void append(LoggingEvent event) {
		try {
			queue.put(event);
		} catch (InterruptedException e) {
			//do nothing
		}
	}

	private class Dispatcher implements Runnable {
		public void run() {
			try {
				while (true) {
					LoggingEvent event = queue.take();
					BlockingQueueAppender.this.subAppend(event);
				}
			} catch (InterruptedException ignored) {
				ignored.printStackTrace();
			}
		}
	}
}

 

 

然后log4j.properties文件配置成这样：

 

log4j.rootLogger=ERROR, CONSOLE

log4j.logger.bright.zheng=DEBUG, queue
log4j.additivity.bright.zheng = false

#file
log4j.appender.file=org.apache.log4j.FileAppender
log4j.appender.file.File=File.log
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{dd MMM yyyy HH:mm:ss,SSS}: %-5p %c: %m%n

#queue
log4j.appender.queue=bright.zheng.BlockingQueueAppender
log4j.appender.queue.File=Queue.log
log4j.appender.queue.layout=org.apache.log4j.PatternLayout
log4j.appender.queue.layout.ConversionPattern=%d{dd MMM yyyy HH:mm:ss,SSS}: %-5p %c: %m%n

 

 

之后把上述的queue换成file反复测试，可得到耗时。

测试用例如下（第一个测试用例用来预热，避免创建文件的消耗存在干扰）：

 

package bright.zheng;

import org.apache.log4j.Logger;
import org.junit.Test;

public class ConfigurationEffectiveTest {
	static Logger logger = Logger.getLogger(ConfigurationEffectiveTest.class);
	
	@Test
	public void testLogger(){
		logger.trace("trace");
		logger.debug("debug");
		logger.info("info");
		logger.warn("warn");
		logger.error("error");
		logger.fatal("fatal");		
	}
	
	@Test
	public void testLoggerN(){
		long start = System.currentTimeMillis();
		for(int i=0; i<10000; i++){
			logger.trace("trace");
			logger.debug("debug");
			logger.info("info");
			logger.warn("warn");
			logger.error("error");
			logger.fatal("fatal");		
		}
		long end = System.currentTimeMillis();
		System.out.println("time:" + (end-start));
		logger.fatal("----------END-------------");
	}
}

 

 

可想而知，这种扔到queue里就收工的做法，queue的长度当然很重要，故可以设想影响“性能”的指标为queue的大小。

下面是测试数据，我拿excel简单整理如下：

 

SN FileAppender BlockingQueueAppender queue length

1 922 1109 10

2 937 1094 100

3 938 1047 1000

4 922 1031 2000

5 937 1016 4000

6 922 906 10000

7 906 735 20000

8 953 531 30000

9 938 266 40000

10 907 187 50000  

 

简单转化为折线图可能看的更清楚些：

很明显，10000个循环，从debug开始算（我设置log的级别为debug），刚好50000个，我直接把queue开成50000个是最快的（好像有点废话，哈哈）

 

总体感觉真有点无理取闹，但这样做确实可以确保我们包含logger的业务代码省了不少毫秒，而即便开了50000个对象的queue又怎样呢，按照每个LoggingEvent对象不超过0.5k来推算，得考虑给logging花上25M的内存。

 

 

是不是值得呢？

 

评论

15 楼 beykery 2011-06-11  

没用过log4j，从来都是jdk的Logger.

14 楼 skzr.org 2011-06-11  

<div class="quote_title">supben 写道</div>
<div class="quote_div">log4j 效率低在判断上。<br><br>除非你打每一种级别都加判断，如debug加上<br>if (logger.isDebugenabled()){<br>    logger.debug(...);<br>}<br><br>所以都用slf4j! 我们总监说的，希望能对楼主有所帮助</div>
<p> </p>
<p>slf4j只是一个桥接器，确实减少了不必要的对象创建产生的时间。</p>
<p>“log4j 效率低在判断上。”意思是我们平时写代码很多时候使用了字符串+，而没有加上if (logger.isXXXenable())判断打log是不是必要，而slf4j正好做了这个事情。</p>
<p> </p>
<p>
</p>
<div style="color: #000000; font-family: Verdana, Arial, Helvetica, sans-serif; font-size: 12px; background-color: #ffffff; margin: 8px;">
<div class="quote_title" style="font-weight: bold; margin-top: 5px; margin-right: 0px; margin-bottom: 0px; margin-left: 15px; padding: 5px;">HelloJimmy 写道</div>
<div class="quote_div" style="margin-top: 0px; margin-right: 5px; margin-bottom: 5px; margin-left: 15px; background-color: #fafafa; padding: 3px; border: 1px solid #cccccc;">非无理取闹；<br>我在2008年做一个项目就用到这种异步log的做法，主要的原因是：当时的系统非常庞大，业务很复杂，log的东西也非常多；</div>
<p style="margin: 0px;">这个我也觉得不是无理取闹，平时用warn问题不大，特别是调试生产系统时，需要大量的debug甚至trace日志，异步日志记录才是王道。</p>
</div>

13 楼 agapple 2011-06-10  

log4j有个AsyncAppender，异步输出的，思路上都是一样的。只不过它用的ArrayList做为buffer，同步控制用了synchronized而已。

性能提升的很多思路都是一样的，要么就是减少I/O阻塞，减少锁竞争。

12 楼 yangguo 2011-06-10  

HelloJimmy 写道

非无理取闹；
我在2008年做一个项目就用到这种异步log的做法，主要的原因是：当时的系统非常庞大，业务很复杂，log的东西也非常多；

只不过buffer一下而已。

11 楼 itstarting 2011-06-10  

HelloJimmy 写道

非无理取闹；
我在2008年做一个项目就用到这种异步log的做法，主要的原因是：当时的系统非常庞大，业务很复杂，log的东西也非常多；

给咱分享分享？

10 楼 itstarting 2011-06-10  

dwbin 写道

用内存换时间，想法不错，不过总觉着目前的应用没必要实时到这个地步吧？如果对于单笔业务的要求到了毫秒级别的话，我觉着业务是不是有问题啊？

一般的企业应用，确实不用太抠这个门

但互联网应用呢？国家级的大型应用呢？当然了，负载多就扩展嘛。
但无论怎么搞，单个业务执行时间总是有扩不动的时候（毕竟是有极限的），这里权当扩展思路咯

9 楼 HelloJimmy 2011-06-10  

非无理取闹；
我在2008年做一个项目就用到这种异步log的做法，主要的原因是：当时的系统非常庞大，业务很复杂，log的东西也非常多；

8 楼 itstarting 2011-06-10  

ticmy 写道

据说logback( http://logback.qos.ch/ ) 比log4j快？ 

没用过，感觉都差不多，无论谁思路都类似
不爽还可以自己扩展

要不你也来一个测试，用数据说话？

7 楼 itstarting 2011-06-10  

supben 写道

log4j 效率低在判断上。

除非你打每一种级别都加判断，如debug加上
if (logger.isDebugenabled()){
    logger.debug(...);
}

所以都用slf4j! 我们总监说的，希望能对楼主有所帮助

呵呵，你们总监那还是有点小水平的，跟咱的想法一样：）
但不是“低在判断上”，而是在于可能过多构造不用log的string，所以才用slf4j这样的facade

6 楼 dwbin 2011-06-10  

用内存换时间，想法不错，不过总觉着目前的应用没必要实时到这个地步吧？如果对于单笔业务的要求到了毫秒级别的话，我觉着业务是不是有问题啊？

5 楼 supben 2011-06-10  

log4j 效率低在判断上。

除非你打每一种级别都加判断，如debug加上
if (logger.isDebugenabled()){
    logger.debug(...);
}

所以都用slf4j! 我们总监说的，希望能对楼主有所帮助

4 楼 ticmy 2011-06-10  

据说logback( http://logback.qos.ch/ ) 比log4j快？ 

3 楼 itstarting 2011-06-10  

houfeng0923 写道

楼主的研究精神值得学习。大部分应用可能log本身就满足吧。

所以说有点“无理取闹”的感觉，Singlish: just for fun lah.
然而有些司空见惯的事情，往往我们想的太少。

另外，一些大型网站可能需要大量的日志来分析用户行为模式，这样的折腾可能也会有帮助

2 楼 小杨学JAVA 2011-06-10  

好深奥啊，强啊

1 楼 houfeng0923 2011-06-10  

楼主的研究精神值得学习。大部分应用可能log本身就满足吧。