Skip to content

Commit ed007cf

Browse files
richardstartinrichardstartin
committed
JFR based timer
1 parent b174715 commit ed007cf

7 files changed

Lines changed: 149 additions & 32 deletions

File tree

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

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -42,4 +42,14 @@ public boolean setBaseLocation(String location) {
4242
}
4343
return true;
4444
}
45+
46+
@Override
47+
public long timestamp() {
48+
return JVM.counterTime();
49+
}
50+
51+
@Override
52+
public double toNanosConversionFactor() {
53+
return JVM.getJVM().getTimeConversionFactor();
54+
}
4555
}

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

Lines changed: 43 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -39,28 +39,43 @@ public JFRAccess create(Instrumentation inst) {
3939
private final Class<?> repositoryClass;
4040
private final Class<?> safePathClass;
4141

42+
// TODO consider refactoring to make these private static final
4243
private final MethodHandle setStackDepthMH;
4344
private final MethodHandle setRepositoryBaseMH;
4445

46+
private final MethodHandle counterTimeMH;
47+
private final MethodHandle getTimeConversionFactorMH;
48+
4549
public JPMSJFRAccess(Instrumentation inst) throws Exception {
4650
patchModuleAccess(inst);
4751

4852
jvmClass = JFRAccess.class.getClassLoader().loadClass("jdk.jfr.internal.JVM");
4953
repositoryClass = JFRAccess.class.getClassLoader().loadClass("jdk.jfr.internal.Repository");
5054
safePathClass =
5155
JFRAccess.class.getClassLoader().loadClass("jdk.jfr.internal.SecuritySupport$SafePath");
52-
setStackDepthMH = setStackDepthMethodHandle();
56+
Object jvm = getJvm();
57+
setStackDepthMH = getJvmMethodHandle(jvm, "setStackDepth", int.class);
5358
setRepositoryBaseMH = setRepositoryBaseMethodHandle();
59+
counterTimeMH = getJvmMethodHandle(jvm, "counterTime");
60+
getTimeConversionFactorMH = getJvmMethodHandle(jvm, "getTimeConversionFactor");
5461
}
5562

56-
private MethodHandle setStackDepthMethodHandle()
57-
throws NoSuchMethodException, IllegalAccessException, InvocationTargetException {
58-
Method m = jvmClass.getMethod("setStackDepth", int.class);
63+
private Object getJvm()
64+
throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {
65+
return jvmClass.getMethod("getJVM").invoke(null);
66+
}
67+
68+
private MethodHandle getJvmMethodHandle(Object jvm, String method, Class... args)
69+
throws NoSuchMethodException, IllegalAccessException {
70+
Method m = jvmClass.getMethod(method, args);
5971
m.setAccessible(true);
60-
MethodHandle mh = MethodHandles.publicLookup().unreflect(m);
61-
if (!Modifier.isStatic(m.getModifiers())) {
62-
// instance method - need to call JVM.getJVM() and bind the instance
63-
Object jvm = jvmClass.getMethod("getJVM").invoke(null);
72+
return unreflectAndBind(m, jvm);
73+
}
74+
75+
private static MethodHandle unreflectAndBind(Method method, Object jvm)
76+
throws IllegalAccessException {
77+
MethodHandle mh = MethodHandles.publicLookup().unreflect(method);
78+
if (!Modifier.isStatic(method.getModifiers())) {
6479
mh = mh.bindTo(jvm);
6580
}
6681
return mh;
@@ -119,4 +134,24 @@ public boolean setBaseLocation(String location) {
119134
}
120135
return false;
121136
}
137+
138+
@Override
139+
public long timestamp() {
140+
try {
141+
return (long) counterTimeMH.invokeExact();
142+
} catch (Throwable t) {
143+
log.debug("Unable to get TSC from JFR", t);
144+
}
145+
return super.timestamp();
146+
}
147+
148+
@Override
149+
public double toNanosConversionFactor() {
150+
try {
151+
return (double) getTimeConversionFactorMH.invokeExact();
152+
} catch (Throwable t) {
153+
log.debug("Unable to get time conversion factor from JFR", t);
154+
}
155+
return super.toNanosConversionFactor();
156+
}
122157
}

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
package com.datadog.profiling.controller.jfr;
22

3+
import com.datadog.profiling.utils.Timestamper;
34
import java.lang.instrument.Instrumentation;
45
import java.util.ServiceLoader;
56
import javax.annotation.Nullable;
@@ -11,7 +12,7 @@
1112
* Provides access to the JFR internal API. For Java 9 and newer, the JFR access requires
1213
* instrumentation in order to patch the module access.
1314
*/
14-
public abstract class JFRAccess {
15+
public abstract class JFRAccess implements Timestamper {
1516
private static final Logger log = LoggerFactory.getLogger(JFRAccess.class);
1617

1718
/** No-op JFR access implementation. */

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

Lines changed: 37 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -29,10 +29,12 @@
2929

3030
import com.datadog.profiling.controller.OngoingRecording;
3131
import com.datadog.profiling.utils.ProfilingMode;
32+
import com.datadog.profiling.utils.Timestamper;
3233
import com.datadoghq.profiler.ContextSetter;
3334
import com.datadoghq.profiler.JavaProfiler;
3435
import datadog.trace.api.profiling.RecordingData;
3536
import datadog.trace.bootstrap.config.provider.ConfigProvider;
37+
import datadog.trace.bootstrap.instrumentation.api.TaskWrapper;
3638
import java.io.IOException;
3739
import java.nio.file.Files;
3840
import java.nio.file.Path;
@@ -95,7 +97,7 @@ public static DatadogProfiler newInstance(ConfigProvider configProvider) {
9597

9698
private final List<String> orderedContextAttributes;
9799

98-
private final long queueTimeThreshold;
100+
private final double queueTimeThresholdNanos;
99101

100102
private DatadogProfiler(ConfigProvider configProvider) {
101103
this(configProvider, getContextAttributes(configProvider));
@@ -132,10 +134,11 @@ private DatadogProfiler(ConfigProvider configProvider) {
132134
orderedContextAttributes.add(RESOURCE);
133135
}
134136
this.contextSetter = new ContextSetter(profiler, orderedContextAttributes);
135-
this.queueTimeThreshold =
136-
configProvider.getLong(
137-
PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS,
138-
PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS_DEFAULT);
137+
this.queueTimeThresholdNanos =
138+
1_000_000D
139+
* configProvider.getLong(
140+
PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS,
141+
PROFILING_QUEUEING_TIME_THRESHOLD_MILLIS_DEFAULT);
139142
}
140143

141144
void addThread() {
@@ -374,6 +377,34 @@ public void recordSetting(String name, String value, String unit) {
374377
}
375378

376379
public QueueTimeTracker newQueueTimeTracker() {
377-
return new QueueTimeTracker(profiler, queueTimeThreshold);
380+
return new QueueTimeTracker(this, timestamper().timestamp());
381+
}
382+
383+
void recordQueueTimeEvent(long startTicks, Object task, Class<?> scheduler, Thread origin) {
384+
if (profiler != null) {
385+
Timestamper timestamper = timestamper();
386+
long endTicks = timestamper.timestamp();
387+
double durationNanos = timestamper.toNanosConversionFactor() * (endTicks - startTicks);
388+
if (durationNanos >= queueTimeThresholdNanos) {
389+
// note: because this type traversal can update secondary_super_cache (see JDK-8180450)
390+
// we avoid doing this unless we are absolutely certain we will record the event
391+
Class<?> taskType = TaskWrapper.getUnwrappedType(task);
392+
if (taskType != null) {
393+
profiler.recordQueueTime(startTicks, endTicks, taskType, scheduler, origin);
394+
}
395+
}
396+
}
397+
}
398+
399+
private Timestamper timestamper() {
400+
// FIXME intended to be injectable, but still a singleton for currently pragmatic reasons.
401+
// We need a way to make the Controller responsible for creating the context integration
402+
// for the tracer, which also allows the context integration to be constant in the tracer,
403+
// as well as allowing for the various late initialisation needs for JFR on certain JDK
404+
// versions
405+
// note that this access does not risk using the default version so long as queue time is
406+
// guarded
407+
// by checking if JFR is ready (this currently happens in QueueTimeHelper, so this is safe)
408+
return Timestamper.timestamper();
378409
}
379410
}

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

Lines changed: 7 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -1,25 +1,23 @@
11
package com.datadog.profiling.ddprof;
22

3-
import com.datadoghq.profiler.JavaProfiler;
43
import datadog.trace.api.profiling.QueueTiming;
5-
import datadog.trace.bootstrap.instrumentation.api.TaskWrapper;
64
import java.lang.ref.WeakReference;
75

86
public class QueueTimeTracker implements QueueTiming {
97

10-
private final JavaProfiler profiler;
8+
private final DatadogProfiler profiler;
119
private final Thread origin;
12-
private final long threshold;
1310
private final long startTicks;
1411
private WeakReference<Object> weakTask;
12+
// FIXME this can be eliminated by altering the instrumentation
13+
// since it is known when the item is polled from the queue
1514
private Class<?> scheduler;
1615

17-
public QueueTimeTracker(JavaProfiler profiler, long threshold) {
16+
public QueueTimeTracker(DatadogProfiler profiler, long startTicks) {
1817
this.profiler = profiler;
1918
this.origin = Thread.currentThread();
20-
this.threshold = threshold;
2119
// TODO get this from JFR if available instead of making a JNI call
22-
this.startTicks = profiler.getCurrentTicks();
20+
this.startTicks = startTicks;
2321
}
2422

2523
@Override
@@ -37,16 +35,8 @@ public void close() {
3735
assert weakTask != null && scheduler != null;
3836
Object task = this.weakTask.get();
3937
if (task != null) {
40-
// potentially avoidable JNI call
41-
long endTicks = profiler.getCurrentTicks();
42-
if (profiler.isThresholdExceeded(threshold, startTicks, endTicks)) {
43-
// note: because this type traversal can update secondary_super_cache (see JDK-8180450)
44-
// we avoid doing this unless we are absolutely certain we will record the event
45-
Class<?> taskType = TaskWrapper.getUnwrappedType(task);
46-
if (taskType != null) {
47-
profiler.recordQueueTime(startTicks, endTicks, taskType, scheduler, origin);
48-
}
49-
}
38+
// indirection reduces shallow size of the tracker instance
39+
profiler.recordQueueTimeEvent(startTicks, task, scheduler, origin);
5040
}
5141
}
5242
}

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

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,48 @@
1+
package com.datadog.profiling.utils;
2+
3+
import java.util.concurrent.atomic.AtomicReferenceFieldUpdater;
4+
5+
public interface Timestamper {
6+
7+
Timestamper DEFAULT = new Timestamper() {};
8+
9+
default long timestamp() {
10+
return System.nanoTime();
11+
}
12+
13+
default double toNanosConversionFactor() {
14+
return 1D;
15+
}
16+
17+
final class Registration {
18+
volatile Timestamper pending = Timestamper.DEFAULT;
19+
private static final AtomicReferenceFieldUpdater<Registration, Timestamper> UPDATER =
20+
AtomicReferenceFieldUpdater.newUpdater(Registration.class, Timestamper.class, "pending");
21+
22+
private static final Registration INSTANCE = new Registration();
23+
}
24+
25+
/**
26+
* One shot chance to override the timestamper, which allows delayed initialisation of the
27+
* timestamp source.
28+
*
29+
* @return whether override was successful
30+
*/
31+
static boolean override(Timestamper timestamper) {
32+
return Registration.UPDATER.compareAndSet(
33+
Registration.INSTANCE, Timestamper.DEFAULT, timestamper);
34+
}
35+
36+
final class Singleton {
37+
//
38+
static final Timestamper TIMESTAMPER = Registration.INSTANCE.pending;
39+
}
40+
41+
/**
42+
* Gets the registered timestamper (e.g. using JFR) if one has been registered, otherwise uses the
43+
* default timer.
44+
*/
45+
static Timestamper timestamper() {
46+
return Singleton.TIMESTAMPER;
47+
}
48+
}

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

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111
import com.datadog.profiling.controller.UnsupportedEnvironmentException;
1212
import com.datadog.profiling.controller.jfr.JFRAccess;
1313
import com.datadog.profiling.uploader.ProfileUploader;
14+
import com.datadog.profiling.utils.Timestamper;
1415
import datadog.trace.api.Config;
1516
import datadog.trace.api.Platform;
1617
import datadog.trace.api.config.ProfilingConfig;
@@ -117,6 +118,7 @@ public static synchronized void run(
117118

118119
try {
119120
JFRAccess.setup(inst);
121+
Timestamper.override(JFRAccess.instance());
120122
ControllerContext context = new ControllerContext();
121123
final Controller controller = CompositeController.build(configProvider, context);
122124

0 commit comments

Comments
 (0)