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?



    • Question
    • Status: Closed
    • Critical
    • Resolution: Fixed
    • 2.9.1
    • 2.9.1
    • Core
    • Windows 10
      Java SE 1.8
      NetBeans 8.2
      Log4j 2.9.1

    • Important


      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;

      *My log4j2.xml file*

              <?xml version="1.0" encoding="UTF-8"?>
          <Configuration status="warn">
               <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">
                  <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %p %m%n</Pattern>
                  <TimeBasedTriggeringPolicy />
                  <SizeBasedTriggeringPolicy size="500 MB"/>
                <DefaultRolloverStrategy max="50"/>
              <Logger name="Messages-log" level="info" additivity="false">
                  <appender-ref ref="Messages-log" level="info"/>
              <root level="info">
                  <appender-ref ref="Messages-log"/>

      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.




            Unassigned Unassigned
            Hemachandra hemachandra
            0 Vote for this issue
            4 Start watching this issue