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 밀리 초에 기록됩니다. 사실 나는 올바른 타임 스탬프가 .226 밀리 초이어야하므로 20 밀리 초 동안 스레드를 자고 있습니다. 여기서 내가 뭘 잘못하고 있니? 프로덕션에서 매우 중요하므로 정확한 타임 스탬프가 필요합니다. 나는 log4j 1에서도 같은 결과를 시도했다. 시스템 시간을 인터넷 시간과 동기화했습니다. 그리고 내가 찾은 한가지는 5 밀리 초의 수면 상태에서 완벽하게 작동했지만 20 밀리 초에서 이것은 큰 문제를 일으키는 것입니다.

Answer 1

로깅으로 인한 것 같지 않습니다. 당신은 (로깅을 제외) 아래에 테스트 코드를 변경하여이를 확인하고 비슷한 결과를 얻는 경우에 볼 수 있습니다

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을 참조하십시오.

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을 고려하지 않습니다.