Log4j优化（一）扩展Log4j来实现性能优化的异步日志收集器

日志收集在互联网企业尤其是大数据时代是一件非常重要的事情，日志记录着用户行为和系统行为，是一种重要的数据来源。Log4j是Java应用程序使用的最多的一种日志收集工作。目前大量的Java应用程序都使用着Lo4j 1.2.X版本，Log4j 1.X版本饱受诟病的原因是使用了大量的锁，在高并发的情况下影响了系统的性能。这篇简单提供一种思路，说说如何扩展一下Log4j，提升一下Log4j的性能。

网上有很多分析Log4j源码的文章，这里不重复说了，只简单分析一下最重要的几个组件。

先看一下Log4j的配置文件log4j.xml

[java] view plain copy

1. <?xml version="1.0" encoding="UTF-8" ?>  
2. <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">  
3.   
4. <log4j:configuration xmlns:log4j="http://jakarta./log4j/">  
5.     <appender name="rootAppender" class="org.apache.log4j.DailyRollingFileAppender">  
6.         <param name="File" value="test.log" />  
7.         <param name="DatePattern" value="'.'yyyy-MM-dd" />  
8.         <layout class="org.apache.log4j.PatternLayout">  
9.             <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %5p %c{1}:%L - %m%n" />  
10.         </layout>  
11.     </appender>  
12.     <logger name="com.test" additivity="false">  
13.         <level value="debug" />  
14.         <appender-ref ref="rootAppender" />  
15.     </logger>  
16.     <root>  
17.         <level value="debug" />  
18.         <appender-ref ref="rootAppender" />  
19.     </root>  
20. </log4j:configuration>  

从log4j.xml里面我们就可以看到Log4j最主要的几个组件

1. Logger，表示日志收集器，包含了各种Level下收集日志的方法，比如debug, info, error等。Logger的一个重要属性是additivity，表示是否附加到父Logger。Logger被设置成单根的树形结构，根就是Root，收集日志时，可以从叶子Logger一直往上直到Root。

Logger还包含了level表示级别，包含了一个appender列表，一个Logger可以对应多个Appender

2. Appender，表示如何处理日志，可以写本地文件，可以写远程文件，也可以输出到消息队列，等等。最常见的场景就是写本地文件。写文件的抽象是WriterAppender，封装了一个过滤器流QuietWriter。既然是过滤器流，那么可以包装节点流，默认的就是FileOutputStream流。Log4j也支持Buffer流，在WriterAppender的子类FileAppender里面有bufferedIO属性，如果采用Buffer流，就会在FileOutputStream外包一层BufferedWriter，最后在包到QuietWriter中。

[java] view plain copy

1. public  
2.  synchronized  
3.  void setFile(String fileName, boolean append, boolean bufferedIO, int bufferSize)  
4.                                                            throws IOException {  
5.    LogLog.debug("setFile called: "+fileName+", "+append);  
6.   
7.    if(bufferedIO) {  
8.      setImmediateFlush(false);  
9.    }  
10.   
11.    reset();  
12.    FileOutputStream ostream = null;  
13.    try {  
14.          ostream = new FileOutputStream(fileName, append);  
15.    } catch(FileNotFoundException ex) {  
16.          String parentName = new File(fileName).getParent();  
17.          if (parentName != null) {  
18.             File parentDir = new File(parentName);  
19.             if(!parentDir.exists() && parentDir.mkdirs()) {  
20.                ostream = new FileOutputStream(fileName, append);  
21.             } else {  
22.                throw ex;  
23.             }  
24.          } else {  
25.             throw ex;  
26.          }  
27.    }  
28.    Writer fw = createWriter(ostream);  
29.    if(bufferedIO) {  
30.      fw = new BufferedWriter(fw, bufferSize);  
31.    }  
32.    this.setQWForFiles(fw);  
33.    this.fileName = fileName;  
34.    this.fileAppend = append;  
35.    this.bufferedIO = bufferedIO;  
36.    this.bufferSize = bufferSize;  
37.    writeHeader();  
38.    LogLog.debug("setFile ended");  
39.  }  

关于Appender，尤其是基于文件的FileAppender，一定要理解，一个FileAppender实例表示的是一个打开文件对象，在计算机底层知识拾遗（四）理解文件系统 中我们说了从Linux的角度来说，open调用就创建了一个打开文件对象，并返回了一个文件描述符，其他系统调用都用文件描述符来引用这个打开文件对象。打开文件对象包含了当前的读写位置，文件长度等等。 而在Java中并没有提供open操作，在Java中，new一个FileInputStream/FileOutputStream实例表示创建了一个打开文件对象。FileInputStream/FileOutputStream维护着当前的读写位置，还维护了文件描述符FileDescriptor对象和FileChannel对象。随便提一下，日志收集操作基本上都是对文件的Append，FileOutputStream支持文件的append打开方式。

