Bug ID: JDK-8191415 Times reported for events seem incorrect

Type: Bug
Component: hotspot
Sub-Component: jfr
Affected Version: 9

Priority: P3
Status: Closed
Resolution: Won't Fix

Submitted: 2017-11-16
Updated: 2021-09-27
Resolved: 2020-01-28

There seems to be a difference in timestamps between jfr and gc-logging for some event(s?). At first this was believed to be an issue in JMC but when verifying this by means of the JDK reference parser this seems to be either jfr or gc-logging reporting the wrong timestamp.
The original bug reported on JMC (JMC-5643) holds logs, recordings and a description of the issue.

I experience the same problem with up-to-date JDK 17. All JFR timestamps and durations are off by 7-8% from the real time. Here is a simple test case, which just sleeps for 100 seconds: public class Test { public static void main(String[] args) throws Exception { long startTime = System.nanoTime(); Thread.sleep(100_000); long endTime = System.nanoTime(); System.out.println("Slept for " + (endTime - startTime) / 1e9 + " seconds"); } } The program expectedly prints Slept for 100.0009663 seconds However, the JFR event claims the sleep duration is 108 seconds: java -XX:StartFlightRecording=filename=test.jfr Test jdk.ThreadSleep { startTime = 22:26:39.656 duration = 1 m 48 s time = 1 m 40 s eventThread = "main" (javaThreadId = 1) stackTrace = [ java.lang.Thread.sleep(long) Test.main(String[]) line: 4 ] } The problem is that the JVM incorrectly computes TSC frequency: jdk.CPUTimeStampCounter { startTime = 22:26:39.649 fastTimeEnabled = true fastTimeAutoEnabled = true osFrequency = 10000000 Hz fastTimeFrequency = 2700000000 Hz } Here JFR tick frequency is 2.7GHz, while the actual value of kernel tsc_khz is 2903997 (2.9 GHz). JVM obtains frequency from the CPU model name, and this is apparently wrong: $ cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 142 model name : Intel(R) Core(TM) i7-7500U CPU @ 2.70GHz stepping : 9 microcode : 0xea cpu MHz : 2904.002 cache size : 4096 KB physical id : 0 siblings : 1 core id : 0 cpu cores : 1 apicid : 0 initial apicid : 0 fpu : yes fpu_exception : yes cpuid level : 22 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon nopl xtopology tsc_reliable nonstop_tsc cpuid pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch cpuid_fault invpcid_single pti ssbd ibrs ibpb stibp fsgsbase tsc_adjust bmi1 avx2 smep bmi2 invpcid mpx rdseed adx smap clflushopt xsaveopt xsavec xsaves arat md_clear flush_l1d arch_capabilities bugs : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds swapgs bogomips : 5808.00 clflush size : 64 cache_alignment : 64 address sizes : 43 bits physical, 48 bits virtual power management: Adding -XX:+UnlockExperimentalVMOptions -XX:-UseFastUnorderedTimeStamps fixes the problem. I believe, JVM should not choose RDTSC for timestamps by default if it cannot reliably determine TSC frequency.
27-09-2021
Runtime Triage: This is not on our current list of priorities. We will consider this feature if we receive additional customer requirements.
28-01-2020
Most likely related to fasttime (rdtsc()) unordered timestamps. GC logging does not use fasttime. A test could be to investigate if the issue can be reproduced by using the same clock source as GC logging: -XX:+UnlockExperimentalVMOptions -XX:-UseFastUnorderedTimeStamps Note that this will have higher overhead from a performance perspective.
11-01-2018
Maybe [~stefank] could try to reproduce this with those options?
11-01-2018