diff --git a/hypertrace-trace-enricher/enriched-span-constants/src/main/java/org/hypertrace/traceenricher/enrichedspan/constants/EnrichedSpanConstants.java b/hypertrace-trace-enricher/enriched-span-constants/src/main/java/org/hypertrace/traceenricher/enrichedspan/constants/EnrichedSpanConstants.java index 696b3875f..904aeb218 100644 --- a/hypertrace-trace-enricher/enriched-span-constants/src/main/java/org/hypertrace/traceenricher/enrichedspan/constants/EnrichedSpanConstants.java +++ b/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. diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/enrichers/ServiceInternalProcessingTimeEnricher.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/enrichers/ServiceInternalProcessingTimeEnricher.java new file mode 100644 index 000000000..7d048af22 --- /dev/null +++ b/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> apiNodeList = apiTraceGraph.getApiNodeList(); + for (ApiNode apiNode : apiNodeList) { + List exitApiBoundaryEvents = apiNode.getExitApiBoundaryEvents(); + List 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 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 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(); + } +} diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/java/org/hypertrace/traceenricher/enrichment/enrichers/ServiceInternalProcessingTimeEnricherTest.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/java/org/hypertrace/traceenricher/enrichment/enrichers/ServiceInternalProcessingTimeEnricherTest.java new file mode 100644 index 000000000..5eeb13f2c --- /dev/null +++ b/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 datumReader = + new SpecificDatumReader<>(StructuredTrace.getClassSchema()); + DataFileReader 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 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 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 getEntryEventsForService( + List 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()); + } +} diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/enricher.conf b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/enricher.conf index ea6b6bd98..61e31b523 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/enricher.conf +++ b/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"] + } } \ No newline at end of file diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/missing-downstream-entry-spans/after-enrichment.json b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/missing-downstream-entry-spans/after-enrichment.json index 37028d617..78753e446 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/test/resources/missing-downstream-entry-spans/after-enrichment.json +++ b/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 } } } diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/resources/configs/common/application.conf b/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/resources/configs/common/application.conf index b9c237b0b..48b6ab453 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/resources/configs/common/application.conf +++ b/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 {