log4j在多線程下的時間順序準確嗎？

時間是LogEvent創(chuàng)建時間, 多線程時,寫入的順序可能與事件的創(chuàng)建時間不一致.

下面是我寫的一個測試程序

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.junit.Test;

public class LogTest {
    final Log log = LogFactory.getLog(this.getClass());

    Object o = new Object() {
        public String toString() {
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            return "this is slow! " + System.currentTimeMillis();
        }
    };

    @Test
    public void testFIFO() throws InterruptedException {
         
            new Thread() {
                public void run() {
                    log.info(o);
                }
            }.start();
            
            Thread.sleep(100);
            
            new Thread() {
                public void run() {
                    log.info("this is fast! " + System.currentTimeMillis());
                }
            }.start();
            
            Thread.sleep(2000);

    }
    

    @Test
    public void testFILO() throws InterruptedException {
         
            new Thread() {
                public void run() {
                    log.info(o.toString());
                }
            }.start();
            
            Thread.sleep(100);
            
            new Thread() {
                public void run() {
                    log.info("this is fast! " + System.currentTimeMillis());
                }
            }.start();
            
            Thread.sleep(2000);

    }

}

這里用的是commons-logging 來間接使用Log4j. 原理上是一樣的

輸出如下:

FIFO

INFO  2018-03-02 12:43:26,846 LogTest$2:run - this is slow! 1519965807848
INFO  2018-03-02 12:43:26,946 LogTest$3:run - this is fast! 1519965806946

FILO

INFO  2018-03-02 12:43:29,048 LogTest$5:run - this is fast! 1519965809048
INFO  2018-03-02 12:43:29,948 LogTest$4:run - this is slow! 1519965809948

第一個測試和第二個不同在于一個(FILO)是 log.info(o.toString());, 一個(FIFO)是log.info(o);
我故意把toString方法變慢. 對比兩個結(jié)果, 可以看到發(fā)生時間和寫出時間的差異.