为什么 Log4j2 需要额外的 11 毫秒来写入文件？

Question

我是 Log4j2 的新手。我编写了一个简单的程序，它实际上使用 log4j2 将数据记录到 RollingRandomAccessFile 中。下面是程序：

public class Log4j2Example {

/**
 * @param args the command line arguments
 */
public static Logger mlogger = null;

public static void main(String[] args) throws InterruptedException {

    mlogger = LogManager.getLogger("Messages-log");
    int i = 0;
    while (true) {
        String str = "Hello" + i;
        System.out.println(str);
        mlogger.info(str);
        i++;
        Thread.sleep(20);
    }
}
}

我的 log4j2.xml 文件

    <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
  <Appenders>
     <RollingRandomAccessFile name="Messages-log" fileName="Log4J/Messages-${date:yyyy-MM-dd}.log"
               immediateflush="true" filePattern="Log4J/Messages-%d{MM-dd-yyyy-HH}-%i.log.gz">
      <PatternLayout>
        <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %p %m%n</Pattern>
      </PatternLayout>
      <Policies>
        <TimeBasedTriggeringPolicy />
        <SizeBasedTriggeringPolicy size="500 MB"/>
      </Policies>
      <DefaultRolloverStrategy max="50"/>
    </RollingRandomAccessFile>
  </Appenders>
  <Loggers>
    <Logger name="Messages-log" level="info" additivity="false">
        <appender-ref ref="Messages-log" level="info"/>
      </Logger>
    <root level="info">
        <appender-ref ref="Messages-log"/>
    </root>
</Loggers>
</Configuration>

我正在将一条简单的语句写入日志文件，每条记录休眠 20 毫秒。现在文件中的时间戳应该是例如： 如果第一个语句记录在 17:20:32:354，那么下一个语句应该记录在 17:20:32:374，但它记录在 17:20:32:384。每条记录都会持续增加额外的 11 毫秒。下面是我的日志文件输出

2017-12-04 17:40:42.205 INFO Hello11
2017-12-04 17:40:42.236 INFO Hello12
2017-12-04 17:40:42.268 INFO Hello13
2017-12-04 17:40:42.299 INFO Hello14
2017-12-04 17:40:42.330 INFO Hello15
2017-12-04 17:40:42.361 INFO Hello16
2017-12-04 17:40:42.393 INFO Hello17
2017-12-04 17:40:42.424 INFO Hello18

您可以看到第一条语句的记录时间为 0.205 毫秒，第二条语句的记录时间为 0.236 毫秒。事实上，我正在让线程休眠 20 毫秒，因此正确的时间戳应该是 0.226 毫秒。我在这里做错了什么？我需要编写确切的时间戳，因为它在生产中非常重要。我也用 log4j 1 试过这个，但结果相同。我也将我的系统时间与互联网时间同步。还有一件事我发现它在 5 毫秒和 15 毫秒的睡眠中非常有效，但是从 20 毫秒开始，这会导致一个大问题。

Answer 1

我在这里做错了什么？

大部分有缺陷的假设和期望：

1. Incorrect micro-benchmark.
2. Flawed assumption that System.currentTimeMillis has sufficient granularity.
3. Assuming Thread.sleep is accurate.
4. Assuming adjustments to the system clock won't change wake up time.
5. 尝试在不使用实时软件的情况下解决实时问题。
6. 不考虑代码日志框架。
7. 不考虑执行 I/O 的 appenders。

Answer 2

我不认为这是由日志记录引起的。您可以通过将测试代码更改为以下（以排除日志记录）来验证这一点，并查看您是否得到类似的结果：

   public static void main(String[] args) throws InterruptedException {
       SimpleDateFormat format = new SimpleDateFormat("HH:mm:ss.SSS");
       int i = 0;
       while (true) {
           System.out.println(format.format(new Date()) + " Hello " + i);
           i++;
           Thread.sleep(20);
       }
   }

正如 Ralph 在 Log4j2-2141 中指出的那样，您很可能遇到了 Windows 调度程序的粒度。请参阅WinAPI Sleep() function call sleeps for longer than expected 和https://forum.sysinternals.com/bug-in-waitable-timers_topic16229.html。