能不能让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的内存。

 

 

是不是值得呢？

 

评论

35 楼 dingherry 2011-06-16  

你们讲的我都听不懂，怎么办？
现在才刚刚会用SSH整合框架……

34 楼 itstarting 2011-06-14  

油炸大龙虾 写道

老外有个BT思路，如何保持日志连贯性并减少锁等，用的是ThreadLocal，呵呵

有帮助吗？在我看来，一点都没有：
1、ThreadLocal是能避免数据在不同线程的冲突——因为压根就是井水不犯河水；
2、都要写到一个地方，比如console、file...请问这个冲突岂是启用ThreadLocal所能避免？

33 楼 itstarting 2011-06-14  

isaac.198 写道

楼主的图是用什么画的呀

这位兄台居然关注这个：把数据粘贴到excel，设置一下即可

32 楼 isaac.198 2011-06-14  

楼主的图是用什么画的呀

31 楼 油炸大龙虾 2011-06-13  

老外有个BT思路，如何保持日志连贯性并减少锁等，用的是ThreadLocal，呵呵

30 楼 itstarting 2011-06-13  

kimmking 写道

log4j本身的扩展设计还是不错的。

严重同意

而且概念很简单，logger/appender/layout/...屈指可数但处处闪光

不过不看代码，还真不知道一些关键东西，比如不鼓励使用category而应使用logger，不鼓励使用PatternLayout而应使用EnhancedPatternLayout等等

29 楼 凤凰山 2011-06-13  

完全可以啊，log4j他爹就说了10个原因换log4j，用logback这个新的日志工具，这里有ppt


10 reasons to use logback !------log4j他爹告诉你为何要使用新的日志包logback


http://guosxu.iteye.com/blog/969152

28 楼 kimmking 2011-06-13  

log4j本身的扩展设计还是不错的。

27 楼 itstarting 2011-06-13  

哈哈，我向来鼓励百花争鸣的

有时候光看代码价值不大，顶多是“哦，原来这样啊”——动动手才好，尤其是自己想些歪招，取巧而已

谢谢你的临门一脚

26 楼 agapple 2011-06-13  

itstarting 写道

曾经de迷茫 写道

agapple 写道

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

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

正解，楼主说看了log4j源码，还搬出这样的轮子。

我知道有这个东西，但请问你看过这两个类的代码了吗？连作者都在打问号呢
在这里，我继承自原有的类，自然也享受了bufferedIO的成果。

我们都用JDK5/6，没必要再用JDK1.3写的套路，所以几行代码就搞定了，大家也看的清爽。
套用李想的一句话：我不投机，但取巧：）

当然，更重要的，是学习的同时，做一些尝试，开拓一下思路

哈，LZ别发火，我原先的本意是说性能优化思路是相通的。
AsyncAppender和你自己实现的BlockingQueueAppender，实现思路都是一样的，我非常赞成一些新的想法和敢于去尝试实践的做法。因为只有你自己切身去写过，才能更加深刻的认识底层源码(因为你在写之前势必会比较深入的学习它的一些底层设计和扩展接口，包括性能好在哪，差在哪)

投个良好贴，支持下这样的工作 

25 楼 itstarting 2011-06-13  

曾经de迷茫 写道

agapple 写道

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

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

正解，楼主说看了log4j源码，还搬出这样的轮子。

我知道有这个东西，但请问你看过这两个类的代码了吗？连作者都在打问号呢
在这里，我继承自原有的类，自然也享受了bufferedIO的成果。

我们都用JDK5/6，没必要再用JDK1.3写的套路，所以几行代码就搞定了，大家也看的清爽。
套用李想的一句话：我不投机，但取巧：）

当然，更重要的，是学习的同时，做一些尝试，开拓一下思路

24 楼 11122233 2011-06-13  

支持楼主的探索精神，回头我也试试异步log。

23 楼 damoqiongqiu 2011-06-13  

楼主威武
深入研究是非常好的精神

22 楼 hlbng 2011-06-13  

唉，只简单用过log4j，惭愧啊

21 楼 曾经de迷茫 2011-06-13  

agapple 写道

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

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

正解，楼主说看了log4j源码，还搬出这样的轮子。

20 楼 liberD 2011-06-12  

顶楼主！进步就是在这些折腾中获得的！加油啊！O(∩_∩)O哈哈~

19 楼 kimmking 2011-06-12  

没必要自己实现。

18 楼 kimmking 2011-06-12  

log4j的file appender有
bufferIO和 AsyncAppender模式

其实都是BlockingQueue的方式
一种缓冲的是bytes[]，一种是记录数。

因为缓冲，不用每次写磁盘（flush=true），批量写入性能更高，曲线更平滑，
因为异步，跑在独立的线程，对系统本身就影响更小。

17 楼 itstarting 2011-06-11  

bao231 写道

错，大错特错，slf4j最根本的差别不是支持桥接模式，而是支持log.debug("XXXXX{},XXX{}",a,b),像这种的模式，这样才能减少字符相加产生的碎片，知道不？如果仅仅是支持桥接模式的话，那common-log早就支持桥接模式了。

SLF4J - Simple Logging Facade for Java

楼上的言语激进了些，不过其核心确实是这样的，就是一个简单的facade，并能克服common-logging的一些classloader的问题

16 楼 bao231 2011-06-11  

错，大错特错，slf4j最根本的差别不是支持桥接模式，而是支持log.debug("XXXXX{},XXX{}",a,b),像这种的模式，这样才能减少字符相加产生的碎片，知道不？如果仅仅是支持桥接模式的话，那common-log早就支持桥接模式了。