Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-2141

Log4j2 is taking an extra of 11 Milli seconds to write into the file?

    Details

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

      Windows 10
      Java SE 1.8
      NetBeans 8.2
      Log4j 2.9.1

    • Flags:
      Important

      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.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              Hemachandra hemachandra
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: