Service Internal Latency

hypertrace-trace-enricher/enriched-span-constants/src/main/java/org/hypertrace/traceenricher/enrichedspan/constants/EnrichedSpanConstants.java

@@ -17,6 +17,7 @@ public class EnrichedSpanConstants {
   public static final String UNIQUE_API_NODES_COUNT = "unique.apis.count";
   public static final String GRPC_REQUEST_URL = "grpc.request.url";
   public static final String GRPC_REQUEST_ENDPOINT = "grpc.request.endpoint";
+  public static final String INTERNAL_SVC_LATENCY = "enriched.serviceInternalProcessingTime";
 
   /**
    * Returns the constant value for the given Enum.

hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/enrichers/ServiceInternalProcessingTimeEnricher.java

@@ -0,0 +1,101 @@
+package org.hypertrace.traceenricher.enrichment.enrichers;
+
+import java.util.List;
+import java.util.Map;
+import java.util.Optional;
+import org.hypertrace.core.datamodel.ApiNodeEventEdge;
+import org.hypertrace.core.datamodel.AttributeValue;
+import org.hypertrace.core.datamodel.Event;
+import org.hypertrace.core.datamodel.StructuredTrace;
+import org.hypertrace.core.datamodel.shared.ApiNode;
+import org.hypertrace.core.datamodel.shared.trace.AttributeValueCreator;
+import org.hypertrace.traceenricher.enrichedspan.constants.EnrichedSpanConstants;
+import org.hypertrace.traceenricher.enrichment.AbstractTraceEnricher;
+import org.hypertrace.traceenricher.trace.util.ApiTraceGraph;
+import org.hypertrace.traceenricher.trace.util.ApiTraceGraphBuilder;
+import org.slf4j.LoggerFactory;
+
+public class ServiceInternalProcessingTimeEnricher extends AbstractTraceEnricher {
+
+  private static final org.slf4j.Logger LOG =
+      LoggerFactory.getLogger(ServiceInternalProcessingTimeEnricher.class);
+
+  public void enrichTrace(StructuredTrace trace) {
+    try {
+      ApiTraceGraph apiTraceGraph = ApiTraceGraphBuilder.buildGraph(trace);
+      List<ApiNode<Event>> apiNodeList = apiTraceGraph.getApiNodeList();
+      for (ApiNode<Event> apiNode : apiNodeList) {
+        List<Event> exitApiBoundaryEvents = apiNode.getExitApiBoundaryEvents();
+        List<ApiNodeEventEdge> edges = apiTraceGraph.getOutboundEdgesForApiNode(apiNode);
+        int edgeDurationSum = 0;
+        // Note: this logic of summing the duration of each child span does not work if children spans
+        // were
+        // concurrent to one-another. In that case, the parent span waits only for
+        // max(duration_child_1,
+        // duration_child2,...,duration_child_n) and not duration_child1 + duration_child_2 +
+        // duration_child_3
+        // Works for:
+        // |------------------PARENT-------------------|
+        //  |---C1---|
+        //              |---C2---|
+        //                          |---C3---|
+        // Doesn't work for:
+        // |------------------PARENT-------------------|
+        //  |---C1---|
+        //    |---C2---|
+        //      |---C3---|
+        for (var edge : edges) {
+          edgeDurationSum += getApiNodeEventEdgeDuration(edge);
+        }
+        // now sum up http or https backends
+        double httpExitCallsSum =
+            exitApiBoundaryEvents.stream()
+                .filter(
+                    event -> {
+                      Map<String, AttributeValue> enrichedAttributes =
+                          event.getEnrichedAttributes().getAttributeMap();
+                      return enrichedAttributes.containsKey("BACKEND_PROTOCOL")
+                          && enrichedAttributes.get("BACKEND_PROTOCOL").getValue().contains("HTTP");
+                    })
+                .mapToDouble(event -> event.getMetrics().getMetricMap().get("Duration").getValue())
+                .sum();
+        Optional<Event> entryApiBoundaryEventMaybe = apiNode.getEntryApiBoundaryEvent();
+        if (entryApiBoundaryEventMaybe.isPresent()) {
+          var entryApiBoundaryEvent = entryApiBoundaryEventMaybe.get();
+          var entryApiBoundaryEventDuration = getEventDuration(entryApiBoundaryEvent);
+          try {
+            entryApiBoundaryEvent
+                .getAttributes()
+                .getAttributeMap()
+                .put(
+                    EnrichedSpanConstants.INTERNAL_SVC_LATENCY,
+                    AttributeValueCreator.create(
+                        String.valueOf(
+                            entryApiBoundaryEventDuration - edgeDurationSum - httpExitCallsSum)));
+          } catch (NullPointerException e) {
+            LOG.error(
+                "NPE while calculating service internal time. entryApiBoundaryEventDuration {}, edgeDurationSum {}",
+                entryApiBoundaryEventDuration,
+                edgeDurationSum,
+                e);
+            throw e;
+          }
+        }
+      }
+    } catch (Exception e) {
+      LOG.error("Exception while calculating service internal time");
+    }
+  }
+
+  private static Double getEventDuration(Event event) {
+    assert event.getMetrics().getMetricMap() != null;
+    assert event.getMetrics().getMetricMap().containsKey("Duration");
+    return event.getMetrics().getMetricMap().get("Duration").getValue();
+  }
+
+  private static Double getApiNodeEventEdgeDuration(ApiNodeEventEdge edge) {
+    assert edge.getMetrics().getMetricMap() != null;
+    assert edge.getMetrics().getMetricMap().containsKey("Duration");
+    return edge.getMetrics().getMetricMap().get("Duration").getValue();
+  }
+}

hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/java/org/hypertrace/traceenricher/enrichment/enrichers/ServiceInternalProcessingTimeEnricherTest.java

@@ -0,0 +1,156 @@
+package org.hypertrace.traceenricher.enrichment.enrichers;
+
+import static java.util.stream.Collectors.toList;
+
+import java.io.File;
+import java.io.IOException;
+import java.net.URL;
+import java.util.List;
+import java.util.stream.Collectors;
+import org.apache.avro.file.DataFileReader;
+import org.apache.avro.specific.SpecificDatumReader;
+import org.hypertrace.core.datamodel.Event;
+import org.hypertrace.core.datamodel.StructuredTrace;
+import org.hypertrace.traceenricher.enrichedspan.constants.EnrichedSpanConstants;
+import org.hypertrace.traceenricher.enrichment.Enricher;
+import org.hypertrace.traceenricher.trace.util.ApiTraceGraph;
+import org.hypertrace.traceenricher.trace.util.ApiTraceGraphBuilder;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Disabled;
+import org.junit.jupiter.api.Test;
+
+@Disabled
+public class ServiceInternalProcessingTimeEnricherTest extends AbstractAttributeEnricherTest {
+
+  private final Enricher testCandidate = new ServiceInternalProcessingTimeEnricher();
+  private StructuredTrace trace;
+
+  @BeforeEach
+  public void setup() throws IOException {
+    URL resource =
+        Thread.currentThread().getContextClassLoader().getResource("StructuredTrace-Hotrod.avro");
+    SpecificDatumReader<StructuredTrace> datumReader =
+        new SpecificDatumReader<>(StructuredTrace.getClassSchema());
+    DataFileReader<StructuredTrace> dfrStructuredTrace =
+        new DataFileReader<>(new File(resource.getPath()), datumReader);
+    trace = dfrStructuredTrace.next();
+    dfrStructuredTrace.close();
+  }
+
+  @Test
+  public void validateServiceInternalTimeAttributeInEntrySpans() {
+    // this trace has 12 api nodes
+    // api edges
+    // 0 -> [1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12]
+    // backend exit
+    // 1 -> to redis 13 exit calls
+    // 2 -> to mysql 1 exit call
+    // for events parts of api_node 0, there should 12 exit calls
+    // for events parts of api_node 1, there should be 13 exit calls
+    // for events parts of api_node 2, there should be 1 exit calls
+    // verify exit call count per service per api_trace
+    // this trace has 4 services
+    // frontend service has 1 api_entry span and that api_node has 12 exit calls [drive: 1,
+    // customer: 1, route: 10]
+    // setup
+    ApiTraceGraph apiTraceGraph = ApiTraceGraphBuilder.buildGraph(trace);
+    var apiNodes = apiTraceGraph.getApiNodeList();
+    // Assert preconditions
+    Assertions.assertEquals(13, apiNodes.size());
+    apiNodes.forEach(
+        apiNode -> Assertions.assertTrue(apiNode.getEntryApiBoundaryEvent().isPresent()));
+    List<String> serviceNames =
+        apiNodes.stream()
+            .map(
+                apiNode -> {
+                  Assertions.assertTrue(apiNode.getEntryApiBoundaryEvent().isPresent());
+                  return apiNode.getEntryApiBoundaryEvent().get().getServiceName();
+                })
+            .collect(toList());
+    Assertions.assertTrue(serviceNames.contains("frontend"));
+    Assertions.assertTrue(serviceNames.contains("driver"));
+    Assertions.assertTrue(serviceNames.contains("customer"));
+    Assertions.assertTrue(serviceNames.contains("route"));
+    // execute
+    testCandidate.enrichTrace(trace);
+    // assertions: All entry spans should have this tag
+    apiTraceGraph
+        .getApiNodeList()
+        .forEach(
+            a ->
+                Assertions.assertTrue(
+                    a.getEntryApiBoundaryEvent()
+                        .get()
+                        .getAttributes()
+                        .getAttributeMap()
+                        .containsKey(EnrichedSpanConstants.INTERNAL_SVC_LATENCY)));
+  }
+
+  @Test
+  public void validateServiceInternalTimeValueInSpans() {
+    ApiTraceGraph apiTraceGraph = ApiTraceGraphBuilder.buildGraph(trace);
+    var apiNodes = apiTraceGraph.getApiNodeList();
+    List<Event> entryApiBoundaryEvents =
+        apiNodes.stream().map(a -> a.getEntryApiBoundaryEvent().get()).collect(toList());
+    // assert pre-conditions
+    Assertions.assertEquals(13, entryApiBoundaryEvents.size());
+    // execute
+    testCandidate.enrichTrace(trace);
+    // All three services below don't have any exit calls to API, only backends. We assert that the
+    // time of these exit spans is
+    // not subtracted from the entry span.
+    var entryEventsForRouteSvc = getEntryEventsForService(entryApiBoundaryEvents, "route");
+    for (Event event : entryEventsForRouteSvc) {
+      Assertions.assertEquals(
+          getEventDuration(event),
+          event
+              .getAttributes()
+              .getAttributeMap()
+              .get(EnrichedSpanConstants.INTERNAL_SVC_LATENCY)
+              .getValue());
+    }
+    var entryEventsForCustomerSvc = getEntryEventsForService(entryApiBoundaryEvents, "customer");
+    for (Event event : entryEventsForCustomerSvc) {
+      Assertions.assertEquals(
+          getEventDuration(event),
+          event
+              .getAttributes()
+              .getAttributeMap()
+              .get(EnrichedSpanConstants.INTERNAL_SVC_LATENCY)
+              .getValue());
+    }
+    var entryEventsDriverSvc = getEntryEventsForService(entryApiBoundaryEvents, "driver");
+    for (Event event : entryEventsDriverSvc) {
+      Assertions.assertEquals(
+          getEventDuration(event),
+          event
+              .getAttributes()
+              .getAttributeMap()
+              .get(EnrichedSpanConstants.INTERNAL_SVC_LATENCY)
+              .getValue());
+    }
+    var entryEventForFrontendSvc =
+        getEntryEventsForService(entryApiBoundaryEvents, "frontend").get(0);
+    // total outbound edge duration = 1016ms
+    // entry event duration = 678ms
+    Assertions.assertEquals(
+        "-335.0",
+        entryEventForFrontendSvc
+            .getAttributes()
+            .getAttributeMap()
+            .get(EnrichedSpanConstants.INTERNAL_SVC_LATENCY)
+            .getValue());
+  }
+
+  private static List<Event> getEntryEventsForService(
+      List<Event> entryApiBoundaryEvents, String service) {
+    return entryApiBoundaryEvents.stream()
+        .filter(a -> a.getServiceName().equals(service))
+        .collect(Collectors.toList());
+  }
+
+  private static String getEventDuration(Event event) {
+    return String.valueOf(event.getMetrics().getMetricMap().get("Duration").getValue());
+  }
+}

hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/enricher.conf

@@ -1,5 +1,5 @@
 enricher {
-  names = ["SpanTypeAttributeEnricher", "ApiStatusEnricher", "EndpointEnricher", "TransactionNameEnricher", "ApiBoundaryTypeAttributeEnricher", "ErrorsAndExceptionsEnricher", "BackendEntityEnricher", "HttpAttributeEnricher", "DefaultServiceEntityEnricher", "UserAgentSpanEnricher"]
+  names = ["SpanTypeAttributeEnricher", "ApiStatusEnricher", "EndpointEnricher", "TransactionNameEnricher", "ApiBoundaryTypeAttributeEnricher", "ErrorsAndExceptionsEnricher", "BackendEntityEnricher", "HttpAttributeEnricher", "DefaultServiceEntityEnricher", "UserAgentSpanEnricher", "ServiceInternalProcessingTimeEnricher"]
 
   DefaultServiceEntityEnricher {
     class = "org.hypertrace.traceenricher.enrichment.enrichers.DefaultServiceEntityEnricher"
@@ -61,4 +61,9 @@ enricher {
     class = "org.hypertrace.traceenricher.enrichment.enrichers.GrpcAttributeEnricher"
     dependencies = ["SpanTypeAttributeEnricher", "ApiBoundaryTypeAttributeEnricher"]
   }
+
+  ServiceInternalProcessingTimeEnricher {
+    class = "org.hypertrace.traceenricher.enrichment.enrichers.ServiceInternalProcessingTimeEnricher"
+    dependencies = ["SpanTypeAttributeEnricher", "ApiBoundaryTypeAttributeEnricher"]
+  }
 }

hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/missing-downstream-entry-spans/after-enrichment.json

@@ -55,6 +55,14 @@
               "binary_value": null,
               "value_list": null,
               "value_map": null
+            },
+            "enriched.serviceInternalProcessingTime":{
+              "value": {
+                "string": "4041.0"
+              },
+              "binary_value":null,
+              "value_list":null,
+              "value_map":null
             }
           }
         }

hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/resources/configs/common/application.conf

@@ -24,7 +24,7 @@ kafka.streams.config = {
 }
 
 enricher {
-  names = ["SpanTypeAttributeEnricher", "ApiStatusEnricher", "EndpointEnricher", "TransactionNameEnricher", "ApiBoundaryTypeAttributeEnricher", "ErrorsAndExceptionsEnricher", "BackendEntityEnricher", "HttpAttributeEnricher", "DefaultServiceEntityEnricher", "UserAgentSpanEnricher", "SpaceEnricher", "EntitySpanEnricher", "ExitCallsEnricher", "TraceStatsEnricher", "GrpcAttributeEnricher"]
+  names = ["SpanTypeAttributeEnricher", "ApiStatusEnricher", "EndpointEnricher", "TransactionNameEnricher", "ApiBoundaryTypeAttributeEnricher", "ErrorsAndExceptionsEnricher", "BackendEntityEnricher", "HttpAttributeEnricher", "DefaultServiceEntityEnricher", "UserAgentSpanEnricher", "SpaceEnricher", "EntitySpanEnricher", "ExitCallsEnricher", "TraceStatsEnricher", "GrpcAttributeEnricher", "ServiceInternalProcessingTimeEnricher"]
 
   clients = {
       entity.service.config = {
@@ -115,6 +115,11 @@ enricher {
     class = "org.hypertrace.traceenricher.enrichment.enrichers.GrpcAttributeEnricher"
     dependencies = ["SpanTypeAttributeEnricher", "ApiBoundaryTypeAttributeEnricher"]
   }
+
+  ServiceInternalProcessingTimeEnricher {
+      class = "org.hypertrace.traceenricher.enrichment.enrichers.ServiceInternalProcessingTimeEnricher"
+      dependencies = ["SpanTypeAttributeEnricher", "ApiBoundaryTypeAttributeEnricher"]
+  }
 }
 
 logger {