Add injection duration telemetry

Author: sarahchen6

dd-java-agent/instrumentation/servlet/request-3/src/main/java/datadog/trace/instrumentation/servlet3/RumHttpServletResponseWrapper.java

@@ -18,6 +18,7 @@ public class RumHttpServletResponseWrapper extends HttpServletResponseWrapper {
   private PrintWriter printWriter;
   private InjectingPipeWriter wrappedPipeWriter;
   private boolean shouldInject = true;
+  private long injectionStartTime = -1;
 
   private static final MethodHandle SET_CONTENT_LENGTH_LONG = getMh("setContentLengthLong");
 
@@ -48,6 +49,10 @@ public ServletOutputStream getOutputStream() throws IOException {
       RumInjector.getTelemetryCollector().onInjectionSkipped();
       return super.getOutputStream();
     }
+    // start timing injection
+    if (injectionStartTime == -1) {
+      injectionStartTime = System.nanoTime();
+    }
     try {
       String encoding = getCharacterEncoding();
       if (encoding == null) {
@@ -76,6 +81,10 @@ public PrintWriter getWriter() throws IOException {
       RumInjector.getTelemetryCollector().onInjectionSkipped();
       return super.getWriter();
     }
+    // start timing injection
+    if (injectionStartTime == -1) {
+      injectionStartTime = System.nanoTime();
+    }
     try {
       wrappedPipeWriter =
           new InjectingPipeWriter(
@@ -149,6 +158,7 @@ public void reset() {
     this.wrappedPipeWriter = null;
     this.printWriter = null;
     this.shouldInject = false;
+    this.injectionStartTime = -1;
     super.reset();
   }
 
@@ -162,6 +172,15 @@ public void resetBuffer() {
 
   public void onInjected() {
     RumInjector.getTelemetryCollector().onInjectionSucceed();
+
+    // report injection time
+    if (injectionStartTime != -1) {
+      long nanoseconds = System.nanoTime() - injectionStartTime;
+      long milliseconds = nanoseconds / 1_000_000L;
+      RumInjector.getTelemetryCollector().onInjectionTime(milliseconds);
+      injectionStartTime = -1;
+    }
+
     try {
       setHeader("x-datadog-rum-injected", "1");
     } catch (Throwable ignored) {

dd-java-agent/instrumentation/servlet/request-3/src/test/groovy/RumHttpServletResponseWrapperTest.groovy

@@ -135,4 +135,6 @@ class RumHttpServletResponseWrapperTest extends AgentTestRunner {
     then:
     1 * mockTelemetryCollector.onInjectionResponseSize(1024)
   }
+
+  // test injection timing?
 }

dd-java-agent/instrumentation/servlet/request-5/src/main/java/datadog/trace/instrumentation/servlet5/RumHttpServletResponseWrapper.java

@@ -15,6 +15,7 @@ public class RumHttpServletResponseWrapper extends HttpServletResponseWrapper {
   private InjectingPipeWriter wrappedPipeWriter;
   private PrintWriter printWriter;
   private boolean shouldInject = true;
+  private long injectionStartTime = -1;
 
   public RumHttpServletResponseWrapper(HttpServletResponse response) {
     super(response);
@@ -30,6 +31,10 @@ public ServletOutputStream getOutputStream() throws IOException {
       RumInjector.getTelemetryCollector().onInjectionSkipped();
       return super.getOutputStream();
     }
+    // start timing injection
+    if (injectionStartTime == -1) {
+      injectionStartTime = System.nanoTime();
+    }
     try {
       String encoding = getCharacterEncoding();
       if (encoding == null) {
@@ -57,6 +62,10 @@ public PrintWriter getWriter() throws IOException {
       RumInjector.getTelemetryCollector().onInjectionSkipped();
       return super.getWriter();
     }
+    // start timing installation
+    if (injectionStartTime == -1) {
+      injectionStartTime = System.nanoTime();
+    }
     try {
       wrappedPipeWriter =
           new InjectingPipeWriter(
@@ -126,6 +135,7 @@ public void reset() {
     this.wrappedPipeWriter = null;
     this.printWriter = null;
     this.shouldInject = false;
+    this.injectionStartTime = -1;
     super.reset();
   }
 
@@ -139,6 +149,15 @@ public void resetBuffer() {
 
   public void onInjected() {
     RumInjector.getTelemetryCollector().onInjectionSucceed();
+
+    // report injection time
+    if (injectionStartTime != -1) {
+      long nanoseconds = System.nanoTime() - injectionStartTime;
+      long milliseconds = nanoseconds / 1_000_000L;
+      RumInjector.getTelemetryCollector().onInjectionTime(milliseconds);
+      injectionStartTime = -1;
+    }
+
     try {
       setHeader("x-datadog-rum-injected", "1");
     } catch (Throwable ignored) {

dd-java-agent/instrumentation/servlet/request-5/src/test/groovy/RumHttpServletResponseWrapperTest.groovy

@@ -135,4 +135,6 @@ class RumHttpServletResponseWrapperTest extends AgentTestRunner {
     then:
     1 * mockTelemetryCollector.onInjectionResponseSize(1024)
   }
+
+  // test injection timing?
 }

internal-api/src/main/java/datadog/trace/api/rum/RumInjectorMetrics.java

@@ -73,6 +73,12 @@ public void onInjectionResponseSize(long bytes) {
     statsd.distribution("rum.injection.response.bytes", bytes, NO_TAGS);
   }
 
+  @Override
+  public void onInjectionTime(long milliseconds) {
+    // report distribution metric immediately
+    statsd.distribution("rum.injection.ms", milliseconds, NO_TAGS);
+  }
+
   public void close() {
     if (null != cancellation) {
       cancellation.cancel();

internal-api/src/main/java/datadog/trace/api/rum/RumTelemetryCollector.java

@@ -24,6 +24,9 @@ public void onContentSecurityPolicyDetected() {}
         @Override
         public void onInjectionResponseSize(long bytes) {}
 
+        @Override
+        public void onInjectionTime(long milliseconds) {}
+
         @Override
         public void close() {}
 
@@ -47,9 +50,12 @@ default void start() {}
   // call when a Content Security Policy header is detected
   void onContentSecurityPolicyDetected();
 
-  // call to get the response size (in bytes) before RUM injection
+  // call to get the response size before RUM injection
   void onInjectionResponseSize(long bytes);
 
+  // call to report the time it takes to inject the RUM SDK
+  void onInjectionTime(long milliseconds);
+
   default void close() {}
 
   // human-readable summary of the current health metrics

internal-api/src/test/groovy/datadog/trace/api/rum/RumInjectorMetricsTest.groovy

@@ -87,14 +87,27 @@ class RumInjectorMetricsTest extends Specification {
 
   def "test onInjectionResponseSize with multiple sizes"() {
     when:
+    metrics.onInjectionResponseSize(256)
     metrics.onInjectionResponseSize(512)
     metrics.onInjectionResponseSize(2048)
-    metrics.onInjectionResponseSize(256)
 
     then:
+    1 * statsD.distribution('rum.injection.response.bytes', 256, _)
     1 * statsD.distribution('rum.injection.response.bytes', 512, _)
     1 * statsD.distribution('rum.injection.response.bytes', 2048, _)
-    1 * statsD.distribution('rum.injection.response.bytes', 256, _)
+    0 * _
+  }
+
+  def "test onInjectionTime with multiple durations"() {
+    when:
+    metrics.onInjectionTime(5L)
+    metrics.onInjectionTime(10L)
+    metrics.onInjectionTime(25L)
+
+    then:
+    1 * statsD.distribution('rum.injection.ms', 5L, _)
+    1 * statsD.distribution('rum.injection.ms', 10L, _)
+    1 * statsD.distribution('rum.injection.ms', 25L, _)
     0 * _
   }
 

internal-api/src/test/groovy/datadog/trace/api/rum/RumInjectorTest.groovy

@@ -169,6 +169,26 @@ class RumInjectorTest extends DDSpecification {
     RumInjector.shutdownTelemetry()
   }
 
+  void 'injection time telemetry does not throw an exception'() {
+    setup:
+    def mockStatsDClient = mock(datadog.trace.api.StatsDClient)
+
+    when:
+    RumInjector.enableTelemetry(mockStatsDClient)
+
+    def telemetryCollector = RumInjector.getTelemetryCollector()
+    telemetryCollector.onInjectionTime(5L)
+    telemetryCollector.onInjectionTime(10L)
+    telemetryCollector.onInjectionTime(20L)
+
+    then:
+    // injection times are reported immediately as distribution metrics
+    noExceptionThrown()
+
+    cleanup:
+    RumInjector.shutdownTelemetry()
+  }
+
   void 'concurrent telemetry calls are thread-safe'() {
     setup:
     RumInjector.enableTelemetry(mock(datadog.trace.api.StatsDClient))