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

["Remko Popma (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-2141?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16276933#comment-16276933 ] 

Remko Popma commented on LOG4J2-2141:
-------------------------------------

Please also try without Log4j and see if you get the same result:

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

Does this show a similar result?

> Log4j2 is taking an extra of 11 Milli seconds to write into the file?
> ---------------------------------------------------------------------
>
>                 Key: LOG4J2-2141
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2141
>             Project: Log4j 2
>          Issue Type: Question
>          Components: Core
>    Affects Versions: 2.9.1
>         Environment: Windows 10
> Java SE 1.8
> NetBeans 8.2
> Log4j 2.9.1
>            Reporter: hemachandra
>            Priority: Critical
>              Labels: easyfix, newbie
>
> I am new to Log4j2. I have written a simple program that actually logs data into RollingRandomAccessFile using log4j2. Below is the program:
> {code}
>     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);
>         }
>     }
>     }
> {code}
> **My log4j2.xml file**
> {code}
>         <?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>
> {code}
> 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 
> {noformat}
>     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
> {noformat}
> 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.



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)