Negative durations?

[David Holmes - Sun Microsystems]

Possible problems depend on the OS, as the elapsed_counter used 
underneath these "timings" is totally different on each platform:

Solaris: uses gethrtime() via getTimeNanos() which has code to ensure 
the returned value is monotonic even if gethrtime() is not (it should be 
but it has had bugs due to TSC usage on x86 MP systems). So negative 
values should not been seen on Solaris, but you might see zero values.

Linux: uses gettimeofday() - so if you have a bad clock and are running 
(x)ntpd then you might see lots of adjustments that cause apparent 
negative intervals. I don't recall if gettimeofday can be subject to TSC 
problems, but you might try booting with the notsc boot option. (It all 
depends on which Linux kernel version you have.)

Windows: uses QueryPerformanceCounter if available, else 
GetSystemTimeAsFileTime. If QPC is used then you need to ensure Windows 
is using a stable time source for your platform eg. not using the TSC on 
MP systems; and not using the TSC if you have "speed-step" or equivalent 
dynamic CPU frequency adjusting mechanisms. Add /usepmtimer to the boot 
options in boot.ini to avoid TSC use. I don't know what problems 
GetSystemTimeAsFileTime might encounter - I suspect it would be 
susceptible to NTP adjustments as well.

(For gory details of clocks and timers on Windows see: 
http://blogs.sun.com/dholmes/entry/inside_the_hotspot_vm_clocks)

Cheers,
David Holmes

Y.S.Ramakrishna at Sun.COM said the following on  4/01/08 09:56 AM:
> If on windows, you could try disabling NTP sync to see if
> the "problem" goes away... Cross-posting to the runtime
> list for possible further comment.
> 
> You clearly see time-stamps also stepping back (for example
> between line n-1 and n-2 below).
> 
> -- ramki
> 
> Keith Holdaway wrote:
>> I have Google'd, but found no explanation for negative GC pauses:
>>
>> 8829.092: [GC 426933K->375154K(517760K), 0.0117606 secs]
>> 8830.373: [GC 427634K->376403K(517760K), 0.0833584 secs]
>> 8830.569: [GC 428883K->377941K(517760K), -0.6576383 secs]
>> 8831.110: [GC 430421K->379175K(517760K), 0.0161026 secs]
>> 8831.548: [GC 431628K->379968K(517760K), 0.0134666 secs]
>> 8831.942: [GC 432448K->379701K(517760K), -0.1804611 secs]
>> 8832.718: [GC 432180K->382348K(517760K), 0.0836352 secs]
>> 8832.303: [GC 434828K->382927K(517760K), 0.6898266 secs]
>> 8833.482: [GC 435407K->384775K(517760K), -0.1111267 secs]
>>
>>
>> Keith R Holdaway
>> Java Development Technologies
>>
>> SAS...  The Power to Know
>>
>> Carpe Diem ...
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>