diff --git a/catalog/core/catalog-core-standardframework/pom.xml b/catalog/core/catalog-core-standardframework/pom.xml index be58f12fee5..76714647d69 100644 --- a/catalog/core/catalog-core-standardframework/pom.xml +++ b/catalog/core/catalog-core-standardframework/pom.xml @@ -125,6 +125,11 @@ com.google.guava guava + + com.google.code.gson + gson + ${gson.version} + dev.failsafe failsafe diff --git a/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/federation/impl/TimedSource.java b/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/federation/impl/TimedSource.java index 280116963f6..566469175cc 100644 --- a/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/federation/impl/TimedSource.java +++ b/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/federation/impl/TimedSource.java @@ -79,9 +79,10 @@ public SourceResponse query(QueryRequest request) throws UnsupportedQueryExcepti // get the elapsed time in ms (rounded by adding 1/2 a ms -> 500000) int elapsedTime = Math.toIntExact(((endTime + 500000) - startTime) / 1000000); String sourceLatencyMetricKey = METRICS_SOURCE_ELAPSED_PREFIX_API + source.getId(); + String sourceMetricKey = "qm.timedsource.elapsed." + source.getId(); Map props = result.getProperties(); props.put(sourceLatencyMetricKey, elapsedTime); - props.put("qm.timedsource.elapsed", endTime - startTime); + props.put(sourceMetricKey, endTime - startTime); // copy over all the original query metrics along with the new solr metrics QueryRequest qr = result.getRequest(); diff --git a/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/impl/operations/QueryOperations.java b/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/impl/operations/QueryOperations.java index da16d0cd75d..9d7fe0efb7e 100644 --- a/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/impl/operations/QueryOperations.java +++ b/catalog/core/catalog-core-standardframework/src/main/java/ddf/catalog/impl/operations/QueryOperations.java @@ -15,6 +15,7 @@ import static ddf.catalog.Constants.QUERY_LOGGER_NAME; +import com.google.gson.Gson; import ddf.catalog.Constants; import ddf.catalog.core.versioning.DeletedMetacard; import ddf.catalog.core.versioning.MetacardVersion; @@ -73,7 +74,6 @@ import java.util.Map; import java.util.Optional; import java.util.Set; -import java.util.function.Function; import java.util.function.Supplier; import java.util.stream.Collectors; import java.util.stream.Stream; @@ -107,6 +107,12 @@ public class QueryOperations extends DescribableImpl { public static final String QM_REQUEST_POLICYMAP = QMB + "request-policymap."; public static final String QM_RESPONSE_POLICYMAP = QMB + "response-policymap."; public static final String QM_ELAPSED = ".elapsed"; + public static final String QM_PRE_QUERY = QMB + "pre-query" + QM_ELAPSED; + public static final String QM_DO_QUERY = QMB + "do-query" + QM_ELAPSED; + public static final String QM_POST_QUERY = QMB + "post-query" + QM_ELAPSED; + + public static final String QM_TOTAL_ELAPSED = QMB + "total" + QM_ELAPSED; + public static final String QM_TIMED_SOURCE = QMB + "timedsource" + QM_ELAPSED + "."; public static final String QM_RESPONSE_INJECTATTRIBUTES = QMB + "response-injectattributes" + QM_ELAPSED; @@ -202,6 +208,7 @@ QueryResponse query( boolean overrideFanoutRename, boolean fanoutEnabled) throws UnsupportedQueryException, FederationException { + long queryStart = System.nanoTime(); FederationStrategy fedStrategy = strategy; QueryResponse queryResponse; @@ -209,6 +216,7 @@ QueryResponse query( queryRequest = setFlagsOnRequest(queryRequest); try { + long start = System.nanoTime(); queryRequest = addTraceId(queryRequest); queryRequest = validateQueryRequest(queryRequest); queryRequest = getFanoutQuery(queryRequest, fanoutEnabled); @@ -230,21 +238,25 @@ QueryResponse query( } } - long start = System.nanoTime(); + long preQueryTime = System.nanoTime() - start; + long doQueryStart = System.nanoTime(); queryResponse = doQuery(queryRequest, fedStrategy); - long elapsedTime = System.nanoTime() - start; - putMetricsDuration(queryResponse, QMB + "do-query" + QM_ELAPSED, elapsedTime); + putMetricsDuration(queryResponse, QM_PRE_QUERY, preQueryTime); + putMetricsDuration(queryResponse, QM_DO_QUERY, System.nanoTime() - doQueryStart); // Allow callers to determine the total results returned from the query; this value // may differ from the number of filtered results after processing plugins have been run. queryResponse.getProperties().put("actualResultSize", queryResponse.getResults().size()); LOGGER.trace("BeforePostQueryFilter result size: {}", queryResponse.getResults().size()); + long postQueryStart = System.nanoTime(); queryResponse = injectAttributes(queryResponse); queryResponse = validateFixQueryResponse(queryResponse, overrideFanoutRename, fanoutEnabled); queryResponse = postProcessPreAuthorizationPlugins(queryResponse); queryResponse = populateQueryResponsePolicyMap(queryResponse); queryResponse = processPostQueryAccessPlugins(queryResponse); queryResponse = processPostQueryPlugins(queryResponse); + putMetricsDuration(queryResponse, QM_POST_QUERY, System.nanoTime() - postQueryStart); + putMetricsDuration(queryResponse, QM_TOTAL_ELAPSED, System.nanoTime() - queryStart); log(queryResponse); @@ -276,54 +288,46 @@ private void log(QueryResponse queryResponse) { } } } - if (QUERY_LOGGER.isDebugEnabled()) { - // Combine the request and response metrics to log - Map allMetrics = - collectQueryMetrics( - queryResponse.getRequest().getProperties(), queryResponse.getProperties()); - QUERY_LOGGER.debug("QueryMetrics: {}", serializeMetrics(allMetrics, QMB)); + Map requestProperties = + queryResponse.getRequest() == null ? null : queryResponse.getRequest().getProperties(); + Map allProperties = + collectQueryProperties(requestProperties, queryResponse.getProperties()); + if (Boolean.TRUE.equals(allProperties.get("metrics-enabled"))) { + QUERY_LOGGER.info("QueryMetrics: {}", getQueryMetricsLog(allProperties)); } } - protected static Map collectQueryMetrics( - Map requestMetrics, Map responseMetrics) { - Map allMetrics = new HashMap<>(); - if (requestMetrics != null) { - allMetrics.putAll(filterMetrics(requestMetrics, QMB)); + protected static String getQueryMetricsLog(Map properties) { + Map metricsMap = new HashMap<>(); + // Combine the request and response metrics to log + metricsMap.put("total-duration", properties.get(QM_TOTAL_ELAPSED)); + metricsMap.put("prequery-duration", properties.get(QM_PRE_QUERY)); + metricsMap.put("query-duration", properties.get(QM_DO_QUERY)); + metricsMap.put("postquery-duration", properties.get(QM_POST_QUERY)); + HashMap sourceDurationMap = new HashMap<>(); + properties.entrySet().stream() + .filter(e -> e.getKey() != null && e.getKey().startsWith(QM_TIMED_SOURCE)) + .forEach(e -> sourceDurationMap.put(e.getKey().split(QM_TIMED_SOURCE)[1], e.getValue())); + metricsMap.put("source-duration", sourceDurationMap); + HashMap additionalQueryMetrics = + (HashMap) properties.get("additional-query-metrics"); + if (additionalQueryMetrics != null) { + metricsMap.putAll(additionalQueryMetrics); } - if (responseMetrics != null) { - allMetrics.putAll(filterMetrics(responseMetrics, QMB)); - } - return allMetrics; - } - protected static Map filterMetrics( - Map src, String base) { - Map filtered = - src.entrySet().stream() - .filter(x -> x.getKey().startsWith(base)) - .collect( - Collectors.toMap( - Map.Entry::getKey, entry -> replaceNullWithNilID(entry, Map.Entry::getValue))); - return filtered; + return new Gson().toJson(metricsMap); } - /** - * replaceNullWithNilID checks the values of a Map.Entry for null - if found, the value is - * replaced with the NIL UUID value (00000000-0000-0000-0000-00000000) with the "-"s removed. This - * can occur when queries don't originate from an endpoint and trace-ids are not injected before - * calling a query operation. - * - * @param entry the Map.Entry being processed - * @param valueExtractor method to retrieve the value from the entry - * @return the original value if non-null, or the NIL UUID value - * @param Type of the key - * @param Type of the value - */ - private static V replaceNullWithNilID( - Map.Entry entry, Function, V> valueExtractor) { - V originalValue = valueExtractor.apply(entry); - return originalValue == null ? (V) NIL_UUID : originalValue; + protected static Map collectQueryProperties( + Map requestProps, Map responseProps) { + Map allProperties = new HashMap<>(); + if (requestProps != null) { + allProperties.putAll(requestProps); + } + if (responseProps != null) { + allProperties.putAll(responseProps); + } + return allProperties; } protected static String serializeMetrics(Map props, String base) { diff --git a/catalog/core/catalog-core-standardframework/src/test/java/ddf/catalog/impl/operations/QueryOperationsTest.java b/catalog/core/catalog-core-standardframework/src/test/java/ddf/catalog/impl/operations/QueryOperationsTest.java index 77a96167cd4..69c353cf593 100644 --- a/catalog/core/catalog-core-standardframework/src/test/java/ddf/catalog/impl/operations/QueryOperationsTest.java +++ b/catalog/core/catalog-core-standardframework/src/test/java/ddf/catalog/impl/operations/QueryOperationsTest.java @@ -18,10 +18,15 @@ import static org.junit.Assert.assertNotNull; import static org.junit.Assert.assertThat; +import ddf.catalog.operation.QueryResponse; +import ddf.catalog.operation.impl.QueryImpl; +import ddf.catalog.operation.impl.QueryRequestImpl; +import ddf.catalog.operation.impl.QueryResponseImpl; import java.io.Serializable; import java.util.HashMap; import java.util.Map; import org.junit.Test; +import org.opengis.filter.Filter; public class QueryOperationsTest { @@ -42,42 +47,13 @@ public void testCollectQueryMetrics() throws NullPointerException { respMetrics.put(QueryOperations.QM_POSTQUERY + "metric2" + QueryOperations.QM_ELAPSED, "56789"); respMetrics.put(QueryOperations.QM_POSTQUERY + "metric3" + QueryOperations.QM_ELAPSED, "98765"); - noQueryMetrics.put("some.metrics", "123"); - noQueryMetrics.put("other.metrics", "456"); - - noTraceIdMetrics.put( - QueryOperations.QM_POSTQUERY + "metric1" + QueryOperations.QM_ELAPSED, "45678"); - noTraceIdMetrics.put( - QueryOperations.QM_POSTQUERY + "metric2" + QueryOperations.QM_ELAPSED, "56789"); - noTraceIdMetrics.put( - QueryOperations.QM_POSTQUERY + "metric3" + QueryOperations.QM_ELAPSED, "98765"); - - nullTraceIdMetrics.put(QueryOperations.QM_TRACEID, null); - nullTraceIdMetrics.put( - QueryOperations.QM_POSTQUERY + "metric1" + QueryOperations.QM_ELAPSED, "45678"); - nullTraceIdMetrics.put( - QueryOperations.QM_POSTQUERY + "metric2" + QueryOperations.QM_ELAPSED, "56789"); - nullTraceIdMetrics.put( - QueryOperations.QM_POSTQUERY + "metric3" + QueryOperations.QM_ELAPSED, "98765"); - - Map metrics = QueryOperations.collectQueryMetrics(null, null); + Map metrics = QueryOperations.collectQueryProperties(null, null); assertNotNull(metrics); assertThat(metrics.size(), is(0)); String metricsString = QueryOperations.serializeMetrics(metrics, QueryOperations.QMB); assertThat(metricsString, is("trace-id: null")); - metrics = QueryOperations.collectQueryMetrics(noQueryMetrics, null); - assertNotNull(metrics); - assertThat(metrics.size(), is(0)); - - metrics = QueryOperations.collectQueryMetrics(noTraceIdMetrics, null); - assertNotNull(metrics); - - metrics = QueryOperations.collectQueryMetrics(nullTraceIdMetrics, null); - assertNotNull(metrics); - assertThat(metrics.get(QueryOperations.QM_TRACEID), is(QueryOperations.NIL_UUID)); - - metrics = QueryOperations.collectQueryMetrics(reqMetrics, null); + metrics = QueryOperations.collectQueryProperties(reqMetrics, null); assertNotNull(metrics); assertThat(metrics.size(), is(reqMetrics.size())); metricsString = QueryOperations.serializeMetrics(metrics, QueryOperations.QMB); @@ -91,7 +67,7 @@ public void testCollectQueryMetrics() throws NullPointerException { containsString( QueryOperations.QM_PREQUERY + "metric2" + QueryOperations.QM_ELAPSED + ": 34567")); - metrics = QueryOperations.collectQueryMetrics(null, respMetrics); + metrics = QueryOperations.collectQueryProperties(null, respMetrics); assertNotNull(metrics); assertThat(metrics.size(), is(respMetrics.size())); metricsString = QueryOperations.serializeMetrics(metrics, QueryOperations.QMB); @@ -109,7 +85,7 @@ public void testCollectQueryMetrics() throws NullPointerException { containsString( QueryOperations.QM_POSTQUERY + "metric3" + QueryOperations.QM_ELAPSED + ": 98765")); - metrics = QueryOperations.collectQueryMetrics(reqMetrics, respMetrics); + metrics = QueryOperations.collectQueryProperties(reqMetrics, respMetrics); assertNotNull(metrics); // trace-id from each is merged into 1 assertThat(metrics.size(), is(reqMetrics.size() + respMetrics.size() - 1)); @@ -136,4 +112,24 @@ public void testCollectQueryMetrics() throws NullPointerException { containsString( QueryOperations.QM_POSTQUERY + "metric3" + QueryOperations.QM_ELAPSED + ": 98765")); } + + @Test + public void testLogQueryMetrics() throws NullPointerException { + QueryResponse queryResponse = + new QueryResponseImpl(new QueryRequestImpl(new QueryImpl(Filter.INCLUDE))); + Map respProps = new HashMap<>(); + + respProps.put(QueryOperations.QM_TRACEID, "12345"); + respProps.put(QueryOperations.QM_PREQUERY + "metric" + QueryOperations.QM_ELAPSED, "23456"); + respProps.put(QueryOperations.QM_DO_QUERY + "metric" + QueryOperations.QM_ELAPSED, "23456"); + respProps.put( + QueryOperations.QM_TOTAL_ELAPSED + "metric" + QueryOperations.QM_ELAPSED, "523456"); + respProps.put(QueryOperations.QM_POSTQUERY + "metric" + QueryOperations.QM_ELAPSED, "45678"); + respProps.put("metrics-enabled", true); + respProps.put("additional-query-metrics", new HashMap<>()); + + queryResponse.getProperties().putAll(respProps); + String queryMetricsLog = QueryOperations.getQueryMetricsLog(queryResponse.getProperties()); + assertNotNull(queryMetricsLog); + } }