可以看到， new一个FileOutputStream会创建一个FileDescriptor对象，并支持open和openAppend方式。这和Linux的open系统调用完成的功能是一样的。

[java] view plain copy

1. public  
2. class FileOutputStream extends OutputStream  
3. {  
4.     /** 
5.      * The system dependent file descriptor. The value is 
6.      * 1 more than actual file descriptor. This means that 
7.      * the default value 0 indicates that the file is not open. 
8.      */  
9.     private FileDescriptor fd;  
10.   
11.     private FileChannel channel= null;  
12.   
13.     private boolean append = false;  
14.   
15.    public FileOutputStream(File file, boolean append)  
16.         throws FileNotFoundException  
17.     {  
18.         String name = (file != null ? file.getPath() : null);  
19.     SecurityManager security = System.getSecurityManager();  
20.     if (security != null) {  
21.         security.checkWrite(name);  
22.     }  
23.         if (name == null) {  
24.             throw new NullPointerException();  
25.         }  
26.     fd = new FileDescriptor();  
27.         fd.incrementAndGetUseCount();  
28.         this.append = append;  
29.     if (append) {  
30.         openAppend(name);  
31.     } else {  
32.         open(name);  
33.     }  
34.     }  
35. }  

理解了一个FileOutputStream对象实例表示了一个打开文件之后，我们再来看一下操作系统内部为进程维护运行时文件数据结构的图。可以看到文件描述符指向了打开文件对象，打开文件对象又指向了inode对象，inode对象代表了一个文件在操作系统中的实例。

对于Java来说，JVM采用了单进程多线程的方式来支持并发，进程打开的所有文件对象对所有线程都是共享的。既然是共享，就涉及到多线程并发安全问题。在这里涉及到到3个地方存在并发安全问题。

1. 一个new FileOutputStream对象表示一个打开文件对象。那么当多个线程使用同一个FileOutputStream对象写文件时，就需要进行同步操作。

2. 当多个线程new了多个FileOutputStream对象对同一个文件进行写操作时，会出现并发问题，写入的顺序和位置都是不确定的。这种情况比较难同步，因为多个FileOutputStream对象是分散的，难以加锁。尽量避免这样写文件。当然也有解决方案，比如采用集中的地方来对外提供FileOutputStream对象，使用文件锁对inode对象加锁等等。

3. 当有另外的JVM进程对同一个文件进行操作时。这种情况只能通过加文件锁的方式来解决

Java提供了文件锁的支持，FileChannel提供了lock方法，并返回一个FileLock对象。

对于Log4j的使用场景，肯定是多线程并发的情况。第3种情况不用考虑。第二种情况比较复杂，所以只有第一种情况是适合的。Log4j也是采用了这一种方式。

可以把一个FileAppender对象理解成维护了一个打开文件对象，当Logger在多线程情况下把日志写入文件时，需要对Appender进行同步，也就是说对Logger加锁，保证使用同一个Logger对象时，一次只有一个线程使用这个FileAppender来写文件，避免了多线程情况下写文件错误。

就是下面这两段代码进行的同步操作，但是这也是Log4j被诟病最多的地方

[java] view plain copy

1. Hierarchy.java   
2.   
3. // 多个线程使用同一个Logger时，加锁  
4.   
5. public  
6.   void callAppenders(LoggingEvent event) {  
7.     int writes = 0;  
8.   
9.     for(Category c = this; c != null; c=c.parent) {  
10.       // Protected against simultaneous call to addAppender, removeAppender,...  
11.       synchronized(c) {  
12.     if(c.aai != null) {  
13.       writes += c.aai.appendLoopOnAppenders(event);  
14.     }  
15.     if(!c.additive) {  
16.       break;  
17.     }  
18.       }  
19.     }  
20.   
21.     if(writes == 0) {  
22.       repository.emitNoAppenderWarning(this);  
23.     }  
24.   }  
25.   
26.   
27. AppenderSkeleton.java  
28.   
29. // 多个线程使用同一个Appender时，对Appender加锁  
30.   
31.   public  
32.   synchronized   
33.   void doAppend(LoggingEvent event) {  
34.     if(closed) {  
35.       LogLog.error("Attempted to append to closed appender named ["+name+"].");  
36.       return;  
37.     }  
38.       
39.     if(!isAsSevereAsThreshold(event.getLevel())) {  
40.       return;  
41.     }  
42.   
43.     Filter f = this.headFilter;  
44.       
45.     FILTER_LOOP:  
46.     while(f != null) {  
47.       switch(f.decide(event)) {  
48.       case Filter.DENY: return;  
49.       case Filter.ACCEPT: break FILTER_LOOP;  
50.       case Filter.NEUTRAL: f = f.getNext();  
51.       }  
52.     }  
53.       
54.     this.append(event);      
55.   }  

