Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[2.29.x] Improve query metrics logging #6823

Open
wants to merge 2 commits into
base: 2.29.x
Choose a base branch
from
+85 −79
Open

[2.29.x] Improve query metrics logging #6823

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
057b76c
Saving progress
zkirksey Oct 29, 2024
76c3a21
Fixed deprecated json dependency
zkirksey Dec 11, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions catalog/core/catalog-core-standardframework/pom.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -125,6 +125,11 @@
<groupId>com.google.guava</groupId>
<artifactId>guava</artifactId>
</dependency>
<dependency>
<groupId>com.google.code.gson</groupId>
<artifactId>gson</artifactId>
<version>${gson.version}</version>
</dependency>
<dependency>
<groupId>dev.failsafe</groupId>
<artifactId>failsafe</artifactId>
Expand Down
3 changes: 2 additions & 1 deletion ...catalog-core-standardframework/src/main/java/ddf/catalog/federation/impl/TimedSource.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<String, Serializable> 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();
Expand Down
94 changes: 49 additions & 45 deletions ...log-core-standardframework/src/main/java/ddf/catalog/impl/operations/QueryOperations.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -202,13 +208,15 @@ QueryResponse query(
boolean overrideFanoutRename,
boolean fanoutEnabled)
throws UnsupportedQueryException, FederationException {
long queryStart = System.nanoTime();

FederationStrategy fedStrategy = strategy;
QueryResponse queryResponse;

queryRequest = setFlagsOnRequest(queryRequest);

try {
long start = System.nanoTime();
queryRequest = addTraceId(queryRequest);
queryRequest = validateQueryRequest(queryRequest);
queryRequest = getFanoutQuery(queryRequest, fanoutEnabled);
Expand All @@ -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);

Expand Down Expand Up @@ -276,54 +288,46 @@ private void log(QueryResponse queryResponse) {
}
}
}
if (QUERY_LOGGER.isDebugEnabled()) {
// Combine the request and response metrics to log
Map<String, Serializable> allMetrics =
collectQueryMetrics(
queryResponse.getRequest().getProperties(), queryResponse.getProperties());
QUERY_LOGGER.debug("QueryMetrics: {}", serializeMetrics(allMetrics, QMB));
Map<String, Serializable> requestProperties =
queryResponse.getRequest() == null ? null : queryResponse.getRequest().getProperties();
Map<String, Serializable> allProperties =
collectQueryProperties(requestProperties, queryResponse.getProperties());
if (Boolean.TRUE.equals(allProperties.get("metrics-enabled"))) {
QUERY_LOGGER.info("QueryMetrics: {}", getQueryMetricsLog(allProperties));
}
}

protected static Map<String, Serializable> collectQueryMetrics(
Map<String, Serializable> requestMetrics, Map<String, Serializable> responseMetrics) {
Map<String, Serializable> allMetrics = new HashMap<>();
if (requestMetrics != null) {
allMetrics.putAll(filterMetrics(requestMetrics, QMB));
protected static String getQueryMetricsLog(Map<String, Serializable> properties) {
Map<String, Serializable> 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<String, Serializable> 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<String, Serializable> additionalQueryMetrics =
(HashMap<String, Serializable>) properties.get("additional-query-metrics");
if (additionalQueryMetrics != null) {
metricsMap.putAll(additionalQueryMetrics);
}
if (responseMetrics != null) {
allMetrics.putAll(filterMetrics(responseMetrics, QMB));
}
return allMetrics;
}

protected static Map<String, Serializable> filterMetrics(
Map<String, Serializable> src, String base) {
Map<String, Serializable> 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 <K> Type of the key
* @param <V> Type of the value
*/
private static <K, V> V replaceNullWithNilID(
Map.Entry<K, V> entry, Function<Map.Entry<K, V>, V> valueExtractor) {
V originalValue = valueExtractor.apply(entry);
return originalValue == null ? (V) NIL_UUID : originalValue;
protected static Map<String, Serializable> collectQueryProperties(
Map<String, Serializable> requestProps, Map<String, Serializable> responseProps) {
Map<String, Serializable> allProperties = new HashMap<>();
if (requestProps != null) {
allProperties.putAll(requestProps);
}
if (responseProps != null) {
allProperties.putAll(responseProps);
}
return allProperties;
}

protected static String serializeMetrics(Map<String, Serializable> props, String base) {
Expand Down
62 changes: 29 additions & 33 deletions ...core-standardframework/src/test/java/ddf/catalog/impl/operations/QueryOperationsTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {

Expand All @@ -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<String, Serializable> metrics = QueryOperations.collectQueryMetrics(null, null);
Map<String, Serializable> 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);
Expand All @@ -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);
Expand All @@ -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));
Expand All @@ -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<String, Serializable> 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);
}
}