Warum benötigt Log4j2 11 Millisekunden, um in die Datei zu schreiben?

Question

Ich bin neu in Log4j2. Ich habe ein einfaches Programm geschrieben, das Daten mit Log4j2 in RollingRandomAccessFile protokolliert. Im Folgenden finden Sie das Programm:

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

Meine log4j2.xml Datei

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

ich eine einfache Anweisung in die Protokolldatei für 20 Milli-Sekunden für jeden Datensatz Schlafen schreibe. Nun sollte der Zeitstempel in der Datei zum Beispiel sein: Wenn die erste Anweisung bei 17: 20: 32: 354 protokolliert wird, sollte die nächste Anweisung um 17: 20: 32: 374 protokolliert werden, aber es wird um 17:20 protokolliert : 32: 384. Ein zusätzlicher Satz von 11 Millisekunden wird für jede Aufzeichnung hinzugefügt. Im Folgenden finden Sie Ausgabe meine Protokolldatei

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 

Sie, dass erste Aussage bei 0,205 Millisekunde und die zweite Anweisung wird protokolliert, sehen bei 0,236 Millisekunde angemeldet ist. Tatsächlich schließe ich den Thread für 20 Millisekunden, so dass der korrekte Zeitstempel 0,226 Millisekunden sein sollte. Was mache ich hier falsch? Ich brauche den genauen Zeitstempel, der geschrieben werden muss, da er in der Produktion sehr wichtig ist. Ich habe dies auch mit log4j 1 versucht, aber das gleiche Ergebnis. Ich habe meine Systemzeit auch mit der Internet-Zeit synchronisiert. Und eine Sache, die ich fand, funktionierte perfekt mit 5 und 15 Millisekunden Schlaf, aber aus 20 Millisekunden verursacht das ein großes Problem.

Answer 1

Ich glaube nicht, dass dies durch Protokollierung verursacht wird. Sie können dies überprüfen, indem Sie Ihre Test-Code an die unten zu wechseln (die Protokollierung auszuschließen) und sehen, ob Sie ähnliche Ergebnisse erhalten:

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

Wie Ralph in Log4j2-2141 wies darauf hin, es ist wahrscheinlich, dass Sie in die laufen Granularität des Windows-Schedulers. Siehe WinAPI Sleep() function call sleeps for longer than expected und https://forum.sysinternals.com/bug-in-waitable-timers_topic16229.html.

Answer 2

Was mache ich hier falsch?

Vorwiegend fehlerhafte Annahmen und Erwartungen:

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. Der Versuch, eine Echtzeit-Problem mit der Software ohne Verwendung von Echtzeit zu lösen.
6. Nicht für Code-Logging-Framework.
7. Nicht für appenders, die I/O durchführen.