なぜLog4j2はファイルに書き込むのに11ミリ秒余分にかかるのですか？

Question

Log4j2の新機能です。私はlog4j2を使って実際にデータをRollingRandomAccessFileに記録する簡単なプログラムを書いています。私はすべてのレコードのために20ミリ秒間スリープログファイルに簡単な文を書いています

<?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> 

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ファイル：下記のプログラムです。今すぐファイルのタイムスタンプは： 最初のステートメントが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ミリ秒間スレッドをスリープ状態にしているので、正しいタイムスタンプは226ミリ秒にする必要があります。私はここで間違って何をしていますか？私は生産時に非常に重要なので、正確なタイムスタンプが必要です。私もlog4j 1でこれを試しましたが、同じ結果です。システム時刻とインターネット時刻も同期させています。そして私がそれを見つけたのは、5秒と15ミリ秒の睡眠で完璧に動作しましたが、20ミリ秒からこれは大きな問題を引き起こしています。

Answer 1

これはロギングによるものではないと思います。ラルフはLog4j2-2141で指摘したように、あなたがに実行されている可能性があり

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

：あなたは以下にテストコードを変更することでこれを確認（ログを除外するために）、あなたが同様の結果を得ているかどうかを確認することができますWindowsスケジューラの粒度。 WinAPI Sleep() function call sleeps for longer than expectedおよびhttps://forum.sysinternals.com/bug-in-waitable-timers_topic16229.htmlを参照してください。

Answer 2

私はここで間違っていますか？

主に欠陥のある仮定と期待：リアルタイムソフトウェアを使用せずに、リアルタイムの問題を解決しようとすると

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を考慮しません。