这几个锁在高并发的情况下对系统的性能影响很大，会阻塞掉业务进程。而日志收集工作应该是作为一个辅助功能，不能影响主业务功能。

所以可以考虑从几个方面对Log4j进行扩展

1. 同步操作改异步操作，将对业务线程的影响减到最小。比如使用一个缓冲队列，Logger.debug操作只将LoggingEvent放入缓冲队列就结束，然后用单独的线程做消费者去消费缓冲队列

2. 使用阻塞队列来做缓冲，可以用基于数组的有界队列的，内存可控，但是在高并发下可能会阻塞生产者线程，也可以用基于链表的无界队列，用内存空间换性能

3. 消费这个缓冲队列时，可以持续消费，也可以采用定时批量消费的方式。持续消费就是使用一个无限循环的线程，只要缓冲队列不空，就从队列中取LoggingEvent来写文件。由于FileAppender维护了一个打开的FileOutputStream对象实例，不会重复执行打开文件操作，也就是说只打开一次，然后一直写，性能也可以接受。

定时批量消费就是采用一个定时的线程，一个时间段消费一次，一次消费一批数据。

Log4j本身就提供一个AsyncAppender类来异步收集日志。

1. 它采用阻塞式的有界缓冲队列，但是没有采用基于管城的BlockingQueue，而是使用了普通的ArrayList，并结合条件队列操作wait, notifty来实现阻塞队列。默认容量是128个LoggingEvent

2. 包含了一个AppenderAttachableImpl，这是一个Appender的列表结构，可以包含多个Appender

3. 使用了Dispatcher线程来做消费者

4. 消费者采用持续消费的方式，只要缓冲队列不为空，就唤醒消费者，先将buffer填充到一个数组中，然后单独对这个数组消费，buffer可以继续给生产者使用。

[java] view plain copy

