[
https://issues.apache.org/jira/browse/LOG4J2-2141?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Remko Popma updated LOG4J2-2141:
--------------------------------
Description:
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.
was:
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.
> 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)
