Timing Differences Between JFR and GC Logs

[Kim Barrett]

> On Aug 15, 2020, at 3:48 PM, Kim Barrett <kim.barrett at oracle.com> wrote:
> 
>> On Aug 14, 2020, at 6:09 PM, Ana Marsh <t-maana at microsoft.com> wrote:
>> 
>> Hi everyone,
>> 
>> My name is Ana Marsh and I am interning at Microsoft on the Java Engineering Team (under Martijn Verburg) and this summer I have been diving into JFR in the JVM and analyzing how it gathers information on garbage collection events. I have noticed over the past two months of digging that the start time of a garbage collection event returned by JFR varies widely from the start time of the same event given with Unified Logging. I decided to explore this further by looking at the specifics of OpenJDK code and found some interesting points to highlight.
>> 
>> 
>> […]
>> 
>> For JFR files, the start time is set to the RDTSC value while in GC logs it uses the OS clock as it prints out the log. This is obviously a further point of concern for timing differences, so I wanted to see how much of a contrast there was in the times these clocks reported.
>> 
>> […]
>> Observations on Results:
>> Both ElapsedCounterSource (OS) and FastUnorderedElapsedCounterSource (RDTSC) have their own way of determining seconds so there could be some issues in there as well. Additionally in this example the clocks are not being set instantaneously causing some numbers to be off, however at the beginning of my test the OS clock ends up reporting a later time even though it is called first. Over time though RDTSC seems to begin reporting later times. Overall these clocks get far very off, in degrees of seconds which seems big in the clock world.
>> 
>> Any insight or thoughts on this matter would be helpful. Thank you!
> 
> What you are seeing is the result of a lot of history and struggles
> with the time subsystems provided by various platforms.  Search JBS
> for JDK issues with the label "time" for an idea of that history.

It seems the behavior you are describing already has a reported bug:

https://bugs.openjdk.java.net/browse/JDK-8191415

I’m disappointed that it’s been resolved as won’t fix.  I think I’m going to have
to go argue with some folks over that resolution.