Log4j的AsyncAppender能否提升性能？
-
博客分类：
- 日志
近日在写多线程方面的东西，需要对多线程进行日志监控就重新翻出了log4j，看到了log4j下居然还有一个AsyncAppender，异步记日志？觉得挺不错，网上搜了一下也有一些讨论，JavaEye上也有很多讨论。但是这个AsyncAppender到底能否提升日志性能呢？我们还是先看看log4j本身文档里的性能测试说明吧，详细测试数据见如下URL:http://www.ingrid.org/jajakarta/log4j/jakarta-log4j-1.1.3/docs/api/org/apache/log4j/performance/Logging.html
由此可见AsyncAppender虽然是异步的，但是并不能提升性能，为什么呢？何谓异步？异步就是另外开了个线程用来专门记录日志，然而既然引入了多线程，线程间的同步开销就不能不考虑了，看AsyncAppender的源代码中到处充斥着synchronized就能看到了。
用独立线程处理日志会引入以下几个问题：
- 中断(如果一个阻塞在日志操作的线程被中断，还出现什么情况？)
- 服务担保(logger能保证成功加入队列的消息都能在服务终止前被记录么？)
- 饥饿策略(当生产者记录消息比logger线程的处理能力更快的时候会如何？)
- 服务的生命周期(如何关闭logger，如何就服务的状态与生产者进行沟通？)
由此的需要讨论就是，为什么要使用异步？何时使用异步？如何使用异步？我们先来看同步和异步到底有何不同：
同步情况
各线程直接获得输出流进行输出(线程间不需要同步)。
异步情况
- 各线程将日志写到缓存，继续执行下面的任务(这里是异步的)
- 日志线程发现需要记日志时独占缓存(与此同时各线程等待，此时各线程是被阻塞住的)，从缓存中取出日志信息，获得输出流进行输出，将缓存解锁(各线程收到提醒，可以接着写日志了)
众所周知，磁盘IO操作、网络IO操作、JDBC操作等都是非常耗时的，日志输出的主要性能瓶颈也就是在写文件、写网络、写JDBC的时候。日志是肯定要记的，而要采用异步方式记，也就只有将这些耗时操作从主线程当中分离出去才能真正的实现性能提升，也只有在线程间同步开销小于耗时操作时使用异步方式才真正有效！现在我们接着分别来看看这几种记录日志的方式。
将日志记录到本地文件
同样都是写本地文件Log4j本身有一个buffer处理入库，采用异步方式并不一定能提高性能(主要是如何配置好缓存大小)；而线程间的同步开销则是非常大的！因此在使用本地文件记录日志时不建议使用异步方式。
将日志记录到JMS
JMS本身是支持异步消息的，如果不考虑JMS消息创建的开销，也不建议使用异步方式。
将日子记录到SOCKET
将日志通过Socket发送，纯网络IO操作不需要反馈，因此也不会耗时
将日志记录到数据库
众所周知JDBC是几种方式中最耗时的：网络、磁盘、数据库事务，都使JDBC操作异常的耗时，在这里采用异步方式入库倒是一个不错的选择。
将日志记录到SMTP
同JDBC
性能测试
在同步和异步方式下，同时起1000个线程，分别测试记录到文件和数据库中的时间消耗，每类测试连测5遍避免误差。
测试环境
1、WINDOWS XP SP2、JDK 1.5、ORACLE 9i2(本地)、log4j-1.2.14.jar
2、MutiTest.java用来测试同步方式，读取配置文件：log4j.properties
MutiTestAsyncAppender.java用来测试异步方式，读取配置文件：log4j.xml
3、每次测试先删除日志文件或清空表，确保测试独立性
测试结果如下：
| FileAppender | ||||
| 同步方式 | 最晚线程执行时间 | 最早线程执行时间 | 消耗时间 | |
| 1 | 1.23209E+12 | 1.23209E+12 | 156 | |
| 2 | 1.23209E+12 | 1.23209E+12 | 172 | |
| 3 | 1.23209E+12 | 1.23209E+12 | 172 | |
| 4 | 1.23209E+12 | 1.23209E+12 | 188 | |
| 5 | 1.23209E+12 | 1.23209E+12 | 157 | |
| 异步方式 | 最晚线程执行时间 | 最早线程执行时间 | 消耗时间 | |
| 1 | 1.23209E+12 | 1.23209E+12 | 157 | |
| 2 | 1.23209E+12 | 1.23209E+12 | 188 | |
| 3 | 1.23209E+12 | 1.23209E+12 | 156 | |
| 4 | 1.23209E+12 | 1.23209E+12 | 187 | |
| 5 | 1.23209E+12 | 1.23209E+12 | 172 | |
| JDBCAppender | ||||
| 同步方式 | 最晚线程执行时间 | 最早线程执行时间 | 消耗时间 | |
| 1 | 1.23209E+12 | 1.23209E+12 | 281 | |
| 2 | 1.23209E+12 | 1.23209E+12 | 172 | |
| 3 | 1.23209E+12 | 1.23209E+12 | 172 | |
| 4 | 1.2321E+12 | 1.2321E+12 | 171 | |
| 5 | 1.2321E+12 | 1.2321E+12 | 203 | |
| 异步方式 | 最晚线程执行时间 | 最早线程执行时间 | 消耗时间 | |
| 1 | 1.2321E+12 | 1.2321E+12 | 94 | |
| 2 | 1.2321E+12 | 1.2321E+12 | 94 | |
| 3 | 1.2321E+12 | 1.2321E+12 | 94 | |
| 4 | 1.2321E+12 | 1.2321E+12 | 94 | |
| 5 | 1.2321E+12 | 1.2321E+12 | 125 |
结论
由以上测试结果可以得出异步方式记录日志并不是什么情况下都能提升性能的，相反由于线程间的同步开销，甚至可能降低性能；只有像在JDBC操作或是SMTP之类的记录耗时比较长的情况下，使用异步入库方式才是个好选择。
PS:第一次写这么长的文章，欢迎大家指摘。