From ed007cfa3f876897a07fc635a4c4e38fd77fdc73 Mon Sep 17 00:00:00 2001 From: Richard Startin Date: Fri, 8 Mar 2024 13:26:48 +0000 Subject: [PATCH] JFR based timer --- .../controller/jfr/SimpleJFRAccess.java | 10 ++++ .../controller/jfr/JPMSJFRAccess.java | 51 ++++++++++++++++--- .../profiling/controller/jfr/JFRAccess.java | 3 +- .../profiling/ddprof/DatadogProfiler.java | 43 +++++++++++++--- .../profiling/ddprof/QueueTimeTracker.java | 24 +++------ .../datadog/profiling/utils/Timestamper.java | 48 +++++++++++++++++ .../profiling/agent/ProfilingAgent.java | 2 + 7 files changed, 149 insertions(+), 32 deletions(-) create mode 100644 dd-java-agent/agent-profiling/profiling-utils/src/main/java/com/datadog/profiling/utils/Timestamper.java diff --git a/dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java/com/datadog/profiling/controller/jfr/SimpleJFRAccess.java b/dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java/com/datadog/profiling/controller/jfr/SimpleJFRAccess.java index 6b19b05544f..95ea50d41af 100644 --- a/dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java/com/datadog/profiling/controller/jfr/SimpleJFRAccess.java +++ b/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(); + } } diff --git a/dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java11/com/datadog/profiling/controller/jfr/JPMSJFRAccess.java b/dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java11/com/datadog/profiling/controller/jfr/JPMSJFRAccess.java index 52ee3707fef..03690412043 100644 --- a/dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java11/com/datadog/profiling/controller/jfr/JPMSJFRAccess.java +++ b/dd-java-agent/agent-profiling/profiling-controller-jfr/implementation/src/main/java11/com/datadog/profiling/controller/jfr/JPMSJFRAccess.java @@ -39,9 +39,13 @@ 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); @@ -49,18 +53,29 @@ public JPMSJFRAccess(Instrumentation inst) throws Exception { 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(); + } } diff --git a/dd-java-agent/agent-profiling/profiling-controller-jfr/src/main/java/com/datadog/profiling/controller/jfr/JFRAccess.java b/dd-java-agent/agent-profiling/profiling-controller-jfr/src/main/java/com/datadog/profiling/controller/jfr/JFRAccess.java index 1b417cf3c94..92f51a009ef 100644 --- a/dd-java-agent/agent-profiling/profiling-controller-jfr/src/main/java/com/datadog/profiling/controller/jfr/JFRAccess.java +++ b/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. */ diff --git a/dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/DatadogProfiler.java b/dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/DatadogProfiler.java index d9271359279..7e676095aab 100644 --- a/dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/DatadogProfiler.java +++ b/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 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(); } } diff --git a/dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/QueueTimeTracker.java b/dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/QueueTimeTracker.java index cf7ac164347..c4915ba1326 100644 --- a/dd-java-agent/agent-profiling/profiling-ddprof/src/main/java/com/datadog/profiling/ddprof/QueueTimeTracker.java +++ b/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 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); } } } diff --git a/dd-java-agent/agent-profiling/profiling-utils/src/main/java/com/datadog/profiling/utils/Timestamper.java b/dd-java-agent/agent-profiling/profiling-utils/src/main/java/com/datadog/profiling/utils/Timestamper.java new file mode 100644 index 00000000000..24da6779d5d --- /dev/null +++ b/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 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; + } +} diff --git a/dd-java-agent/agent-profiling/src/main/java/com/datadog/profiling/agent/ProfilingAgent.java b/dd-java-agent/agent-profiling/src/main/java/com/datadog/profiling/agent/ProfilingAgent.java index 20e607adf74..ef04453b990 100644 --- a/dd-java-agent/agent-profiling/src/main/java/com/datadog/profiling/agent/ProfilingAgent.java +++ b/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);