[LOG4J2-2141] Log4j2 is taking an extra of 11 Milli seconds to write into the file?

• Type: Question
• Status: Closed
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 2.9.1
• Fix Version/s: 2.9.1
• Component/s: Core
• Labels: easyfix newbie

Environment

Windows 10
Java SE 1.8
NetBeans 8.2
Log4j 2.9.1

• Flags: Important
• Assignee: Unassigned
• Reporter: hemachandra
• Created: 04/Dec/17 14:21
• Updated: 19/Feb/18 05:43
• Resolved: 19/Feb/18 05:42

Description

I am new to Log4j2. I have written a simple program that actually logs data into RollingRandomAccessFile using log4j2. Below is the program:

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

*My log4j2.xml file*

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

I am writing a simple statement into the log file sleeping for 20 milli-seconds for every record. Now the time stamp in the file should be for example:
If the first statement is logged at 17:20:32:354 then the next statement should be logged at 17:20:32:374 but it is logging at 17:20:32:384. An extra of 11 milli-seconds constantly is added for every record. Below is my log file output

    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

You can see that first statement is logged at .205 milli second and the second statement is logged at .236 milli second. Infact I am sleeping the thread for 20 milliseconds so the correct timestamp should be .226 milli second. What am I doing wrong here? I need the exact time stamp to be written as it is very important in production. I have also tried this with log4j 1 but the same result. I have synchronized my System time with Internet time also. And one thing I found it worked perfectly with 5 and 15 milli-seconds of sleep but from 20 milli seconds this is causing a big issue.