From 4d0d36e29ebd063b6938b8ae41b025f7a82f9da8 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 9 Apr 2020 19:16:17 +0200 Subject: [PATCH 01/18] Initial implementation of thread cpu time per scope --- .../java/datadog/trace/bootstrap/Agent.java | 30 +++++++++++++++---- .../opentracing/jfr/openjdk/ScopeEvent.java | 11 +++++++ .../jfr/openjdk/ThreadCpuTime.java | 16 ++++++++++ 3 files changed, 52 insertions(+), 5 deletions(-) create mode 100644 dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index 2ffc541f6e6..4b33574c556 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java @@ -72,9 +72,9 @@ public static void start(final Instrumentation inst, final URL bootstrapURL) { */ if (appUsingCustomLogManager) { log.debug("Custom logger detected. Delaying JMXFetch initialization."); - registerLogManagerCallback(new StartJmxFetchCallback(bootstrapURL)); + registerLogManagerCallback(new StartJmxCallback(bootstrapURL)); } else { - startJmxFetch(bootstrapURL); + startJmx(bootstrapURL); } /* @@ -151,8 +151,8 @@ public void run() { public abstract void execute(); } - protected static class StartJmxFetchCallback extends ClassLoadCallBack { - StartJmxFetchCallback(final URL bootstrapURL) { + protected static class StartJmxCallback extends ClassLoadCallBack { + StartJmxCallback(final URL bootstrapURL) { super(bootstrapURL); } @@ -163,7 +163,7 @@ public String getName() { @Override public void execute() { - startJmxFetch(bootstrapURL); + startJmx(bootstrapURL); } } @@ -262,6 +262,26 @@ private static synchronized void installDatadogTracer() { } } + private static synchronized void initializeScopeThreadCpuTime() { + if (AGENT_CLASSLOADER == null) { + throw new IllegalStateException("Datadog agent should have been started already"); + } + try { + final Class threadCpuTimeClass = + AGENT_CLASSLOADER.loadClass("datadog.trace.agent.ot.jfr.openjdk.ThreadCpuTime"); + final Method initializeMethod = threadCpuTimeClass.getDeclaredMethod("initialize"); + initializeMethod.setAccessible(true); + initializeMethod.invoke(null); + } catch (final Throwable ex) { + log.error("Throwable thrown while initializing the Scope thread cpu time access", ex); + } + } + + private static void startJmx(final URL bootstrapURL) { + startJmxFetch(bootstrapURL); + initializeScopeThreadCpuTime(); + } + private static synchronized void startJmxFetch(final URL bootstrapURL) { if (JMXFETCH_CLASSLOADER == null) { final ClassLoader contextLoader = Thread.currentThread().getContextClassLoader(); diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java index cdefad81eaf..702dc33c8fe 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java @@ -8,6 +8,7 @@ import jdk.jfr.Label; import jdk.jfr.Name; import jdk.jfr.StackTrace; +import jdk.jfr.Timespan; @Name("datadog.Scope") @Label("Scope") @@ -38,6 +39,12 @@ public final class ScopeEvent extends Event implements DDScopeEvent { @Label("Operation Name") private String operationName; + @Label("Thread CPU Time") + @Timespan + private long cpuTime = 0L; + + private long startCpuTime; + ScopeEvent(final DDSpanContext spanContext) { this.spanContext = spanContext; } @@ -46,12 +53,16 @@ public final class ScopeEvent extends Event implements DDScopeEvent { public void start() { if (isEnabled()) { begin(); + startCpuTime = ThreadCpuTime.get(); } } @Override public void finish() { end(); + if (startCpuTime > 0) { + cpuTime = ThreadCpuTime.get() - startCpuTime; + } if (shouldCommit()) { traceId = spanContext.getTraceId().toString(IDS_RADIX); spanId = spanContext.getSpanId().toString(IDS_RADIX); diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java new file mode 100644 index 00000000000..289bb5382d7 --- /dev/null +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java @@ -0,0 +1,16 @@ +package datadog.opentracing.jfr.openjdk; + +import java.lang.management.ManagementFactory; +import java.util.function.Supplier; + +public class ThreadCpuTime { + private static volatile Supplier CPU_TIME_PROVIDER; + + static void initialize() { + CPU_TIME_PROVIDER = ManagementFactory.getThreadMXBean()::getCurrentThreadCpuTime; + } + + static long get() { + return CPU_TIME_PROVIDER == null ? Long.MIN_VALUE : CPU_TIME_PROVIDER.get(); + } +} From 9bd8d1499b048f8e5dc9b34068e261406f670f9f Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 9 Apr 2020 20:55:21 +0200 Subject: [PATCH 02/18] Play nicely also with JVMs eagerly resolving constant pool symbols --- .../main/java/datadog/trace/bootstrap/Agent.java | 14 ++++++++++++-- .../opentracing/jfr/openjdk/ThreadCpuTime.java | 15 +++++++++------ 2 files changed, 21 insertions(+), 8 deletions(-) diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index 4b33574c556..ef5ba99dd00 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java @@ -1,10 +1,14 @@ package datadog.trace.bootstrap; import java.lang.instrument.Instrumentation; +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadMXBean; import java.lang.reflect.Constructor; import java.lang.reflect.InvocationTargetException; import java.lang.reflect.Method; import java.net.URL; +import java.util.concurrent.Callable; + import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -269,9 +273,15 @@ private static synchronized void initializeScopeThreadCpuTime() { try { final Class threadCpuTimeClass = AGENT_CLASSLOADER.loadClass("datadog.trace.agent.ot.jfr.openjdk.ThreadCpuTime"); - final Method initializeMethod = threadCpuTimeClass.getDeclaredMethod("initialize"); + final Method initializeMethod = threadCpuTimeClass.getDeclaredMethod("initialize", Callable.class); + final ThreadMXBean mxBean = ManagementFactory.getThreadMXBean(); initializeMethod.setAccessible(true); - initializeMethod.invoke(null); + initializeMethod.invoke(null, new Callable() { + @Override + public Long call() throws Exception { + return mxBean.getCurrentThreadCpuTime(); + } + }); } catch (final Throwable ex) { log.error("Throwable thrown while initializing the Scope thread cpu time access", ex); } diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java index 289bb5382d7..a4d0029574f 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java @@ -1,16 +1,19 @@ package datadog.opentracing.jfr.openjdk; -import java.lang.management.ManagementFactory; -import java.util.function.Supplier; +import java.util.concurrent.Callable; public class ThreadCpuTime { - private static volatile Supplier CPU_TIME_PROVIDER; + private static volatile Callable CPU_TIME_PROVIDER; - static void initialize() { - CPU_TIME_PROVIDER = ManagementFactory.getThreadMXBean()::getCurrentThreadCpuTime; + // must use Callable here since initialization is invoked from Agent which needs to be Java 7 compatible + static void initialize(Callable provider) { + CPU_TIME_PROVIDER = provider; } static long get() { - return CPU_TIME_PROVIDER == null ? Long.MIN_VALUE : CPU_TIME_PROVIDER.get(); + try { + return CPU_TIME_PROVIDER == null ? Long.MIN_VALUE : CPU_TIME_PROVIDER.call(); + } catch (Exception ignored) {} + return Long.MIN_VALUE; } } From c9dad48a893bb758e9f6feb8535d76e42aa35611 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Tue, 14 Apr 2020 14:16:50 +0200 Subject: [PATCH 03/18] Do not include the time spent in handling ThreadCpuTime in event duration --- .../main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java index 702dc33c8fe..1d50d5e01b0 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java @@ -52,8 +52,8 @@ public final class ScopeEvent extends Event implements DDScopeEvent { @Override public void start() { if (isEnabled()) { - begin(); startCpuTime = ThreadCpuTime.get(); + begin(); } } From 1511296fec73d5d367dcd6ad0ea13af25e63db90 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Tue, 14 Apr 2020 14:45:44 +0200 Subject: [PATCH 04/18] Do not use extra field in event --- .../datadog/opentracing/jfr/openjdk/ScopeEvent.java | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java index 1d50d5e01b0..424dbbdf713 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java @@ -41,9 +41,7 @@ public final class ScopeEvent extends Event implements DDScopeEvent { @Label("Thread CPU Time") @Timespan - private long cpuTime = 0L; - - private long startCpuTime; + private volatile long cpuTime = 0L; ScopeEvent(final DDSpanContext spanContext) { this.spanContext = spanContext; @@ -52,7 +50,7 @@ public final class ScopeEvent extends Event implements DDScopeEvent { @Override public void start() { if (isEnabled()) { - startCpuTime = ThreadCpuTime.get(); + cpuTime = ThreadCpuTime.get(); begin(); } } @@ -60,8 +58,8 @@ public void start() { @Override public void finish() { end(); - if (startCpuTime > 0) { - cpuTime = ThreadCpuTime.get() - startCpuTime; + if (cpuTime > 0) { + cpuTime = ThreadCpuTime.get() - cpuTime; } if (shouldCommit()) { traceId = spanContext.getTraceId().toString(IDS_RADIX); From 7597450f8a740d1da45b6806fd365530ae23e951 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Tue, 14 Apr 2020 15:39:21 +0200 Subject: [PATCH 05/18] Fix formatting --- .../java/datadog/trace/bootstrap/Agent.java | 19 +++++++++++-------- .../jfr/openjdk/ThreadCpuTime.java | 6 ++++-- 2 files changed, 15 insertions(+), 10 deletions(-) diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index ef5ba99dd00..ca3d92d7bed 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java @@ -8,7 +8,6 @@ import java.lang.reflect.Method; import java.net.URL; import java.util.concurrent.Callable; - import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -273,15 +272,19 @@ private static synchronized void initializeScopeThreadCpuTime() { try { final Class threadCpuTimeClass = AGENT_CLASSLOADER.loadClass("datadog.trace.agent.ot.jfr.openjdk.ThreadCpuTime"); - final Method initializeMethod = threadCpuTimeClass.getDeclaredMethod("initialize", Callable.class); + final Method initializeMethod = + threadCpuTimeClass.getDeclaredMethod("initialize", Callable.class); final ThreadMXBean mxBean = ManagementFactory.getThreadMXBean(); initializeMethod.setAccessible(true); - initializeMethod.invoke(null, new Callable() { - @Override - public Long call() throws Exception { - return mxBean.getCurrentThreadCpuTime(); - } - }); + initializeMethod.invoke( + null, + new Callable() { + @Override + public Long call() throws Exception { + return mxBean.getCurrentThreadCpuTime(); + } + }); + log.debug("Thread CPU time provider enabled"); } catch (final Throwable ex) { log.error("Throwable thrown while initializing the Scope thread cpu time access", ex); } diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java index a4d0029574f..afc1e7cdd38 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java @@ -5,7 +5,8 @@ public class ThreadCpuTime { private static volatile Callable CPU_TIME_PROVIDER; - // must use Callable here since initialization is invoked from Agent which needs to be Java 7 compatible + // must use Callable here since initialization is invoked from Agent which needs to be Java 7 + // compatible static void initialize(Callable provider) { CPU_TIME_PROVIDER = provider; } @@ -13,7 +14,8 @@ static void initialize(Callable provider) { static long get() { try { return CPU_TIME_PROVIDER == null ? Long.MIN_VALUE : CPU_TIME_PROVIDER.call(); - } catch (Exception ignored) {} + } catch (Exception ignored) { + } return Long.MIN_VALUE; } } From 551e3319817ce8e7e5a2ffdf8de26bfe14a89ec6 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Wed, 15 Apr 2020 18:35:38 +0200 Subject: [PATCH 06/18] Formatting --- .../datadog/opentracing/jfr/openjdk/ThreadCpuTime.java | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java index afc1e7cdd38..8686843d202 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java @@ -3,7 +3,13 @@ import java.util.concurrent.Callable; public class ThreadCpuTime { - private static volatile Callable CPU_TIME_PROVIDER; + private static volatile Callable CPU_TIME_PROVIDER = + new Callable() { + @Override + public Long call() throws Exception { + return Long.MIN_VALUE; + } + }; // must use Callable here since initialization is invoked from Agent which needs to be Java 7 // compatible @@ -13,7 +19,7 @@ static void initialize(Callable provider) { static long get() { try { - return CPU_TIME_PROVIDER == null ? Long.MIN_VALUE : CPU_TIME_PROVIDER.call(); + return CPU_TIME_PROVIDER.call(); } catch (Exception ignored) { } return Long.MIN_VALUE; From d283b3ed7e748caad9f1346b9426f61c49608d90 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Wed, 15 Apr 2020 18:36:09 +0200 Subject: [PATCH 07/18] Capture thread CPU time diff only when the event is about to commit --- .../java/datadog/opentracing/jfr/openjdk/ScopeEvent.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java index 424dbbdf713..6f3bb0e0491 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java @@ -58,10 +58,10 @@ public void start() { @Override public void finish() { end(); - if (cpuTime > 0) { - cpuTime = ThreadCpuTime.get() - cpuTime; - } if (shouldCommit()) { + if (cpuTime > 0) { + cpuTime = ThreadCpuTime.get() - cpuTime; + } traceId = spanContext.getTraceId().toString(IDS_RADIX); spanId = spanContext.getSpanId().toString(IDS_RADIX); parentId = spanContext.getParentId().toString(IDS_RADIX); From d579738a7704af951a9305649ba025870029dea6 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 16 Apr 2020 10:30:27 +0200 Subject: [PATCH 08/18] cpuTime field does not need to be volatile --- .../main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java index 6f3bb0e0491..0fa8cc1ab46 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java @@ -41,7 +41,8 @@ public final class ScopeEvent extends Event implements DDScopeEvent { @Label("Thread CPU Time") @Timespan - private volatile long cpuTime = 0L; + // does not need to be volatile since the event is created and committed from the same thread + private long cpuTime = 0L; ScopeEvent(final DDSpanContext spanContext) { this.spanContext = spanContext; From 91a4146ab6fea04cd8b34608a5506d2be515d85b Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 16 Apr 2020 10:36:24 +0200 Subject: [PATCH 09/18] Improve test coverage --- .../jfr/openjdk}/ScopeEventFactoryTest.groovy | 4 +- .../jfr/openjdk}/ScopeEventTest.groovy | 34 +++++++++++++- .../jfr/openjdk/ThreadCpuTimeTest.groovy | 46 +++++++++++++++++++ .../opentracing/jfr/openjdk}/JfrHelper.java | 2 + 4 files changed, 83 insertions(+), 3 deletions(-) rename dd-trace-ot/jfr-openjdk/src/test/groovy/{ => datadog/opentracing/jfr/openjdk}/ScopeEventFactoryTest.groovy (85%) rename dd-trace-ot/jfr-openjdk/src/test/groovy/{ => datadog/opentracing/jfr/openjdk}/ScopeEventTest.groovy (71%) create mode 100644 dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ThreadCpuTimeTest.groovy rename dd-trace-ot/jfr-openjdk/src/test/{groovy => java/datadog/opentracing/jfr/openjdk}/JfrHelper.java (94%) diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/ScopeEventFactoryTest.groovy b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventFactoryTest.groovy similarity index 85% rename from dd-trace-ot/jfr-openjdk/src/test/groovy/ScopeEventFactoryTest.groovy rename to dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventFactoryTest.groovy index ea30c156c39..85a52c9f9bf 100644 --- a/dd-trace-ot/jfr-openjdk/src/test/groovy/ScopeEventFactoryTest.groovy +++ b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventFactoryTest.groovy @@ -1,6 +1,6 @@ +package datadog.opentracing.jfr.openjdk + import datadog.opentracing.jfr.DDNoopScopeEvent -import datadog.opentracing.jfr.openjdk.ScopeEvent -import datadog.opentracing.jfr.openjdk.ScopeEventFactory import spock.lang.Requires import spock.lang.Specification diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/ScopeEventTest.groovy b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy similarity index 71% rename from dd-trace-ot/jfr-openjdk/src/test/groovy/ScopeEventTest.groovy rename to dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy index a687ac96558..b2de7d9e193 100644 --- a/dd-trace-ot/jfr-openjdk/src/test/groovy/ScopeEventTest.groovy +++ b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy @@ -1,3 +1,5 @@ +package datadog.opentracing.jfr.openjdk + import datadog.opentracing.DDSpanContext import datadog.opentracing.DDTracer import datadog.opentracing.PendingTrace @@ -10,6 +12,7 @@ import io.opentracing.Span import spock.lang.Requires import spock.lang.Specification +import java.lang.management.ManagementFactory import java.time.Duration import static datadog.trace.api.Config.DEFAULT_SERVICE_NAME @@ -45,8 +48,36 @@ class ScopeEventTest extends Specification { .withServiceName("test service") .withResourceName("test resource") - def "Scope event is written"() { + def "Scope event is written with thread CPU time"() { + setup: + ThreadCpuTime.initialize(ManagementFactory.getThreadMXBean().&getCurrentThreadCpuTime) + def recording = JfrHelper.startRecording() + + when: + Scope scope = builder.startActive(false) + Span span = scope.span() + sleep(SLEEP_DURATION.toMillis()) + scope.close() + def events = JfrHelper.stopRecording(recording) + span.finish() + + then: + events.size() == 1 + def event = events[0] + event.eventType.name == "datadog.Scope" + event.duration >= SLEEP_DURATION + event.getString("traceId") == span.context().traceId.toString(IDS_RADIX) + event.getString("spanId") == span.context().spanId.toString(IDS_RADIX) + event.getString("parentId") == span.context().parentId.toString(IDS_RADIX) + event.getString("serviceName") == "test service" + event.getString("resourceName") == "test resource" + event.getString("operationName") == "test operation" + event.getLong("cpuTime") != Long.MIN_VALUE + } + + def "Scope event is written without thread CPU time"() { setup: + ThreadCpuTime.initialize(null) def recording = JfrHelper.startRecording() when: @@ -68,6 +99,7 @@ class ScopeEventTest extends Specification { event.getString("serviceName") == "test service" event.getString("resourceName") == "test resource" event.getString("operationName") == "test operation" + event.getLong("cpuTime") == Long.MIN_VALUE } def "Scope event is written after continuation activation"() { diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ThreadCpuTimeTest.groovy b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ThreadCpuTimeTest.groovy new file mode 100644 index 00000000000..a84c3a7ba33 --- /dev/null +++ b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ThreadCpuTimeTest.groovy @@ -0,0 +1,46 @@ +package datadog.opentracing.jfr.openjdk + +import spock.lang.Specification + +import java.lang.management.ManagementFactory + +class ThreadCpuTimeTest extends Specification { + def "No thread CPU time provider"() { + setup: + ThreadCpuTime.initialize(null) + + when: + def threadCpuTime1 = ThreadCpuTime.get() + // burn some cpu + def sum = 0 + for (int i = 0; i < 10_000; i++) { + sum += i + } + def threadCpuTime2 = ThreadCpuTime.get() + + then: + sum > 0 + threadCpuTime1 == Long.MIN_VALUE + threadCpuTime2 == Long.MIN_VALUE + } + + def "JMX thread CPU time provider"() { + setup: + ThreadCpuTime.initialize(ManagementFactory.getThreadMXBean().&getCurrentThreadCpuTime) + + when: + def threadCpuTime1 = ThreadCpuTime.get() + // burn some cpu + def sum = 0 + for (int i = 0; i < 10_000; i++) { + sum += i + } + def threadCpuTime2 = ThreadCpuTime.get() + + then: + sum > 0 + threadCpuTime1 != Long.MIN_VALUE + threadCpuTime2 != Long.MIN_VALUE + threadCpuTime2 > threadCpuTime1 + } +} diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/JfrHelper.java b/dd-trace-ot/jfr-openjdk/src/test/java/datadog/opentracing/jfr/openjdk/JfrHelper.java similarity index 94% rename from dd-trace-ot/jfr-openjdk/src/test/groovy/JfrHelper.java rename to dd-trace-ot/jfr-openjdk/src/test/java/datadog/opentracing/jfr/openjdk/JfrHelper.java index 9bbf5d6678f..d91785fe6d7 100644 --- a/dd-trace-ot/jfr-openjdk/src/test/groovy/JfrHelper.java +++ b/dd-trace-ot/jfr-openjdk/src/test/java/datadog/opentracing/jfr/openjdk/JfrHelper.java @@ -1,3 +1,5 @@ +package datadog.opentracing.jfr.openjdk; + import java.io.IOException; import java.nio.file.Files; import java.nio.file.Path; From f59cf0e53bf5358eed041da53abe4e39db15cf4c Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 16 Apr 2020 11:02:25 +0200 Subject: [PATCH 10/18] Move ThreadCpuTime to Java 7 only location --- .../src/main/java/datadog/trace/bootstrap/Agent.java | 3 +-- .../datadog/opentracing/jfr/openjdk/ScopeEvent.java | 1 + .../opentracing/jfr/openjdk/ScopeEventTest.groovy | 1 + .../datadog/trace/common/util}/ThreadCpuTime.java | 12 ++++++------ .../opentracing/util}/ThreadCpuTimeTest.groovy | 3 ++- 5 files changed, 11 insertions(+), 9 deletions(-) rename dd-trace-ot/{jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk => src/main/java/datadog/trace/common/util}/ThreadCpuTime.java (62%) rename dd-trace-ot/{jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk => src/test/groovy/datadog/opentracing/util}/ThreadCpuTimeTest.groovy (92%) diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index ca3d92d7bed..4a58acff851 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java @@ -273,9 +273,8 @@ private static synchronized void initializeScopeThreadCpuTime() { final Class threadCpuTimeClass = AGENT_CLASSLOADER.loadClass("datadog.trace.agent.ot.jfr.openjdk.ThreadCpuTime"); final Method initializeMethod = - threadCpuTimeClass.getDeclaredMethod("initialize", Callable.class); + threadCpuTimeClass.getMethod("initialize", Callable.class); final ThreadMXBean mxBean = ManagementFactory.getThreadMXBean(); - initializeMethod.setAccessible(true); initializeMethod.invoke( null, new Callable() { diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java index 0fa8cc1ab46..db9c29b07da 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java @@ -2,6 +2,7 @@ import datadog.opentracing.DDSpanContext; import datadog.opentracing.jfr.DDScopeEvent; +import datadog.trace.common.util.ThreadCpuTime; import jdk.jfr.Category; import jdk.jfr.Description; import jdk.jfr.Event; diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy index b2de7d9e193..c2c17af03ac 100644 --- a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy +++ b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy @@ -5,6 +5,7 @@ import datadog.opentracing.DDTracer import datadog.opentracing.PendingTrace import datadog.trace.api.sampling.PrioritySampling import datadog.trace.common.sampling.RateByServiceSampler +import datadog.trace.common.util.ThreadCpuTime import datadog.trace.common.writer.ListWriter import datadog.trace.context.TraceScope import io.opentracing.Scope diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTime.java similarity index 62% rename from dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java rename to dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTime.java index 8686843d202..15edf61fe53 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTime.java @@ -1,9 +1,9 @@ -package datadog.opentracing.jfr.openjdk; +package datadog.trace.common.util; import java.util.concurrent.Callable; public class ThreadCpuTime { - private static volatile Callable CPU_TIME_PROVIDER = + private static volatile Callable cpuTimeProvider = new Callable() { @Override public Long call() throws Exception { @@ -13,13 +13,13 @@ public Long call() throws Exception { // must use Callable here since initialization is invoked from Agent which needs to be Java 7 // compatible - static void initialize(Callable provider) { - CPU_TIME_PROVIDER = provider; + public static void initialize(Callable provider) { + cpuTimeProvider = provider; } - static long get() { + public static long get() { try { - return CPU_TIME_PROVIDER.call(); + return cpuTimeProvider.call(); } catch (Exception ignored) { } return Long.MIN_VALUE; diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ThreadCpuTimeTest.groovy b/dd-trace-ot/src/test/groovy/datadog/opentracing/util/ThreadCpuTimeTest.groovy similarity index 92% rename from dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ThreadCpuTimeTest.groovy rename to dd-trace-ot/src/test/groovy/datadog/opentracing/util/ThreadCpuTimeTest.groovy index a84c3a7ba33..a0023b7cee4 100644 --- a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ThreadCpuTimeTest.groovy +++ b/dd-trace-ot/src/test/groovy/datadog/opentracing/util/ThreadCpuTimeTest.groovy @@ -1,5 +1,6 @@ -package datadog.opentracing.jfr.openjdk +package datadog.opentracing.util +import datadog.trace.common.util.ThreadCpuTime import spock.lang.Specification import java.lang.management.ManagementFactory From e1350c25e23b81f32138a23ad9f2c78c6570934a Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 16 Apr 2020 16:32:21 +0200 Subject: [PATCH 11/18] Modify the mode of the CPU time provider initialization --- .../java/datadog/trace/bootstrap/Agent.java | 36 +++++-------- ...ngIntegrationContinuousProfilesTest.groovy | 25 +++++++++ .../opentracing/jfr/openjdk/ScopeEvent.java | 6 +-- .../jfr/openjdk/ScopeEventTest.groovy | 7 ++- .../common/util/JmxThreadCpuTimeProvider.java | 22 ++++++++ .../trace/common/util/ThreadCpuTime.java | 27 ---------- .../common/util/ThreadCpuTimeAccess.java | 54 +++++++++++++++++++ .../common/util/ThreadCpuTimeProvider.java | 22 ++++++++ .../util/ThreadCpuTimeAccessTest.groovy} | 19 +++---- 9 files changed, 149 insertions(+), 69 deletions(-) create mode 100644 dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java delete mode 100644 dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTime.java create mode 100644 dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java create mode 100644 dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java rename dd-trace-ot/src/test/groovy/datadog/{opentracing/util/ThreadCpuTimeTest.groovy => trace/common/util/ThreadCpuTimeAccessTest.groovy} (55%) diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index 4a58acff851..454636b11f3 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java @@ -1,13 +1,10 @@ package datadog.trace.bootstrap; import java.lang.instrument.Instrumentation; -import java.lang.management.ManagementFactory; -import java.lang.management.ThreadMXBean; import java.lang.reflect.Constructor; import java.lang.reflect.InvocationTargetException; import java.lang.reflect.Method; import java.net.URL; -import java.util.concurrent.Callable; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -265,35 +262,26 @@ private static synchronized void installDatadogTracer() { } } - private static synchronized void initializeScopeThreadCpuTime() { + private static synchronized void startJmx(final URL bootstrapURL) { + startJmxFetch(bootstrapURL); + initializeJmxThreadCpuTimeProvider(); + } + + /** Enable JMX based thread CPU time provider once it is safe to touch JMX */ + private static synchronized void initializeJmxThreadCpuTimeProvider() { if (AGENT_CLASSLOADER == null) { throw new IllegalStateException("Datadog agent should have been started already"); } try { - final Class threadCpuTimeClass = - AGENT_CLASSLOADER.loadClass("datadog.trace.agent.ot.jfr.openjdk.ThreadCpuTime"); - final Method initializeMethod = - threadCpuTimeClass.getMethod("initialize", Callable.class); - final ThreadMXBean mxBean = ManagementFactory.getThreadMXBean(); - initializeMethod.invoke( - null, - new Callable() { - @Override - public Long call() throws Exception { - return mxBean.getCurrentThreadCpuTime(); - } - }); - log.debug("Thread CPU time provider enabled"); + final Class tracerInstallerClass = + AGENT_CLASSLOADER.loadClass("datadog.trace.common.util.ThreadCpuTime"); + final Method enableJmxMethod = tracerInstallerClass.getMethod("enableJmx"); + enableJmxMethod.invoke(null); } catch (final Throwable ex) { - log.error("Throwable thrown while initializing the Scope thread cpu time access", ex); + log.error("Throwable thrown while initializing JMX thread CPU time provider", ex); } } - private static void startJmx(final URL bootstrapURL) { - startJmxFetch(bootstrapURL); - initializeScopeThreadCpuTime(); - } - private static synchronized void startJmxFetch(final URL bootstrapURL) { if (JMXFETCH_CLASSLOADER == null) { final ClassLoader contextLoader = Thread.currentThread().getContextClassLoader(); diff --git a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy index a76b2ee42fb..faf864e8e03 100644 --- a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy +++ b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy @@ -6,7 +6,10 @@ import net.jpountz.lz4.LZ4FrameInputStream import okhttp3.mockwebserver.MockResponse import okhttp3.mockwebserver.MockWebServer import okhttp3.mockwebserver.RecordedRequest +import org.openjdk.jmc.common.item.Attribute +import org.openjdk.jmc.common.item.IItem import org.openjdk.jmc.common.item.IItemCollection +import org.openjdk.jmc.common.item.IType import org.openjdk.jmc.common.item.ItemFilters import org.openjdk.jmc.flightrecorder.JfrLoaderToolkit @@ -101,6 +104,28 @@ class ProfilingIntegrationContinuousProfilesTest extends AbstractSmokeTest { IItemCollection scopeEvents = events.apply(ItemFilters.type("datadog.Scope")) scopeEvents.size() > 0 + // only one event type in filtered collection - can just grab the first item from iterator + def scopeEventIterable = scopeEvents.iterator().next() + def attribute = findCpuTimeAttribute(scopeEventIterable.type) + attribute != null + + def accessor = scopeEventIterable.type.getAccessor(attribute) + scopeEventIterable.every { + scopeEvent -> + def cpuTime = accessor.getMember(scopeEvent).toLong() + cpuTime != Long.MIN_VALUE + } + } + + private static Attribute findCpuTimeAttribute(IType type) { + def attribute = null + type.accessorKeys.forEach { + k, v -> + if (k.identifier == "cpuTime") { + attribute = k + } + } + return attribute } } diff --git a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java index db9c29b07da..55b1298599b 100644 --- a/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java +++ b/dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java @@ -2,7 +2,7 @@ import datadog.opentracing.DDSpanContext; import datadog.opentracing.jfr.DDScopeEvent; -import datadog.trace.common.util.ThreadCpuTime; +import datadog.trace.common.util.ThreadCpuTimeAccess; import jdk.jfr.Category; import jdk.jfr.Description; import jdk.jfr.Event; @@ -52,7 +52,7 @@ public final class ScopeEvent extends Event implements DDScopeEvent { @Override public void start() { if (isEnabled()) { - cpuTime = ThreadCpuTime.get(); + cpuTime = ThreadCpuTimeAccess.getCurrentThreadCpuTime(); begin(); } } @@ -62,7 +62,7 @@ public void finish() { end(); if (shouldCommit()) { if (cpuTime > 0) { - cpuTime = ThreadCpuTime.get() - cpuTime; + cpuTime = ThreadCpuTimeAccess.getCurrentThreadCpuTime() - cpuTime; } traceId = spanContext.getTraceId().toString(IDS_RADIX); spanId = spanContext.getSpanId().toString(IDS_RADIX); diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy index c2c17af03ac..56abde8685f 100644 --- a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy +++ b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy @@ -5,7 +5,7 @@ import datadog.opentracing.DDTracer import datadog.opentracing.PendingTrace import datadog.trace.api.sampling.PrioritySampling import datadog.trace.common.sampling.RateByServiceSampler -import datadog.trace.common.util.ThreadCpuTime +import datadog.trace.common.util.ThreadCpuTimeAccess import datadog.trace.common.writer.ListWriter import datadog.trace.context.TraceScope import io.opentracing.Scope @@ -13,7 +13,6 @@ import io.opentracing.Span import spock.lang.Requires import spock.lang.Specification -import java.lang.management.ManagementFactory import java.time.Duration import static datadog.trace.api.Config.DEFAULT_SERVICE_NAME @@ -51,7 +50,7 @@ class ScopeEventTest extends Specification { def "Scope event is written with thread CPU time"() { setup: - ThreadCpuTime.initialize(ManagementFactory.getThreadMXBean().&getCurrentThreadCpuTime) + ThreadCpuTimeAccess.enableJmx() def recording = JfrHelper.startRecording() when: @@ -78,7 +77,7 @@ class ScopeEventTest extends Specification { def "Scope event is written without thread CPU time"() { setup: - ThreadCpuTime.initialize(null) + ThreadCpuTimeAccess.disableJmx() def recording = JfrHelper.startRecording() when: diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java new file mode 100644 index 00000000000..1084d106871 --- /dev/null +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java @@ -0,0 +1,22 @@ +package datadog.trace.common.util; + +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadMXBean; + +/** Thread CPU time provider based on {@linkplain ThreadMXBean#getCurrentThreadCpuTime()} */ +final class JmxThreadCpuTimeProvider extends ThreadCpuTimeProvider { + private final ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); + + public static final JmxThreadCpuTimeProvider INSTANCE = new JmxThreadCpuTimeProvider(); + + private JmxThreadCpuTimeProvider() {} + + /** + * @return the actual thread CPU time as reported by {@linkplain + * ThreadMXBean#getCurrentThreadCpuTime()} + */ + @Override + public long getThreadCpuTime() { + return threadMXBean.getCurrentThreadCpuTime(); + } +} diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTime.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTime.java deleted file mode 100644 index 15edf61fe53..00000000000 --- a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTime.java +++ /dev/null @@ -1,27 +0,0 @@ -package datadog.trace.common.util; - -import java.util.concurrent.Callable; - -public class ThreadCpuTime { - private static volatile Callable cpuTimeProvider = - new Callable() { - @Override - public Long call() throws Exception { - return Long.MIN_VALUE; - } - }; - - // must use Callable here since initialization is invoked from Agent which needs to be Java 7 - // compatible - public static void initialize(Callable provider) { - cpuTimeProvider = provider; - } - - public static long get() { - try { - return cpuTimeProvider.call(); - } catch (Exception ignored) { - } - return Long.MIN_VALUE; - } -} diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java new file mode 100644 index 00000000000..66a220423c2 --- /dev/null +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java @@ -0,0 +1,54 @@ +package datadog.trace.common.util; + +import lombok.extern.slf4j.Slf4j; + +/** + * Thread CPU time accessor.
+ * This class abstracts away the actual method used to get the current thread CPU time. + */ +@Slf4j +public final class ThreadCpuTimeAccess { + private static volatile ThreadCpuTimeProvider cpuTimeProvider = ThreadCpuTimeProvider.DEFAULT; + + /** + * Disable JMX based thread CPU time. Will flip back to the {@linkplain + * ThreadCpuTimeProvider#DEFAULT} implementation. + */ + public static void disableJmx() { + log.debug("Disabling JMX thread CPU time provider"); + cpuTimeProvider = ThreadCpuTimeProvider.DEFAULT; + } + + /** Enable JMX based thread CPU time */ + public static void enableJmx() { + try { + log.debug("Enabling JMX thread CPU time provider"); + /* + * Can not use direct class reference to JmxThreadCpuTimeProvider since on some rare JVM implementations + * using eager class resolution that class could be resolved at the moment when ThreadCpuTime is being loaded, + * potentially triggering j.u.l initialization which is potentially dangerous and can be done only at certain + * point in time. + * Using reflection should alleviate this problem - no class constant to resolve during class load. The JMX + * thread cpu time provider will be loaded at exact moment when the reflection code is executed. Then it is up + * to the caller to ensure that it is safe to use JMX. + */ + cpuTimeProvider = + (ThreadCpuTimeProvider) + Class.forName("datadog.trace.common.util.JmxThreadCpuTimeProvider") + .getField("INSTANCE") + .get(null); + } catch (ClassNotFoundException | NoSuchFieldException | IllegalAccessException e) { + log.info("Unable to initialize JMX thread CPU time provider", e); + } + } + + /** + * Get the current thread CPU time + * + * @return the actual current thread CPU time or {@linkplain Long#MIN_VALUE} if the JMX provider + * is not available + */ + public static long getCurrentThreadCpuTime() { + return cpuTimeProvider.getThreadCpuTime(); + } +} diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java new file mode 100644 index 00000000000..d96b3f7c6d4 --- /dev/null +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java @@ -0,0 +1,22 @@ +package datadog.trace.common.util; + +/** + * A pluggable thread CPU time provider used by {@linkplain ThreadCpuTimeAccess}. {@linkplain + * ThreadCpuTimeAccess} may not use JMX classes (even via transitive dependencies) due to potential + * race in j.u.l initialization. Therefore it uses an abstract {@linkplain ThreadCpuTimeProvider} + * type to hold the actual implementation which may be switched between the {@linkplain + * ThreadCpuTimeProvider#DEFAULT} and {@linkplain JmxThreadCpuTimeProvider} on-the-fly once JMX is + * safe to use. + */ +abstract class ThreadCpuTimeProvider { + static final ThreadCpuTimeProvider DEFAULT = new ThreadCpuTimeProvider() {}; + + /** + * Get the current thread CPU time + * + * @return {@linkplain Long#MIN_VALUE} + */ + long getThreadCpuTime() { + return Long.MIN_VALUE; + } +} diff --git a/dd-trace-ot/src/test/groovy/datadog/opentracing/util/ThreadCpuTimeTest.groovy b/dd-trace-ot/src/test/groovy/datadog/trace/common/util/ThreadCpuTimeAccessTest.groovy similarity index 55% rename from dd-trace-ot/src/test/groovy/datadog/opentracing/util/ThreadCpuTimeTest.groovy rename to dd-trace-ot/src/test/groovy/datadog/trace/common/util/ThreadCpuTimeAccessTest.groovy index a0023b7cee4..43944953fde 100644 --- a/dd-trace-ot/src/test/groovy/datadog/opentracing/util/ThreadCpuTimeTest.groovy +++ b/dd-trace-ot/src/test/groovy/datadog/trace/common/util/ThreadCpuTimeAccessTest.groovy @@ -1,23 +1,20 @@ -package datadog.opentracing.util +package datadog.trace.common.util -import datadog.trace.common.util.ThreadCpuTime import spock.lang.Specification -import java.lang.management.ManagementFactory - -class ThreadCpuTimeTest extends Specification { +class ThreadCpuTimeAccessTest extends Specification { def "No thread CPU time provider"() { setup: - ThreadCpuTime.initialize(null) + ThreadCpuTimeAccess.disableJmx() when: - def threadCpuTime1 = ThreadCpuTime.get() + def threadCpuTime1 = ThreadCpuTimeAccess.getCurrentThreadCpuTime() // burn some cpu def sum = 0 for (int i = 0; i < 10_000; i++) { sum += i } - def threadCpuTime2 = ThreadCpuTime.get() + def threadCpuTime2 = ThreadCpuTimeAccess.getCurrentThreadCpuTime() then: sum > 0 @@ -27,16 +24,16 @@ class ThreadCpuTimeTest extends Specification { def "JMX thread CPU time provider"() { setup: - ThreadCpuTime.initialize(ManagementFactory.getThreadMXBean().&getCurrentThreadCpuTime) + ThreadCpuTimeAccess.enableJmx() when: - def threadCpuTime1 = ThreadCpuTime.get() + def threadCpuTime1 = ThreadCpuTimeAccess.getCurrentThreadCpuTime() // burn some cpu def sum = 0 for (int i = 0; i < 10_000; i++) { sum += i } - def threadCpuTime2 = ThreadCpuTime.get() + def threadCpuTime2 = ThreadCpuTimeAccess.getCurrentThreadCpuTime() then: sum > 0 From e41bafc32c7f6774db434e176dfc7d43d1d45ffa Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 16 Apr 2020 16:52:52 +0200 Subject: [PATCH 12/18] Do not initialize the thread if profiling is not enabled --- .../src/main/java/datadog/trace/bootstrap/Agent.java | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index 454636b11f3..3ea1e3cf553 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java @@ -1,5 +1,6 @@ package datadog.trace.bootstrap; +import datadog.trace.api.Config; import java.lang.instrument.Instrumentation; import java.lang.reflect.Constructor; import java.lang.reflect.InvocationTargetException; @@ -264,17 +265,24 @@ private static synchronized void installDatadogTracer() { private static synchronized void startJmx(final URL bootstrapURL) { startJmxFetch(bootstrapURL); - initializeJmxThreadCpuTimeProvider(); + /* + * Initialize the thread cpu time provider only if profiling is enabled. + * ATTENTION! If ever is the thread cpu time provider used outside of profiler this check should be revisited. + */ + if (Config.get().isProfilingEnabled()) { + initializeJmxThreadCpuTimeProvider(); + } } /** Enable JMX based thread CPU time provider once it is safe to touch JMX */ private static synchronized void initializeJmxThreadCpuTimeProvider() { + log.info("Initializing JMX thread CPU time provider"); if (AGENT_CLASSLOADER == null) { throw new IllegalStateException("Datadog agent should have been started already"); } try { final Class tracerInstallerClass = - AGENT_CLASSLOADER.loadClass("datadog.trace.common.util.ThreadCpuTime"); + AGENT_CLASSLOADER.loadClass("datadog.trace.common.util.ThreadCpuTimeAccess"); final Method enableJmxMethod = tracerInstallerClass.getMethod("enableJmx"); enableJmxMethod.invoke(null); } catch (final Throwable ex) { From e43088e5bd10adf737873bd1d64252296a0c6f87 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 16 Apr 2020 16:58:07 +0200 Subject: [PATCH 13/18] Make the cpu time assertion more lenient - some events might not have cpu time at all --- .../ProfilingIntegrationContinuousProfilesTest.groovy | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy index faf864e8e03..8b46f18b240 100644 --- a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy +++ b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy @@ -110,11 +110,13 @@ class ProfilingIntegrationContinuousProfilesTest extends AbstractSmokeTest { attribute != null def accessor = scopeEventIterable.type.getAccessor(attribute) + def hasCpuTime = false scopeEventIterable.every { scopeEvent -> - def cpuTime = accessor.getMember(scopeEvent).toLong() - cpuTime != Long.MIN_VALUE + hasCpuTime = hasCpuTime || accessor.getMember(scopeEvent).toLong() } + + hasCpuTime } private static Attribute findCpuTimeAttribute(IType type) { From a992b167d053c565066d79a13be176b2c2e1795f Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Thu, 16 Apr 2020 19:23:39 +0200 Subject: [PATCH 14/18] Allow more predictable cpu time check in the integration test --- .../profiling/ProfilingTestApplication.java | 21 ++++++++++++++++++- ...ngIntegrationContinuousProfilesTest.groovy | 7 +++---- 2 files changed, 23 insertions(+), 5 deletions(-) diff --git a/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java b/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java index 3d693a40080..34dd9ebd2c0 100644 --- a/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java +++ b/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java @@ -1,9 +1,13 @@ package datadog.smoketest.profiling; import datadog.trace.api.Trace; +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadMXBean; +import java.util.Random; import java.util.concurrent.TimeUnit; public class ProfilingTestApplication { + private static final ThreadMXBean THREAD_MX_BEAN = ManagementFactory.getThreadMXBean(); public static void main(final String[] args) throws InterruptedException { long exitDelay = -1; @@ -23,6 +27,21 @@ public static void main(final String[] args) throws InterruptedException { @Trace private static void tracedMethod() throws InterruptedException { System.out.println("Tracing"); - Thread.sleep(100); + tracedBusyMethod(); + } + + @Trace + private static void tracedBusyMethod() { + long startTime = THREAD_MX_BEAN.getCurrentThreadCpuTime(); + Random random = new Random(); + long accumulator = 0L; + while (true) { + accumulator += random.nextInt(113); + if (THREAD_MX_BEAN.getCurrentThreadCpuTime() - startTime > 100_000_000L) { + // looking for at least 100ms CPU time + break; + } + } + System.out.println("accumulated: " + accumulator); } } diff --git a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy index 8b46f18b240..06715a5821b 100644 --- a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy +++ b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy @@ -110,13 +110,12 @@ class ProfilingIntegrationContinuousProfilesTest extends AbstractSmokeTest { attribute != null def accessor = scopeEventIterable.type.getAccessor(attribute) - def hasCpuTime = false scopeEventIterable.every { scopeEvent -> - hasCpuTime = hasCpuTime || accessor.getMember(scopeEvent).toLong() + def cpuTime = accessor.getMember(scopeEvent).toLong() + // cpu time is either not provided or must be >=100ms + cpuTime == Long.MIN_VALUE || cpuTime >= 100_000_000L } - - hasCpuTime } private static Attribute findCpuTimeAttribute(IType type) { From 17c01c64b76a644bb9c41fdb6f9b08bacf986362 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Fri, 17 Apr 2020 16:02:32 +0200 Subject: [PATCH 15/18] Address review comments --- .../java/datadog/trace/bootstrap/Agent.java | 9 +-------- ...ngIntegrationContinuousProfilesTest.groovy | 19 ++----------------- .../common/util/JmxThreadCpuTimeProvider.java | 2 +- .../util/NoneThreadCpuTimeProvider.java | 8 ++++++++ .../common/util/ThreadCpuTimeAccess.java | 11 ++++++++--- .../common/util/ThreadCpuTimeProvider.java | 18 ++++++------------ 6 files changed, 26 insertions(+), 41 deletions(-) create mode 100644 dd-trace-ot/src/main/java/datadog/trace/common/util/NoneThreadCpuTimeProvider.java diff --git a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java index 3ea1e3cf553..898933771fe 100644 --- a/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java +++ b/dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java @@ -1,6 +1,5 @@ package datadog.trace.bootstrap; -import datadog.trace.api.Config; import java.lang.instrument.Instrumentation; import java.lang.reflect.Constructor; import java.lang.reflect.InvocationTargetException; @@ -265,13 +264,7 @@ private static synchronized void installDatadogTracer() { private static synchronized void startJmx(final URL bootstrapURL) { startJmxFetch(bootstrapURL); - /* - * Initialize the thread cpu time provider only if profiling is enabled. - * ATTENTION! If ever is the thread cpu time provider used outside of profiler this check should be revisited. - */ - if (Config.get().isProfilingEnabled()) { - initializeJmxThreadCpuTimeProvider(); - } + initializeJmxThreadCpuTimeProvider(); } /** Enable JMX based thread CPU time provider once it is safe to touch JMX */ diff --git a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy index 06715a5821b..e74fb0ae82a 100644 --- a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy +++ b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy @@ -7,10 +7,9 @@ import okhttp3.mockwebserver.MockResponse import okhttp3.mockwebserver.MockWebServer import okhttp3.mockwebserver.RecordedRequest import org.openjdk.jmc.common.item.Attribute -import org.openjdk.jmc.common.item.IItem import org.openjdk.jmc.common.item.IItemCollection -import org.openjdk.jmc.common.item.IType import org.openjdk.jmc.common.item.ItemFilters +import org.openjdk.jmc.common.unit.UnitLookup import org.openjdk.jmc.flightrecorder.JfrLoaderToolkit import java.time.Instant @@ -106,10 +105,8 @@ class ProfilingIntegrationContinuousProfilesTest extends AbstractSmokeTest { scopeEvents.size() > 0 // only one event type in filtered collection - can just grab the first item from iterator def scopeEventIterable = scopeEvents.iterator().next() - def attribute = findCpuTimeAttribute(scopeEventIterable.type) - attribute != null - def accessor = scopeEventIterable.type.getAccessor(attribute) + def accessor = Attribute.attr("cpuTime", UnitLookup.NANOSECOND.getContentType()).getAccessor(scopeEventIterable.type) scopeEventIterable.every { scopeEvent -> def cpuTime = accessor.getMember(scopeEvent).toLong() @@ -117,16 +114,4 @@ class ProfilingIntegrationContinuousProfilesTest extends AbstractSmokeTest { cpuTime == Long.MIN_VALUE || cpuTime >= 100_000_000L } } - - private static Attribute findCpuTimeAttribute(IType type) { - def attribute = null - type.accessorKeys.forEach { - k, v -> - if (k.identifier == "cpuTime") { - attribute = k - } - } - return attribute - } - } diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java index 1084d106871..f1c8ac2a796 100644 --- a/dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/JmxThreadCpuTimeProvider.java @@ -4,7 +4,7 @@ import java.lang.management.ThreadMXBean; /** Thread CPU time provider based on {@linkplain ThreadMXBean#getCurrentThreadCpuTime()} */ -final class JmxThreadCpuTimeProvider extends ThreadCpuTimeProvider { +final class JmxThreadCpuTimeProvider implements ThreadCpuTimeProvider { private final ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean(); public static final JmxThreadCpuTimeProvider INSTANCE = new JmxThreadCpuTimeProvider(); diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/NoneThreadCpuTimeProvider.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/NoneThreadCpuTimeProvider.java new file mode 100644 index 00000000000..aaef7ddce89 --- /dev/null +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/NoneThreadCpuTimeProvider.java @@ -0,0 +1,8 @@ +package datadog.trace.common.util; + +final class NoneThreadCpuTimeProvider implements ThreadCpuTimeProvider { + @Override + public long getThreadCpuTime() { + return Long.MIN_VALUE; + } +} diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java index 66a220423c2..dd792c2dc00 100644 --- a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java @@ -1,5 +1,6 @@ package datadog.trace.common.util; +import datadog.trace.api.Config; import lombok.extern.slf4j.Slf4j; /** @@ -8,19 +9,23 @@ */ @Slf4j public final class ThreadCpuTimeAccess { - private static volatile ThreadCpuTimeProvider cpuTimeProvider = ThreadCpuTimeProvider.DEFAULT; + private static volatile ThreadCpuTimeProvider cpuTimeProvider = ThreadCpuTimeProvider.NONE; /** * Disable JMX based thread CPU time. Will flip back to the {@linkplain - * ThreadCpuTimeProvider#DEFAULT} implementation. + * ThreadCpuTimeProvider#NONE} implementation. */ public static void disableJmx() { log.debug("Disabling JMX thread CPU time provider"); - cpuTimeProvider = ThreadCpuTimeProvider.DEFAULT; + cpuTimeProvider = ThreadCpuTimeProvider.NONE; } /** Enable JMX based thread CPU time */ public static void enableJmx() { + if (!Config.get().isProfilingEnabled()) { + log.info("Will not enable thread CPU time access. Profiling is disabled."); + return; + } try { log.debug("Enabling JMX thread CPU time provider"); /* diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java index d96b3f7c6d4..380b3f8241c 100644 --- a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java @@ -5,18 +5,12 @@ * ThreadCpuTimeAccess} may not use JMX classes (even via transitive dependencies) due to potential * race in j.u.l initialization. Therefore it uses an abstract {@linkplain ThreadCpuTimeProvider} * type to hold the actual implementation which may be switched between the {@linkplain - * ThreadCpuTimeProvider#DEFAULT} and {@linkplain JmxThreadCpuTimeProvider} on-the-fly once JMX is - * safe to use. + * ThreadCpuTimeProvider#NONE} and {@linkplain JmxThreadCpuTimeProvider} on-the-fly once JMX is safe + * to use. */ -abstract class ThreadCpuTimeProvider { - static final ThreadCpuTimeProvider DEFAULT = new ThreadCpuTimeProvider() {}; +interface ThreadCpuTimeProvider { + ThreadCpuTimeProvider NONE = new NoneThreadCpuTimeProvider(); - /** - * Get the current thread CPU time - * - * @return {@linkplain Long#MIN_VALUE} - */ - long getThreadCpuTime() { - return Long.MIN_VALUE; - } + /** Get the current thread CPU time */ + long getThreadCpuTime(); } From 25155204fa5fddbeac5d1d60c7d59a4f2cfadedf Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Fri, 17 Apr 2020 17:01:15 +0200 Subject: [PATCH 16/18] Change log level --- .../java/datadog/trace/common/util/ThreadCpuTimeAccess.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java index dd792c2dc00..dc7480a9adb 100644 --- a/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java +++ b/dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java @@ -23,7 +23,7 @@ public static void disableJmx() { /** Enable JMX based thread CPU time */ public static void enableJmx() { if (!Config.get().isProfilingEnabled()) { - log.info("Will not enable thread CPU time access. Profiling is disabled."); + log.debug("Will not enable thread CPU time access. Profiling is disabled."); return; } try { From ac70cad2041d8e545302e1b242165801ee625ed1 Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Fri, 17 Apr 2020 17:01:35 +0200 Subject: [PATCH 17/18] Simplification in the integration smoke test --- .../profiling/ProfilingTestApplication.java | 5 +++-- ...ngIntegrationContinuousProfilesTest.groovy | 20 +++++++++---------- 2 files changed, 13 insertions(+), 12 deletions(-) diff --git a/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java b/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java index 34dd9ebd2c0..c9bf3a40534 100644 --- a/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java +++ b/dd-smoke-tests/profiling-integration-tests/src/main/java/datadog/smoketest/profiling/ProfilingTestApplication.java @@ -28,6 +28,7 @@ public static void main(final String[] args) throws InterruptedException { private static void tracedMethod() throws InterruptedException { System.out.println("Tracing"); tracedBusyMethod(); + Thread.sleep(50); } @Trace @@ -37,8 +38,8 @@ private static void tracedBusyMethod() { long accumulator = 0L; while (true) { accumulator += random.nextInt(113); - if (THREAD_MX_BEAN.getCurrentThreadCpuTime() - startTime > 100_000_000L) { - // looking for at least 100ms CPU time + if (THREAD_MX_BEAN.getCurrentThreadCpuTime() - startTime > 10_000_000L) { + // looking for at least 10ms CPU time break; } } diff --git a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy index e74fb0ae82a..7643d868859 100644 --- a/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy +++ b/dd-smoke-tests/profiling-integration-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy @@ -6,6 +6,7 @@ import net.jpountz.lz4.LZ4FrameInputStream import okhttp3.mockwebserver.MockResponse import okhttp3.mockwebserver.MockWebServer import okhttp3.mockwebserver.RecordedRequest +import org.openjdk.jmc.common.item.Aggregators import org.openjdk.jmc.common.item.Attribute import org.openjdk.jmc.common.item.IItemCollection import org.openjdk.jmc.common.item.ItemFilters @@ -103,15 +104,14 @@ class ProfilingIntegrationContinuousProfilesTest extends AbstractSmokeTest { IItemCollection scopeEvents = events.apply(ItemFilters.type("datadog.Scope")) scopeEvents.size() > 0 - // only one event type in filtered collection - can just grab the first item from iterator - def scopeEventIterable = scopeEvents.iterator().next() - - def accessor = Attribute.attr("cpuTime", UnitLookup.NANOSECOND.getContentType()).getAccessor(scopeEventIterable.type) - scopeEventIterable.every { - scopeEvent -> - def cpuTime = accessor.getMember(scopeEvent).toLong() - // cpu time is either not provided or must be >=100ms - cpuTime == Long.MIN_VALUE || cpuTime >= 100_000_000L - } + + def cpuTimeAttr = Attribute.attr("cpuTime", "cpuTime", UnitLookup.TIMESPAN) + + // filter out scope events without CPU time data + def filteredScopeEvents = scopeEvents.apply(ItemFilters.more(cpuTimeAttr, UnitLookup.NANOSECOND.quantity(Long.MIN_VALUE))) + // make sure there is at least one scope event with CPU time data + filteredScopeEvents.size() > 0 + + filteredScopeEvents.getAggregate(Aggregators.min("datadog.Scope", cpuTimeAttr)).longValue() >= 10_000L } } From ea821f0e763db75c72907fd00ba3f54e2399cb2d Mon Sep 17 00:00:00 2001 From: Jaroslav Bachorik Date: Fri, 17 Apr 2020 17:54:15 +0200 Subject: [PATCH 18/18] Fix failing tests --- dd-trace-ot/jfr-openjdk/jfr-openjdk.gradle | 1 + .../jfr/openjdk/ScopeEventTest.groovy | 53 +++++++++++++++++-- .../util/ThreadCpuTimeAccessTest.groovy | 45 ++++++++++++++-- 3 files changed, 93 insertions(+), 6 deletions(-) diff --git a/dd-trace-ot/jfr-openjdk/jfr-openjdk.gradle b/dd-trace-ot/jfr-openjdk/jfr-openjdk.gradle index 3500efa998d..8f37a36d411 100644 --- a/dd-trace-ot/jfr-openjdk/jfr-openjdk.gradle +++ b/dd-trace-ot/jfr-openjdk/jfr-openjdk.gradle @@ -9,6 +9,7 @@ apply plugin: 'idea' dependencies { compile deps.slf4j compile project(':dd-trace-ot') + testCompile project(':dd-java-agent:testing') } /* diff --git a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy index 56abde8685f..e7f020137e0 100644 --- a/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy +++ b/dd-trace-ot/jfr-openjdk/src/test/groovy/datadog/opentracing/jfr/openjdk/ScopeEventTest.groovy @@ -3,22 +3,24 @@ package datadog.opentracing.jfr.openjdk import datadog.opentracing.DDSpanContext import datadog.opentracing.DDTracer import datadog.opentracing.PendingTrace +import datadog.trace.agent.test.utils.ConfigUtils +import datadog.trace.api.Config import datadog.trace.api.sampling.PrioritySampling import datadog.trace.common.sampling.RateByServiceSampler import datadog.trace.common.util.ThreadCpuTimeAccess import datadog.trace.common.writer.ListWriter import datadog.trace.context.TraceScope +import datadog.trace.util.test.DDSpecification import io.opentracing.Scope import io.opentracing.Span import spock.lang.Requires -import spock.lang.Specification import java.time.Duration import static datadog.trace.api.Config.DEFAULT_SERVICE_NAME @Requires({ jvm.java11Compatible }) -class ScopeEventTest extends Specification { +class ScopeEventTest extends DDSpecification { private static final int IDS_RADIX = 16 private static final Duration SLEEP_DURATION = Duration.ofSeconds(1) @@ -50,6 +52,9 @@ class ScopeEventTest extends Specification { def "Scope event is written with thread CPU time"() { setup: + ConfigUtils.updateConfig { + System.properties.setProperty("dd.${Config.PROFILING_ENABLED}", "true") + } ThreadCpuTimeAccess.enableJmx() def recording = JfrHelper.startRecording() @@ -73,11 +78,50 @@ class ScopeEventTest extends Specification { event.getString("resourceName") == "test resource" event.getString("operationName") == "test operation" event.getLong("cpuTime") != Long.MIN_VALUE + + cleanup: + ThreadCpuTimeAccess.disableJmx() } - def "Scope event is written without thread CPU time"() { + def "Scope event is written without thread CPU time - profiling enabled"() { setup: + ConfigUtils.updateConfig { + System.properties.setProperty("dd.${Config.PROFILING_ENABLED}", "true") + } + ThreadCpuTimeAccess.disableJmx() + def recording = JfrHelper.startRecording() + + when: + Scope scope = builder.startActive(false) + Span span = scope.span() + sleep(SLEEP_DURATION.toMillis()) + scope.close() + def events = JfrHelper.stopRecording(recording) + span.finish() + + then: + events.size() == 1 + def event = events[0] + event.eventType.name == "datadog.Scope" + event.duration >= SLEEP_DURATION + event.getString("traceId") == span.context().traceId.toString(IDS_RADIX) + event.getString("spanId") == span.context().spanId.toString(IDS_RADIX) + event.getString("parentId") == span.context().parentId.toString(IDS_RADIX) + event.getString("serviceName") == "test service" + event.getString("resourceName") == "test resource" + event.getString("operationName") == "test operation" + event.getLong("cpuTime") == Long.MIN_VALUE + + cleanup: ThreadCpuTimeAccess.disableJmx() + } + + def "Scope event is written without thread CPU time - profiling disabled"() { + setup: + ConfigUtils.updateConfig { + System.properties.setProperty("dd.${Config.PROFILING_ENABLED}", "false") + } + ThreadCpuTimeAccess.enableJmx() def recording = JfrHelper.startRecording() when: @@ -100,6 +144,9 @@ class ScopeEventTest extends Specification { event.getString("resourceName") == "test resource" event.getString("operationName") == "test operation" event.getLong("cpuTime") == Long.MIN_VALUE + + cleanup: + ThreadCpuTimeAccess.disableJmx() } def "Scope event is written after continuation activation"() { diff --git a/dd-trace-ot/src/test/groovy/datadog/trace/common/util/ThreadCpuTimeAccessTest.groovy b/dd-trace-ot/src/test/groovy/datadog/trace/common/util/ThreadCpuTimeAccessTest.groovy index 43944953fde..88f6f1e85b0 100644 --- a/dd-trace-ot/src/test/groovy/datadog/trace/common/util/ThreadCpuTimeAccessTest.groovy +++ b/dd-trace-ot/src/test/groovy/datadog/trace/common/util/ThreadCpuTimeAccessTest.groovy @@ -1,10 +1,15 @@ package datadog.trace.common.util -import spock.lang.Specification +import datadog.trace.agent.test.utils.ConfigUtils +import datadog.trace.api.Config +import datadog.trace.util.test.DDSpecification -class ThreadCpuTimeAccessTest extends Specification { - def "No thread CPU time provider"() { +class ThreadCpuTimeAccessTest extends DDSpecification { + def "No thread CPU time provider - profiling enabled"() { setup: + ConfigUtils.updateConfig { + System.properties.setProperty("dd.${Config.PROFILING_ENABLED}", "true") + } ThreadCpuTimeAccess.disableJmx() when: @@ -20,10 +25,41 @@ class ThreadCpuTimeAccessTest extends Specification { sum > 0 threadCpuTime1 == Long.MIN_VALUE threadCpuTime2 == Long.MIN_VALUE + + cleanup: + ThreadCpuTimeAccess.disableJmx() + } + + def "No thread CPU time provider - profiling disabled"() { + setup: + ConfigUtils.updateConfig { + System.properties.setProperty("dd.${Config.PROFILING_ENABLED}", "false") + } + ThreadCpuTimeAccess.enableJmx() + + when: + def threadCpuTime1 = ThreadCpuTimeAccess.getCurrentThreadCpuTime() + // burn some cpu + def sum = 0 + for (int i = 0; i < 10_000; i++) { + sum += i + } + def threadCpuTime2 = ThreadCpuTimeAccess.getCurrentThreadCpuTime() + + then: + sum > 0 + threadCpuTime1 == Long.MIN_VALUE + threadCpuTime2 == Long.MIN_VALUE + + cleanup: + ThreadCpuTimeAccess.disableJmx() } def "JMX thread CPU time provider"() { setup: + ConfigUtils.updateConfig { + System.properties.setProperty("dd.${Config.PROFILING_ENABLED}", "true") + } ThreadCpuTimeAccess.enableJmx() when: @@ -40,5 +76,8 @@ class ThreadCpuTimeAccessTest extends Specification { threadCpuTime1 != Long.MIN_VALUE threadCpuTime2 != Long.MIN_VALUE threadCpuTime2 > threadCpuTime1 + + cleanup: + ThreadCpuTimeAccess.disableJmx() } }