1. public class AsyncAppender extends AppenderSkeleton  
2.   implements AppenderAttachable {  
3.     
4.   public static final int DEFAULT_BUFFER_SIZE = 128；  
5.   private final List buffer = new ArrayList();   
6.   private final Map discardMap = new HashMap();  
7.   private int bufferSize = DEFAULT_BUFFER_SIZE;  
8.   /** Nested appenders. */  
9.   AppenderAttachableImpl aai;  
10.    
11.   private final AppenderAttachableImpl appenders;  
12.   
13.   public AsyncAppender() {  
14.     appenders = new AppenderAttachableImpl();  
15.     aai = appenders;  
16.   
17.     dispatcher =  
18.       new Thread(new Dispatcher(this, buffer, discardMap, appenders));  
19.     dispatcher.setDaemon(true);  
20.     dispatcher.setName("AsyncAppender-Dispatcher-" + dispatcher.getName());  
21.     dispatcher.start();  
22.   }  
23.   
24. private static class Dispatcher implements Runnable {  
25.     private final AsyncAppender parent;  
26.     private final List buffer;  
27.     private final Map discardMap;  
28.     private final AppenderAttachableImpl appenders;  
29.   
30. }  

AsyncAppender的代码比较老，可以使用ArrayBlockingQueue对其进行改写，减少条件队列的操作。也可以进一步优化，采用无界的LinkedBlockingQueue，采用空间换性能的方式，这样不会阻塞生产者线程，也就是不阻塞业务线程。只有当LinedBlockingQueue为空时才会阻塞消费线程。这是可以接受的，因为消费线程不是业务线程，也防止了消费线程的空转。

还可以使用定时批量处理的生产者消费者模式来异步处理线程，下面是一个简单的基于定时线程池的定时批量异步日志收集器实现

1. 使用ScheduledExecutorService 定时线程池

2. 使用LinkedBlockingQueue无界阻塞队列做缓冲，不会阻塞生产者线程

3. 定时执行Dispatcher线程，每次把缓冲队列填充到一个局部的列表，只对局部列表中的数据处理，缓冲队列可以继续被生产者使用

4. appenders上的锁是防止添加删除appender时出并发问题，实际上Logger一旦创建，很少会在运行时取修改appenders，所以这个锁基本没有影响

[java] view plain copy

1. import java.util.ArrayList;  
2. import java.util.Enumeration;  
3. import java.util.List;  
4. import java.util.concurrent.Executors;  
5. import java.util.concurrent.LinkedBlockingQueue;  
6. import java.util.concurrent.ScheduledExecutorService;  
7. import java.util.concurrent.TimeUnit;  
8.   
9. import org.apache.log4j.Appender;  
10. import org.apache.log4j.AppenderSkeleton;  
11. import org.apache.log4j.helpers.AppenderAttachableImpl;  
12. import org.apache.log4j.spi.AppenderAttachable;  
13. import org.apache.log4j.spi.LoggingEvent;  
14.   
15. public class ScheduledAsyncAppender extends AppenderSkeleton implements  
16.         AppenderAttachable {  
17.   
18.     private final AppenderAttachableImpl appenders;  
19.   
20.     protected final ScheduledExecutorService executorService;  
21.   
22.     protected final LinkedBlockingQueue<LoggingEvent> queue;  
23.   
24.     protected long initialDelay;  
25.   
26.     protected long period;  
27.   
28.     protected TimeUnit unit;  
29.   
30.     public ScheduledAsyncAppender(long initialDelay, long period, TimeUnit unit) {  
31.         this.initialDelay = initialDelay;  
32.         this.period = period;  
33.         this.unit = unit;  
34.         appenders = new AppenderAttachableImpl();  
35.         // 初始化线程池  
36.         executorService = Executors.newScheduledThreadPool(1);  
37.         queue = new LinkedBlockingQueue<LoggingEvent>();  
38.         executorService.scheduleWithFixedDelay(new Dispatcher(), initialDelay,  
39.                 period, unit);  
40.     }  
41.   
42.     /** 
43.      * 生产者线程只把LoggingEvent加入阻塞队列就返回，由于是无界队列，所以生产者线程不会阻塞，不影响业务 
44.      * */  
45.     @Override  
46.     protected void append(LoggingEvent event) {  
47.         try {  
48.             queue.put(event);  
49.         } catch (InterruptedException e) {  
50.             // if producer interrupted, do nothing  
51.         }  
52.     }  
53.   
54.     @Override  
55.     public void close() {  
56.         executorService.shutdown();  
57.   
58.         synchronized (appenders) {  
59.             Enumeration iter = appenders.getAllAppenders();  
60.             if (iter != null) {  
61.                 while (iter.hasMoreElements()) {  
62.                     Object next = iter.nextElement();  
63.   
64.                     if (next instanceof Appender) {  
65.                         ((Appender) next).close();  
66.                     }  
67.                 }  
68.             }  
69.         }  
70.     }  
71.   
72.     private class Dispatcher implements Runnable {  
73.   
74.         @Override  
75.         public void run() {  
76.             List<LoggingEvent> logCache = new ArrayList<LoggingEvent>();  
77.             queue.drainTo(logCache);  
78.             for (LoggingEvent event : logCache) {  
79.                 synchronized (appenders) {  
80.                     appenders.appendLoopOnAppenders(event);  
81.                 }  
82.             }  
83.         }  
84.   
85.     }  
86.   
87.     @Override  
88.     public void addAppender(final Appender newAppender) {  
89.         synchronized (appenders) {  
90.             appenders.addAppender(newAppender);  
91.         }  
92.     }  
93.   
94.     @Override  
95.     public Enumeration getAllAppenders() {  
96.         synchronized (appenders) {  
97.             return appenders.getAllAppenders();  
98.         }  
99.     }  
100.   
101.     @Override  
102.     public Appender getAppender(final String name) {  
103.         synchronized (appenders) {  
104.             return appenders.getAppender(name);  
105.         }  
106.     }  
107.   
108.     @Override  
109.     public boolean isAttached(final Appender appender) {  
110.         synchronized (appenders) {  
111.             return appenders.isAttached(appender);  
112.         }  
113.     }  
114.   
115.     @Override  
116.     public void removeAllAppenders() {  
117.         synchronized (appenders) {  
118.             appenders.removeAllAppenders();  
119.         }  
120.     }  
121.   
122.     @Override  
123.     public void removeAppender(final Appender appender) {  
124.         synchronized (appenders) {  
125.             appenders.removeAppender(appender);  
126.         }  
127.     }  
128.   
129.     @Override  
130.     public void removeAppender(final String name) {  
131.         synchronized (appenders) {  
132.             appenders.removeAppender(name);  
133.         }  
134.     }  
135.   
136.     @Override  
137.     public boolean requiresLayout() {  
138.         return false;  
139.     }  
140.   
141. }  

具体采用持续消费，还是定时批量消费，可以根据实际情况进行选择。定时批量消费时还可以优化，比如先把批量的日志日志变成一个大日志，一次只写一次文件文件，减少写文件的次数。

最后看一下如何运行时创建Logger，而不是使用log4j.xml配置文件的方式

[java] view plain copy

1. static{  
2.     Layout patternLayout = new PatternLayout();  
3.     Appender appender = null;  
4.     String fileName = Configuration.getInstance().getLogFileName();  
5.     try {  
6.         appender = new DailyRollingFileAppender(patternLayout, fileName, "'.'yyyy-MM-dd");  
7.     } catch (IOException e) {  
8.         e.printStackTrace();  
9.     }  
10.     log.addAppender(rtracerAppender);  
11.     log.setLevel(Level.DEBUG);  
12.     log.setAdditivity(false);  
13. }