-1

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.

hema chandra
  • 402
  • 1
  • 8
  • 29

2 Answers2

2

What am I doing wrong here?

Mostly flawed assumptions and expectations:

  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. Trying to solve a realtime problem without using realtime software.
  6. Not accounting for code logging framework.
  7. Not accounting for appenders that perform I/O.
jmehrens
  • 10,580
  • 1
  • 38
  • 47
1

I don’t think that this is caused by logging. You can verify this by changing your test code to the below (to exclude the logging) and see if you are getting similar results:

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

As Ralph pointed out in Log4j2-2141, it is likely that you are running into the granularity of the Windows scheduler. See WinAPI Sleep() function call sleeps for longer than expected and https://forum.sysinternals.com/bug-in-waitable-timers_topic16229.html.

Remko Popma
  • 35,130
  • 11
  • 92
  • 114
  • I ran with sleeps of multiples of 5 that consists digit 5 at last (5,15,25,35) It is absolutely working fine. But when I use even numbers like 10,20 30 I am facing this problem. Need to research more. So do you have any idea that which Operating System is Real-Time? – hema chandra Dec 05 '17 at 04:49
  • There are “real-time” Linux versions (probably Windows versions also) that can give better guarantees about wait time. The trade off is usually reduced throughput. Most people give up on building programs around the assumption that it can wake up at a too granular interval, unless you really have hard or soft realtime requirements. Like airplanes or medical or military equipment. – Remko Popma Dec 05 '17 at 04:53