代码之家 › 专栏 › 技术社区 › hema chandra

为什么Log4j2需要额外的11毫秒才能写入文件?

log4j2 log4j logging java

-1

hema chandra · 技术社区 · 8 年前

我不熟悉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);
    }
}
}

我的日志4J2。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

您可以看到第一条语句记录在。205毫秒,第二条语句记录在。236毫秒。事实上,我正在休眠线程20毫秒,因此正确的时间戳应该是。226毫秒。我做错了什么?我需要准确的时间戳写,因为它是非常重要的生产。我也用log4j 1试过了,但结果是一样的。我还将我的系统时间与互联网时间同步。有一件事,我发现它在5毫秒和15毫秒的睡眠中效果很好,但从20毫秒开始,这就造成了一个大问题。

2 回复 | 直到 8 年前

jmehrens 8 年前

我做错了什么?

大多数有缺陷的假设和期望:

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

Remko Popma 8 年前

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

   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);
       }
   }

正如拉尔夫在 Log4j2-2141 ,很可能您正在运行Windows调度程序的粒度。看见 WinAPI Sleep() function call sleeps for longer than expected 和 https://forum.sysinternals.com/bug-in-waitable-timers_topic16229.html .