log4j在多线程下的时间顺序准确吗？

Question

譬如下面的日志

    2018-03-01 15:20:36,201 [pool-2-thread-4] DEBUG - 填充用户组JT1000000100395的缓存 [TransactionHelper:31]
    2018-03-01 15:20:36,202 [pool-2-thread-4] DEBUG - 进入同步块 [TransactionHelper:34]
    2018-03-01 15:20:36,201 [pool-2-thread-5] DEBUG - 填充用户组JT1000000100395的缓存 [TransactionHelper:31]
    2018-03-01 15:20:36,201 [pool-2-thread-2] DEBUG - 填充用户组JT1000000100395的缓存 [TransactionHelper:31]
    2018-03-01 15:20:36,202 [pool-2-thread-5] DEBUG - 进入同步块 [TransactionHelper:34]
    2018-03-01 15:20:36,202 [pool-2-thread-1] DEBUG - 进入同步块 [TransactionHelper:34]
    2018-03-01 15:20:36,202 [pool-2-thread-2] DEBUG - 进入同步块 [TransactionHelper:34]
    2018-03-01 15:20:36,206 [pool-2-thread-5] INFO  - 白名单组加入 5 个号码[TransactionHelper:44]
    2018-03-01 15:20:36,207 [pool-2-thread-1] INFO  - 白名单组加入 5 个号码 [TransactionHelper:44]
    2018-03-01 15:20:36,207 [pool-2-thread-2] INFO  - 白名单组加入 5 个号码 [TransactionHelper:44]
    2018-03-01 15:20:36,206 [pool-2-thread-4]
    

线程之间的顺序是严格按照时间吗？ 譬如说这个 2018-03-01 15:20:36,206 [pool-2-thread-4] 肯定在 “2018-03-01 15:20:36,207 [pool-2-thread-2] INFO - 白名单组加入 5 个号码 ” 前面？

Answer 1

时间是LogEvent创建时间, 多线程时,写入的顺序可能与事件的创建时间不一致.

下面是我写的一个测试程序

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方法变慢. 对比两个结果, 可以看到发生时间和写出时间的差异.