[
https://issues.apache.org/jira/browse/LOG4J2-2338?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16473481#comment-16473481
]
Remko Popma commented on LOG4J2-2338:
-------------------------------------
I can reproduce the issue, but it seems to have to do with the granularity of
the clock on the platform (JVM + OS).
On my laptop, with Windows 10, jdk-9.0.4 and Log4j 2.11, the following program:
{code}
public class Granularity {
public static void main(String[] args) {
Logger logger = LogManager.getLogger(Granularity.class);
for (int i = 0; i < 1000; i++) {
logger.info("entry {}: {}", i, Instant.now().getNano());
}
}
}
{code}
The above produces for following output:
{noformat}
22:04:26,140218100 [main] INFO test.Granularity - entry 0: 136207800
22:04:26,142223500 [main] INFO test.Granularity - entry 1: 142223500
22:04:26,143227000 [main] INFO test.Granularity - entry 2: 143227000
...
22:04:26,143227000 [main] INFO test.Granularity - entry 13: 143227000
22:04:26,144228400 [main] INFO test.Granularity - entry 14: 144228400
...
22:04:26,144228400 [main] INFO test.Granularity - entry 28: 144228400
22:04:26,145231600 [main] INFO test.Granularity - entry 29: 145231600
...
22:04:26,145231600 [main] INFO test.Granularity - entry 42: 145231600
22:04:26,149240900 [main] INFO test.Granularity - entry 43: 149240900
...
22:04:26,150244400 [main] INFO test.Granularity - entry 48: 149240900
22:04:26,150244400 [main] INFO test.Granularity - entry 49: 150244400
22:04:26,151246900 [main] INFO test.Granularity - entry 50: 151246900
...
22:04:26,151246900 [main] INFO test.Granularity - entry 62: 151246900
22:04:26,152249800 [main] INFO test.Granularity - entry 63: 152249800
...
22:04:26,152249800 [main] INFO test.Granularity - entry 75: 152249800
22:04:26,153253000 [main] INFO test.Granularity - entry 76: 153253000
...
22:04:26,153253000 [main] INFO test.Granularity - entry 90: 153253000
22:04:26,154255400 [main] INFO test.Granularity - entry 91: 154255400
...
22:04:26,154255400 [main] INFO test.Granularity - entry 102: 154255400
22:04:26,155258300 [main] INFO test.Granularity - entry 103: 155258300
...
22:04:26,156261100 [main] INFO test.Granularity - entry 119: 155258300
22:04:26,156261100 [main] INFO test.Granularity - entry 120: 156261100
...
22:04:26,156261100 [main] INFO test.Granularity - entry 128: 156261100
22:04:26,157263300 [main] INFO test.Granularity - entry 129: 157263300
...
{noformat}
So, the clock moves, but it moves in jumps of one millisecond plus change.
I can try to run this on Linux but it does not seem to be a Log4j issue...
> Micosecond, nano second level logging not working.
> --------------------------------------------------
>
> Key: LOG4J2-2338
> URL: https://issues.apache.org/jira/browse/LOG4J2-2338
> Project: Log4j 2
> Issue Type: Bug
> Environment: JRE10
> Reporter: Chetna Rustagi
> Priority: Critical
>
> Using JRE10 and log4j2, getting logs as :
> 12:42:05,972803200 [main] DEBUG Log4j2Test -Debug Message Logged!!!
> 12:42:05,975803200 [main] INFO Log4j2Test - Info Message Logged !!!
> 12:42:05,975803200 [main] ERROR Log4j2Test - Error Message Logged !!!
> micro and nanoseconds are always same : 803200
> Log4j2.xml looks like:
> {code}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration status="INFO">
> <Appenders>
> <Console name="console" target="SYSTEM_OUT">
> <PatternLayout pattern="%d{ABSOLUTE_NANOS} [%t] %-5level %logger{36} -
> %msg%n"/>
> <!-- <PatternLayout
> pattern="[%-5level] %d{ABSOLUTE_NANOS} [%t] %c{1} - %msg%n" /> -->
> </Console>
> </Appenders>
> <Loggers>
> <Root level="debug" additivity="false">
> <AppenderRef ref="console" />
> </Root>
> </Loggers>
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
