From f0d87b2a527d8adb549463fdf22d24720801e904 Mon Sep 17 00:00:00 2001 From: Ronak Date: Fri, 8 Jan 2021 01:18:13 +0530 Subject: [PATCH 1/6] fix for performance --- .../trace/util/ApiTraceGraph.java | 8 +++- .../util/StructuredTraceGraphBuilder.java | 47 +++++++++++++++++++ .../enrichment/AbstractTraceEnricher.java | 14 +++++- .../DefaultServiceEntityEnricher.java | 4 +- .../StructuredTraceEnrichProcessor.java | 9 ++++ 5 files changed, 77 insertions(+), 5 deletions(-) create mode 100644 hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java index 6dc73ce3c..a15289b56 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java @@ -2,6 +2,8 @@ import com.google.common.collect.Sets; import java.nio.ByteBuffer; +import java.time.Duration; +import java.time.Instant; import java.util.ArrayList; import java.util.HashMap; import java.util.HashSet; @@ -178,7 +180,11 @@ private Pair, List> getEventsInApiBoundary( } public ApiTraceGraph build() { - StructuredTraceGraph graph = StructuredTraceGraph.createGraph(trace); + Instant start = Instant.now(); + StructuredTraceGraph graph = StructuredTraceGraphBuilder.buildGraph(trace); + Instant finish = Instant.now(); + long timeElapsed = Duration.between(start, finish).toMillis(); + LOGGER.info("Time taken building structure trace time:{}", timeElapsed); List> apiNodes = buildApiNodes(graph); this.setNodeList(apiNodes); diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java new file mode 100644 index 000000000..9b5aac9de --- /dev/null +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java @@ -0,0 +1,47 @@ +package org.hypertrace.traceenricher.trace.util; + +import org.hypertrace.core.datamodel.StructuredTrace; +import org.hypertrace.core.datamodel.shared.StructuredTraceGraph; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +public class StructuredTraceGraphBuilder { + private static final Logger LOG = LoggerFactory.getLogger(StructuredTraceGraphBuilder.class); + + private static ThreadLocal cachedGraph = new ThreadLocal<>(); + private static ThreadLocal cachedTrace = new ThreadLocal<>(); + + public static StructuredTraceGraph buildGraph(StructuredTrace trace) { + if (cachedTrace.get() == null) { + LOG.info("Building structured trace graph. Reason: no cached trace"); + StructuredTraceGraph graph = StructuredTraceGraph.createGraph(trace); + cachedTrace.set(StructuredTrace.newBuilder(trace).build()); + cachedGraph.set(graph); + return graph; + } + + if (!cachedTrace.get().getCustomerId().equals(trace.getCustomerId()) || + !cachedTrace.get().getTraceId().equals(trace.getTraceId())) { + LOG.info("Building structured trace graph. Reason: cached trace and current trace doesn't not match"); + StructuredTraceGraph graph = StructuredTraceGraph.createGraph(trace); + cachedTrace.set(StructuredTrace.newBuilder(trace).build()); + cachedGraph.set(graph); + return graph; + } + + // trace internally changed + if(cachedTrace.get().getEntityList().size() != trace.getEntityList().size() || + cachedTrace.get().getEventList().size() != trace.getEventList().size() || + cachedTrace.get().getEntityEdgeList().size() != trace.getEntityEdgeList().size() || + cachedTrace.get().getEntityEventEdgeList().size() != trace.getEntityEventEdgeList().size() || + cachedTrace.get().getEventEdgeList().size() != trace.getEventEdgeList().size()) { + LOG.info("Building structured trace graph. Reason: cached trace and current trace have different size"); + StructuredTraceGraph graph = StructuredTraceGraph.createGraph(trace); + cachedTrace.set(StructuredTrace.newBuilder(trace).build()); + cachedGraph.set(graph); + return graph; + } + + return cachedGraph.get(); + } +} diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java index 4c8fd3a1d..7cccfab06 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java @@ -2,6 +2,8 @@ import com.google.common.collect.Lists; import com.typesafe.config.Config; +import java.time.Duration; +import java.time.Instant; import java.util.HashSet; import java.util.List; import java.util.Objects; @@ -16,8 +18,13 @@ import org.hypertrace.core.datamodel.StructuredTrace; import org.hypertrace.core.datamodel.shared.StructuredTraceGraph; import org.hypertrace.entity.data.service.client.EntityDataServiceClientProvider; +import org.hypertrace.traceenricher.trace.util.StructuredTraceGraphBuilder; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; public abstract class AbstractTraceEnricher implements Enricher { + private static final Logger LOG = LoggerFactory.getLogger(AbstractTraceEnricher.class); + @Override public void init(Config enricherConfig, EntityDataServiceClientProvider provider) { @@ -52,7 +59,12 @@ public void enrichTrace(StructuredTrace trace) { * Wrapper to the structure graph factory for testing */ public StructuredTraceGraph buildGraph(StructuredTrace trace) { - return StructuredTraceGraph.createGraph(trace); + Instant start = Instant.now(); + StructuredTraceGraph graph = StructuredTraceGraphBuilder.buildGraph(trace); + Instant finish = Instant.now(); + long timeElapsed = Duration.between(start, finish).toMillis(); + LOG.info("Time taken building structure trace time:{}", timeElapsed); + return graph; } @Nullable diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/enrichers/DefaultServiceEntityEnricher.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/enrichers/DefaultServiceEntityEnricher.java index f2b7f43de..e68d0c6db 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/enrichers/DefaultServiceEntityEnricher.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/enrichers/DefaultServiceEntityEnricher.java @@ -10,8 +10,6 @@ import org.hypertrace.core.datamodel.shared.SpanAttributeUtils; import org.hypertrace.core.datamodel.shared.StructuredTraceGraph; import org.hypertrace.core.datamodel.shared.trace.AttributeValueCreator; -import org.hypertrace.core.span.constants.RawSpanConstants; -import org.hypertrace.core.span.constants.v1.JaegerAttribute; import org.hypertrace.entity.constants.v1.ServiceAttribute; import org.hypertrace.entity.data.service.client.EdsClient; import org.hypertrace.entity.data.service.client.EntityDataServiceClientProvider; @@ -69,7 +67,7 @@ public void enrichEvent(StructuredTrace trace, Event event) { // 2. Enrich the exit span with the parent span's service entity. // This will enable creating an edge between the exit span and the backend - StructuredTraceGraph graph = StructuredTraceGraph.createGraph(trace); + StructuredTraceGraph graph = buildGraph(trace); if (EnrichedSpanUtils.isExitSpan(event) && SpanAttributeUtils.isLeafSpan(graph, event)) { String parentSvcName = findServiceNameOfFirstAncestorThatIsNotAnExitSpanAndBelongsToADifferentService(event, diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java b/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java index 35bc47ed8..90cad3db0 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java @@ -5,6 +5,8 @@ import static org.hypertrace.traceenricher.trace.enricher.StructuredTraceEnricherConstants.STRUCTURED_TRACES_ENRICHMENT_JOB_CONFIG_KEY; import com.typesafe.config.Config; +import java.time.Duration; +import java.time.Instant; import java.util.LinkedHashMap; import java.util.List; import java.util.Map; @@ -15,10 +17,13 @@ import org.hypertrace.entity.data.service.client.DefaultEdsClientProvider; import org.hypertrace.traceenricher.enrichment.EnrichmentProcessor; import org.hypertrace.traceenricher.enrichment.EnrichmentRegistry; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; public class StructuredTraceEnrichProcessor implements Transformer> { + private static final Logger logger = LoggerFactory.getLogger(StructuredTraceEnrichProcessor.class); private static EnrichmentProcessor processor = null; @Override @@ -38,7 +43,11 @@ public void init(ProcessorContext context) { @Override public KeyValue transform(String key, StructuredTrace value) { + Instant start = Instant.now(); processor.process(value); + Instant finish = Instant.now(); + long timeElapsed = Duration.between(start, finish).toMillis(); + logger.info("Enrichment process took time:{} for key:{}", timeElapsed, key); return new KeyValue<>(null, value); } From c6a8118b26f8a7f18ea6edc25b5316a6ff044077 Mon Sep 17 00:00:00 2001 From: Ronak Date: Fri, 8 Jan 2021 13:22:45 +0530 Subject: [PATCH 2/6] functional validation --- .../trace/enricher/StructuredTraceEnrichProcessor.java | 2 ++ 1 file changed, 2 insertions(+) diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java b/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java index 90cad3db0..b1510a88b 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java @@ -44,10 +44,12 @@ public void init(ProcessorContext context) { @Override public KeyValue transform(String key, StructuredTrace value) { Instant start = Instant.now(); + logger.info("Structure Trace:{}", value.toString()); processor.process(value); Instant finish = Instant.now(); long timeElapsed = Duration.between(start, finish).toMillis(); logger.info("Enrichment process took time:{} for key:{}", timeElapsed, key); + logger.info("Enriched Structure Trace:{}", value.toString()); return new KeyValue<>(null, value); } From 4a073192f3534ef806733692a1ddec7b3aa7ce4f Mon Sep 17 00:00:00 2001 From: Ronak Date: Fri, 8 Jan 2021 16:13:28 +0530 Subject: [PATCH 3/6] changes logs --- .../org/hypertrace/traceenricher/util/AvroToJsonLogger.java | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java index ce0cbf9b0..bb5f36ae7 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java @@ -29,12 +29,12 @@ public static String convertToJsonString(T object } public static void log(Logger logger, String fmt, T object) { - if (logger.isDebugEnabled()) { + //if (logger.isDebugEnabled()) { try { - logger.debug(fmt, convertToJsonString(object, object.getSchema())); + logger.info(fmt, convertToJsonString(object, object.getSchema())); } catch (IOException e) { logger.warn("An exception occured while converting avro to JSON string", e); } - } + //} } } From 499c1aa0fb50d44019d0b1849cd0d0b08e3ff67f Mon Sep 17 00:00:00 2001 From: Ronak Date: Mon, 11 Jan 2021 09:44:44 +0530 Subject: [PATCH 4/6] cleaning PR by removing measuing logging codes --- .../traceenricher/trace/util/ApiTraceGraph.java | 6 ------ .../traceenricher/enrichment/AbstractTraceEnricher.java | 9 +-------- .../hypertrace/traceenricher/util/AvroToJsonLogger.java | 6 +++--- .../trace/enricher/StructuredTraceEnrichProcessor.java | 4 +--- 4 files changed, 5 insertions(+), 20 deletions(-) diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java index a15289b56..69027113c 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/ApiTraceGraph.java @@ -2,8 +2,6 @@ import com.google.common.collect.Sets; import java.nio.ByteBuffer; -import java.time.Duration; -import java.time.Instant; import java.util.ArrayList; import java.util.HashMap; import java.util.HashSet; @@ -180,11 +178,7 @@ private Pair, List> getEventsInApiBoundary( } public ApiTraceGraph build() { - Instant start = Instant.now(); StructuredTraceGraph graph = StructuredTraceGraphBuilder.buildGraph(trace); - Instant finish = Instant.now(); - long timeElapsed = Duration.between(start, finish).toMillis(); - LOGGER.info("Time taken building structure trace time:{}", timeElapsed); List> apiNodes = buildApiNodes(graph); this.setNodeList(apiNodes); diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java index 7cccfab06..f7aca83f7 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java @@ -2,8 +2,6 @@ import com.google.common.collect.Lists; import com.typesafe.config.Config; -import java.time.Duration; -import java.time.Instant; import java.util.HashSet; import java.util.List; import java.util.Objects; @@ -59,12 +57,7 @@ public void enrichTrace(StructuredTrace trace) { * Wrapper to the structure graph factory for testing */ public StructuredTraceGraph buildGraph(StructuredTrace trace) { - Instant start = Instant.now(); - StructuredTraceGraph graph = StructuredTraceGraphBuilder.buildGraph(trace); - Instant finish = Instant.now(); - long timeElapsed = Duration.between(start, finish).toMillis(); - LOG.info("Time taken building structure trace time:{}", timeElapsed); - return graph; + return StructuredTraceGraphBuilder.buildGraph(trace); } @Nullable diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java index bb5f36ae7..ce0cbf9b0 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/util/AvroToJsonLogger.java @@ -29,12 +29,12 @@ public static String convertToJsonString(T object } public static void log(Logger logger, String fmt, T object) { - //if (logger.isDebugEnabled()) { + if (logger.isDebugEnabled()) { try { - logger.info(fmt, convertToJsonString(object, object.getSchema())); + logger.debug(fmt, convertToJsonString(object, object.getSchema())); } catch (IOException e) { logger.warn("An exception occured while converting avro to JSON string", e); } - //} + } } } diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java b/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java index b1510a88b..28a9fb292 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher/src/main/java/org/hypertrace/traceenricher/trace/enricher/StructuredTraceEnrichProcessor.java @@ -44,12 +44,10 @@ public void init(ProcessorContext context) { @Override public KeyValue transform(String key, StructuredTrace value) { Instant start = Instant.now(); - logger.info("Structure Trace:{}", value.toString()); processor.process(value); Instant finish = Instant.now(); long timeElapsed = Duration.between(start, finish).toMillis(); - logger.info("Enrichment process took time:{} for key:{}", timeElapsed, key); - logger.info("Enriched Structure Trace:{}", value.toString()); + logger.debug("Time taken by enrichment process for key:{} is :{}", key, timeElapsed); return new KeyValue<>(null, value); } From 6ae6b395617b0a8409753e8ff123a8c962e77a5e Mon Sep 17 00:00:00 2001 From: Ronak Date: Mon, 11 Jan 2021 09:48:14 +0530 Subject: [PATCH 5/6] Removes un-used logger --- .../traceenricher/enrichment/AbstractTraceEnricher.java | 4 ---- 1 file changed, 4 deletions(-) diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java index f7aca83f7..ef9e6abae 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-impl/src/main/java/org/hypertrace/traceenricher/enrichment/AbstractTraceEnricher.java @@ -17,12 +17,8 @@ import org.hypertrace.core.datamodel.shared.StructuredTraceGraph; import org.hypertrace.entity.data.service.client.EntityDataServiceClientProvider; import org.hypertrace.traceenricher.trace.util.StructuredTraceGraphBuilder; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; public abstract class AbstractTraceEnricher implements Enricher { - private static final Logger LOG = LoggerFactory.getLogger(AbstractTraceEnricher.class); - @Override public void init(Config enricherConfig, EntityDataServiceClientProvider provider) { From f2831e1296745a968e1fa9ea2f8ba38644931a48 Mon Sep 17 00:00:00 2001 From: Ronak Date: Mon, 11 Jan 2021 11:56:14 +0530 Subject: [PATCH 6/6] Adds comments for redability --- .../traceenricher/trace/util/StructuredTraceGraphBuilder.java | 2 ++ 1 file changed, 2 insertions(+) diff --git a/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java index 9b5aac9de..c2d0b6d83 100644 --- a/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java +++ b/hypertrace-trace-enricher/hypertrace-trace-enricher-api/src/main/java/org/hypertrace/traceenricher/trace/util/StructuredTraceGraphBuilder.java @@ -12,6 +12,7 @@ public class StructuredTraceGraphBuilder { private static ThreadLocal cachedTrace = new ThreadLocal<>(); public static StructuredTraceGraph buildGraph(StructuredTrace trace) { + // trace doesn't exist if (cachedTrace.get() == null) { LOG.info("Building structured trace graph. Reason: no cached trace"); StructuredTraceGraph graph = StructuredTraceGraph.createGraph(trace); @@ -20,6 +21,7 @@ public static StructuredTraceGraph buildGraph(StructuredTrace trace) { return graph; } + // is processed and cached are same trace? if (!cachedTrace.get().getCustomerId().equals(trace.getCustomerId()) || !cachedTrace.get().getTraceId().equals(trace.getTraceId())) { LOG.info("Building structured trace graph. Reason: cached trace and current trace doesn't not match");