Skip to main content

System.nanoTime() on Solaris/AMD64 returns huge value and doesn't increase

1 reply [Last post]
neighbour
Offline
Joined: 2007-11-27
Points: 0

The result of System.nanoTime() on Solaris/AMD64 returns unexpectedly huge value and then doesn't increase.
Also in the gc.log there is a huge application time (176670 seconds which is 2 days) and then all the times are zeros:

: 65408K->0K(65472K), 0.0882915 secs] 109804K->108186K(2097088K), 0.0884087 secs] [Times: user=0.20 sys=0.06, real=0.09 secs]
Total time for which application threads were stopped: 0.0888438 seconds
Application time: 0.5105322 seconds
Total time for which application threads were stopped: 0.0003030 seconds
Application time: 1.7103498 seconds
6.636: [GC 6.636: [ParNew
Desired survivor size 32768 bytes, new threshold 0 (max 0)
: 65408K->0K(65472K), 0.0884198 secs] 173594K->165912K(2097088K), 0.0885425 secs] [Times: user=0.21 sys=0.06, real=0.09 secs]
Total time for which application threads were stopped: 0.0889200 seconds
Application time: 176670.4304176 seconds
176677.155: [GC 176677.155: [ParNew
Desired survivor size 32768 bytes, new threshold 0 (max 0)
: 65408K->0K(65472K), 0.0000000 secs] 231320K->225092K(2097088K), 0.0000000 secs] [Times: user=0.22 sys=0.07, real=0.00 secs]
Total time for which application threads were stopped: 0.0000000 seconds
Application time: 0.0000000 seconds
176677.155: [GC 176677.155: [ParNew
Desired survivor size 32768 bytes, new threshold 0 (max 0)
: 65408K->0K(65472K), 0.0000000 secs] 290500K->287448K(2097088K), 0.0000000 secs] [Times: user=0.21 sys=0.06, real=0.00 secs]
Total time for which application threads were stopped: 0.0000000 seconds

It looks like the JVM bug http://bugs.sun.com/view_bug.do?bug_id=6596720,
but this bug is marked as a duplicate of Solaris bug http://bugs.opensolaris.org/bugdatabase/view_bug.do?bug_id=6600939
which is stated as fixed in the solaris_10u6(s10u6_01).

My Solaris version (SunOS 5.10 Generic_137138-09) is greater than the version of this fix, it contains this patch, but the bug is still there.

There is one more serious impact of this bug apart from gc.log mess and timers failures: when such a spike in nanoTime occurs,
JGroups transport doesn't work anymore - its threads are stalled in a state of waiting of some acknowledges that never arrive.

The environment is:

java version "1.6.0_13"
SunOS x2001 5.10 Generic_137138-09 i86pc i386 i86pc
x2200 M2, AMD Opteron 2356 2 CPU x Quad-Core 2312 MHz, 16 GB RAM

Steps to reproduce the bug:
1) Run the attached test application (bin/test-nano-time.sh) on Solaris/AMD64 platform.
2) Immediately the bug should be reproduced with the message
"
[3] Nanotime splash found in 422743 iterations, 1963 milliseconds. Diff : 175857420098648
[9] Nanotime reports same value for 202 milliseconds.
"

Here is a part of source code:

SOURCE -------------------------------------------------
long testStartTime = System.currentTimeMillis();
long previousValue = System.nanoTime();

long sameValueStartTime = testStartTime;
int sameValueCount = 0;
for(long iteration = 0; sameValueCount < MAX_SAME_VALUE_FOUND; iteration++) {
long newValue = System.nanoTime();
long diff = newValue - previousValue;
if (diff > 100l * 1000000000l) {
System.out.println("[" + threadNumber + "] Nanotime splash found in " + iteration + " iterations, "
+ (System.currentTimeMillis() - testStartTime) + " milliseconds. Diff : " + diff);
}
if (newValue == previousValue) {
sameValueCount++;
} else {
sameValueCount = 0;
sameValueStartTime = System.currentTimeMillis();
}
previousValue = newValue;
}

System.out.println("[" + threadNumber + "] Nanotime reports same value for " +
(System.currentTimeMillis() - sameValueStartTime) + " milliseconds.");
/SOURCE -------------------------------------------------

There are also environment details and logs in the folder "log" of the attached zip.

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
neighbour
Offline
Joined: 2007-11-27
Points: 0

After applying the latest Solaris release from May 2009 "Kernel version: SunOS 5.10 Generic_139556-08, Solaris 10 5/09 s10x_u7wos_08 X86", the bug is not reproduced any longer.