JFR based timer

dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java/com/datadog/profiling/controller/jfr/SimpleJFRAccess.java

@@ -42,4 +42,14 @@ public boolean setBaseLocation(String location) {
     }
     return true;
   }
+
+  @Override
+  public long timestamp() {
+    return JVM.counterTime();
+  }
+
+  @Override
+  public double toNanosConversionFactor() {
+    return JVM.getJVM().getTimeConversionFactor();
+  }
 }

dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java11/com/datadog/profiling/controller/jfr/JPMSJFRAccess.java

@@ -39,28 +39,43 @@ public JFRAccess create(Instrumentation inst) {
   private final Class<?> repositoryClass;
   private final Class<?> safePathClass;
 
+  // TODO consider refactoring to make these private static final
   private final MethodHandle setStackDepthMH;
   private final MethodHandle setRepositoryBaseMH;
 
+  private final MethodHandle counterTimeMH;
+  private final MethodHandle getTimeConversionFactorMH;
+
   public JPMSJFRAccess(Instrumentation inst) throws Exception {
     patchModuleAccess(inst);
 
     jvmClass = JFRAccess.class.getClassLoader().loadClass("jdk.jfr.internal.JVM");
     repositoryClass = JFRAccess.class.getClassLoader().loadClass("jdk.jfr.internal.Repository");
     safePathClass =
         JFRAccess.class.getClassLoader().loadClass("jdk.jfr.internal.SecuritySupport$SafePath");
-    setStackDepthMH = setStackDepthMethodHandle();
+    Object jvm = getJvm();
+    setStackDepthMH = getJvmMethodHandle(jvm, "setStackDepth", int.class);
     setRepositoryBaseMH = setRepositoryBaseMethodHandle();
+    counterTimeMH = getJvmMethodHandle(jvm, "counterTime");
+    getTimeConversionFactorMH = getJvmMethodHandle(jvm, "getTimeConversionFactor");
   }
 
-  private MethodHandle setStackDepthMethodHandle()
-      throws NoSuchMethodException, IllegalAccessException, InvocationTargetException {
-    Method m = jvmClass.getMethod("setStackDepth", int.class);
+  private Object getJvm()
+      throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {
+    return jvmClass.getMethod("getJVM").invoke(null);
+  }
+
+  private MethodHandle getJvmMethodHandle(Object jvm, String method, Class... args)
+      throws NoSuchMethodException, IllegalAccessException {
+    Method m = jvmClass.getMethod(method, args);
     m.setAccessible(true);
-    MethodHandle mh = MethodHandles.publicLookup().unreflect(m);
-    if (!Modifier.isStatic(m.getModifiers())) {
-      // instance method - need to call JVM.getJVM() and bind the instance
-      Object jvm = jvmClass.getMethod("getJVM").invoke(null);
+    return unreflectAndBind(m, jvm);
+  }
+
+  private static MethodHandle unreflectAndBind(Method method, Object jvm)
+      throws IllegalAccessException {
+    MethodHandle mh = MethodHandles.publicLookup().unreflect(method);
+    if (!Modifier.isStatic(method.getModifiers())) {
       mh = mh.bindTo(jvm);
     }
     return mh;
@@ -119,4 +134,24 @@ public boolean setBaseLocation(String location) {
     }
     return false;
   }
+
+  @Override
+  public long timestamp() {
+    try {
+      return (long) counterTimeMH.invokeExact();
+    } catch (Throwable t) {
+      log.debug("Unable to get TSC from JFR", t);
+    }
+    return super.timestamp();
+  }
+
+  @Override
+  public double toNanosConversionFactor() {
+    try {
+      return (double) getTimeConversionFactorMH.invokeExact();
+    } catch (Throwable t) {
+      log.debug("Unable to get time conversion factor from JFR", t);
+    }
+    return super.toNanosConversionFactor();
+  }
 }

dd-java-agent/agent-profiling/profiling-controller-jfr/src/main/java/com/datadog/profiling/controller/jfr/JFRAccess.java

@@ -1,5 +1,6 @@
 package com.datadog.profiling.controller.jfr;
 
+import com.datadog.profiling.utils.Timestamper;
 import java.lang.instrument.Instrumentation;
 import java.util.ServiceLoader;
 import javax.annotation.Nullable;
@@ -11,7 +12,7 @@
  * Provides access to the JFR internal API. For Java 9 and newer, the JFR access requires
  * instrumentation in order to patch the module access.
  */
-public abstract class JFRAccess {
+public abstract class JFRAccess implements Timestamper {
   private static final Logger log = LoggerFactory.getLogger(JFRAccess.class);
 
   /** No-op JFR access implementation. */

dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/DatadogProfiler.java

@@ -29,10 +29,12 @@
 
 import com.datadog.profiling.controller.OngoingRecording;
 import com.datadog.profiling.utils.ProfilingMode;
+import com.datadog.profiling.utils.Timestamper;
 import com.datadoghq.profiler.ContextSetter;
 import com.datadoghq.profiler.JavaProfiler;
 import datadog.trace.api.profiling.RecordingData;
 import datadog.trace.bootstrap.config.provider.ConfigProvider;
+import datadog.trace.bootstrap.instrumentation.api.TaskWrapper;
 import java.io.IOException;
 import java.nio.file.Files;
 import java.nio.file.Path;
@@ -95,7 +97,7 @@ public static DatadogProfiler newInstance(ConfigProvider configProvider) {
 
   private final List<String> orderedContextAttributes;
 
-  private final long queueTimeThreshold;
+  private final double queueTimeThresholdNanos;
 
   private DatadogProfiler(ConfigProvider configProvider) {
     this(configProvider, getContextAttributes(configProvider));
@@ -132,10 +134,11 @@ private DatadogProfiler(ConfigProvider configProvider) {
       orderedContextAttributes.add(RESOURCE);
     }
     this.contextSetter = new ContextSetter(profiler, orderedContextAttributes);
-    this.queueTimeThreshold =
-        configProvider.getLong(
-            PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS,
-            PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS_DEFAULT);
+    this.queueTimeThresholdNanos =
+        1_000_000D
+            * configProvider.getLong(
+                PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS,
+                PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS_DEFAULT);
   }
 
   void addThread() {
@@ -374,6 +377,34 @@ public void recordSetting(String name, String value, String unit) {
   }
 
   public QueueTimeTracker newQueueTimeTracker() {
-    return new QueueTimeTracker(profiler, queueTimeThreshold);
+    return new QueueTimeTracker(this, timestamper().timestamp());
+  }
+
+  void recordQueueTimeEvent(long startTicks, Object task, Class<?> scheduler, Thread origin) {
+    if (profiler != null) {
+      Timestamper timestamper = timestamper();
+      long endTicks = timestamper.timestamp();
+      double durationNanos = timestamper.toNanosConversionFactor() * (endTicks - startTicks);
+      if (durationNanos >= queueTimeThresholdNanos) {
+        // note: because this type traversal can update secondary_super_cache (see JDK-8180450)
+        // we avoid doing this unless we are absolutely certain we will record the event
+        Class<?> taskType = TaskWrapper.getUnwrappedType(task);
+        if (taskType != null) {
+          profiler.recordQueueTime(startTicks, endTicks, taskType, scheduler, origin);
+        }
+      }
+    }
+  }
+
+  private Timestamper timestamper() {
+    // FIXME intended to be injectable, but still a singleton for currently pragmatic reasons.
+    //  We need a way to make the Controller responsible for creating the context integration
+    //  for the tracer, which also allows the context integration to be constant in the tracer,
+    //  as well as allowing for the various late initialisation needs for JFR on certain JDK
+    // versions
+    // note that this access does not risk using the default version so long as queue time is
+    // guarded
+    // by checking if JFR is ready (this currently happens in QueueTimeHelper, so this is safe)
+    return Timestamper.timestamper();
   }
 }

dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/QueueTimeTracker.java

@@ -1,25 +1,23 @@
 package com.datadog.profiling.ddprof;
 
-import com.datadoghq.profiler.JavaProfiler;
 import datadog.trace.api.profiling.QueueTiming;
-import datadog.trace.bootstrap.instrumentation.api.TaskWrapper;
 import java.lang.ref.WeakReference;
 
 public class QueueTimeTracker implements QueueTiming {
 
-  private final JavaProfiler profiler;
+  private final DatadogProfiler profiler;
   private final Thread origin;
-  private final long threshold;
   private final long startTicks;
   private WeakReference<Object> weakTask;
+  // FIXME this can be eliminated by altering the instrumentation
+  //  since it is known when the item is polled from the queue
   private Class<?> scheduler;
 
-  public QueueTimeTracker(JavaProfiler profiler, long threshold) {
+  public QueueTimeTracker(DatadogProfiler profiler, long startTicks) {
     this.profiler = profiler;
     this.origin = Thread.currentThread();
-    this.threshold = threshold;
     // TODO get this from JFR if available instead of making a JNI call
-    this.startTicks = profiler.getCurrentTicks();
+    this.startTicks = startTicks;
   }
 
   @Override
@@ -37,16 +35,8 @@ public void close() {
     assert weakTask != null && scheduler != null;
     Object task = this.weakTask.get();
     if (task != null) {
-      // potentially avoidable JNI call
-      long endTicks = profiler.getCurrentTicks();
-      if (profiler.isThresholdExceeded(threshold, startTicks, endTicks)) {
-        // note: because this type traversal can update secondary_super_cache (see JDK-8180450)
-        // we avoid doing this unless we are absolutely certain we will record the event
-        Class<?> taskType = TaskWrapper.getUnwrappedType(task);
-        if (taskType != null) {
-          profiler.recordQueueTime(startTicks, endTicks, taskType, scheduler, origin);
-        }
-      }
+      // indirection reduces shallow size of the tracker instance
+      profiler.recordQueueTimeEvent(startTicks, task, scheduler, origin);
     }
   }
 }

dd-java-agent/agent-profiling/profiling-utils/src/main/java/com/datadog/profiling/utils/Timestamper.java

@@ -0,0 +1,48 @@
+package com.datadog.profiling.utils;
+
+import java.util.concurrent.atomic.AtomicReferenceFieldUpdater;
+
+public interface Timestamper {
+
+  Timestamper DEFAULT = new Timestamper() {};
+
+  default long timestamp() {
+    return System.nanoTime();
+  }
+
+  default double toNanosConversionFactor() {
+    return 1D;
+  }
+
+  final class Registration {
+    volatile Timestamper pending = Timestamper.DEFAULT;
+    private static final AtomicReferenceFieldUpdater<Registration, Timestamper> UPDATER =
+        AtomicReferenceFieldUpdater.newUpdater(Registration.class, Timestamper.class, "pending");
+
+    private static final Registration INSTANCE = new Registration();
+  }
+
+  /**
+   * One shot chance to override the timestamper, which allows delayed initialisation of the
+   * timestamp source.
+   *
+   * @return whether override was successful
+   */
+  static boolean override(Timestamper timestamper) {
+    return Registration.UPDATER.compareAndSet(
+        Registration.INSTANCE, Timestamper.DEFAULT, timestamper);
+  }
+
+  final class Singleton {
+    //
+    static final Timestamper TIMESTAMPER = Registration.INSTANCE.pending;
+  }
+
+  /**
+   * Gets the registered timestamper (e.g. using JFR) if one has been registered, otherwise uses the
+   * default timer.
+   */
+  static Timestamper timestamper() {
+    return Singleton.TIMESTAMPER;
+  }
+}

dd-java-agent/agent-profiling/src/main/java/com/datadog/profiling/agent/ProfilingAgent.java

@@ -11,6 +11,7 @@
 import com.datadog.profiling.controller.UnsupportedEnvironmentException;
 import com.datadog.profiling.controller.jfr.JFRAccess;
 import com.datadog.profiling.uploader.ProfileUploader;
+import com.datadog.profiling.utils.Timestamper;
 import datadog.trace.api.Config;
 import datadog.trace.api.Platform;
 import datadog.trace.api.config.ProfilingConfig;
@@ -117,6 +118,7 @@ public static synchronized void run(
 
       try {
         JFRAccess.setup(inst);
+        Timestamper.override(JFRAccess.instance());
         ControllerContext context = new ControllerContext();
         final Controller controller = CompositeController.build(configProvider, context);