From 0b02d5f68e3116debfb3aaac84f4635bbf5e1759 Mon Sep 17 00:00:00 2001 From: Maytas Monsereenusorn Date: Fri, 30 Jul 2021 15:05:47 +0700 Subject: [PATCH 1/4] Improve query error logging --- .../org/apache/druid/query/QueryContexts.java | 7 ++++++ .../apache/druid/query/QueryContextsTest.java | 24 +++++++++++++++++++ .../apache/druid/server/QueryLifecycle.java | 7 +++++- 3 files changed, 37 insertions(+), 1 deletion(-) diff --git a/processing/src/main/java/org/apache/druid/query/QueryContexts.java b/processing/src/main/java/org/apache/druid/query/QueryContexts.java index 4979d7ce5971..b0536c116ebb 100644 --- a/processing/src/main/java/org/apache/druid/query/QueryContexts.java +++ b/processing/src/main/java/org/apache/druid/query/QueryContexts.java @@ -65,6 +65,7 @@ public class QueryContexts public static final String RETURN_PARTIAL_RESULTS_KEY = "returnPartialResults"; public static final String USE_CACHE_KEY = "useCache"; public static final String SECONDARY_PARTITION_PRUNING_KEY = "secondaryPartitionPruning"; + public static final String LOG_QUERY_EXCEPTION_STACK_TRACE_KEY = "logQueryExceptionStackTrace"; public static final String BY_SEGMENT_KEY = "bySegment"; public static final boolean DEFAULT_BY_SEGMENT = false; @@ -87,6 +88,7 @@ public class QueryContexts public static final boolean DEFAULT_ENABLE_SQL_JOIN_LEFT_SCAN_DIRECT = false; public static final boolean DEFAULT_USE_FILTER_CNF = false; public static final boolean DEFAULT_SECONDARY_PARTITION_PRUNING = true; + public static final boolean DEFAULT_LOG_QUERY_EXCEPTION_STACK_TRACE = false; @SuppressWarnings("unused") // Used by Jackson serialization public enum Vectorize @@ -321,6 +323,11 @@ public static boolean isSecondaryPartitionPruningEnabled(Query query) return parseBoolean(query, SECONDARY_PARTITION_PRUNING_KEY, DEFAULT_SECONDARY_PARTITION_PRUNING); } + public static boolean isLogQueryExceptionStackTrace(Query query) + { + return parseBoolean(query, LOG_QUERY_EXCEPTION_STACK_TRACE_KEY, DEFAULT_LOG_QUERY_EXCEPTION_STACK_TRACE); + } + public static Query withMaxScatterGatherBytes(Query query, long maxScatterGatherBytesLimit) { Object obj = query.getContextValue(MAX_SCATTER_GATHER_BYTES_KEY); diff --git a/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java b/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java index 593216c78389..507105b79bcb 100644 --- a/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java +++ b/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java @@ -145,4 +145,28 @@ public void testGetEnableJoinLeftScanDirect() false ))); } + + @Test + public void testDefaultLogQueryExceptionStackTrace() + { + Query query = new TestQuery( + new TableDataSource("test"), + new MultipleIntervalSegmentSpec(ImmutableList.of(Intervals.of("0/100"))), + false, + ImmutableMap.of() + ); + Assert.assertFalse(QueryContexts.isLogQueryExceptionStackTrace(query)); + } + + @Test + public void testEnabledLogQueryExceptionStackTrace() + { + Query query = new TestQuery( + new TableDataSource("test"), + new MultipleIntervalSegmentSpec(ImmutableList.of(Intervals.of("0/100"))), + false, + ImmutableMap.of(QueryContexts.LOG_QUERY_EXCEPTION_STACK_TRACE_KEY, true) + ); + Assert.assertTrue(QueryContexts.isLogQueryExceptionStackTrace(query)); + } } diff --git a/server/src/main/java/org/apache/druid/server/QueryLifecycle.java b/server/src/main/java/org/apache/druid/server/QueryLifecycle.java index 5da60d4c62b1..e1eb87bd5fa0 100644 --- a/server/src/main/java/org/apache/druid/server/QueryLifecycle.java +++ b/server/src/main/java/org/apache/druid/server/QueryLifecycle.java @@ -36,6 +36,7 @@ import org.apache.druid.query.DruidMetrics; import org.apache.druid.query.GenericQueryMetricsFactory; import org.apache.druid.query.Query; +import org.apache.druid.query.QueryContexts; import org.apache.druid.query.QueryInterruptedException; import org.apache.druid.query.QueryMetrics; import org.apache.druid.query.QueryPlus; @@ -316,7 +317,11 @@ public void emitLogsAndMetrics( if (e != null) { statsMap.put("exception", e.toString()); - log.noStackTrace().warn(e, "Exception while processing queryId [%s]", baseQuery.getId()); + if (QueryContexts.isLogQueryExceptionStackTrace(baseQuery)) { + log.error(e, "Exception while processing queryId [%s]", baseQuery.getId()); + } else { + log.noStackTrace().error(e, "Exception while processing queryId [%s]", baseQuery.getId()); + } if (e instanceof QueryInterruptedException || e instanceof QueryTimeoutException) { // Mimic behavior from QueryResource, where this code was originally taken from. statsMap.put("interrupted", true); From fe084152871aeeb3abe02d131a76c82f0b7cf7d7 Mon Sep 17 00:00:00 2001 From: Maytas Monsereenusorn Date: Fri, 30 Jul 2021 15:24:30 +0700 Subject: [PATCH 2/4] add docs --- docs/querying/query-context.md | 1 + 1 file changed, 1 insertion(+) diff --git a/docs/querying/query-context.md b/docs/querying/query-context.md index a566b8bd702b..7daaa59cf7fc 100644 --- a/docs/querying/query-context.md +++ b/docs/querying/query-context.md @@ -61,6 +61,7 @@ Unless otherwise noted, the following parameters apply to all query types. |useFilterCNF|`false`| If true, Druid will attempt to convert the query filter to Conjunctive Normal Form (CNF). During query processing, columns can be pre-filtered by intersecting the bitmap indexes of all values that match the eligible filters, often greatly reducing the raw number of rows which need to be scanned. But this effect only happens for the top level filter, or individual clauses of a top level 'and' filter. As such, filters in CNF potentially have a higher chance to utilize a large amount of bitmap indexes on string columns during pre-filtering. However, this setting should be used with great caution, as it can sometimes have a negative effect on performance, and in some cases, the act of computing CNF of a filter can be expensive. We recommend hand tuning your filters to produce an optimal form if possible, or at least verifying through experimentation that using this parameter actually improves your query performance with no ill-effects.| |secondaryPartitionPruning|`true`|Enable secondary partition pruning on the Broker. The Broker will always prune unnecessary segments from the input scan based on a filter on time intervals, but if the data is further partitioned with hash or range partitioning, this option will enable additional pruning based on a filter on secondary partition dimensions.| |enableJoinLeftTableScanDirect|`false`|This flag applies to queries which have joins. For joins, where left child is a simple scan with a filter, by default, druid will run the scan as a query and the join the results to the right child on broker. Setting this flag to true overrides that behavior and druid will attempt to push the join to data servers instead. Please note that the flag could be applicable to queries even if there is no explicit join. since queries can internally translated into a join by the SQL planner.| +|logQueryExceptionStackTrace | `false` | Flag indicating whether to log the stack trace of the exception (if any) produced by the query. Primarily used for debugging. When set to false, only the exception class and message will be logged. When set to true, the exception stack trace will also be logged | ## Query-type-specific parameters From c893bea36f85ffa2be8c254575a24afe7b148e8d Mon Sep 17 00:00:00 2001 From: Maytas Monsereenusorn Date: Wed, 4 Aug 2021 15:29:02 +0700 Subject: [PATCH 3/4] address comments --- docs/querying/query-context.md | 2 +- .../java/org/apache/druid/query/QueryContexts.java | 8 ++++---- .../java/org/apache/druid/query/QueryContextsTest.java | 10 +++++----- .../java/org/apache/druid/server/QueryLifecycle.java | 2 +- 4 files changed, 11 insertions(+), 11 deletions(-) diff --git a/docs/querying/query-context.md b/docs/querying/query-context.md index 7daaa59cf7fc..bc41e74ae508 100644 --- a/docs/querying/query-context.md +++ b/docs/querying/query-context.md @@ -61,7 +61,7 @@ Unless otherwise noted, the following parameters apply to all query types. |useFilterCNF|`false`| If true, Druid will attempt to convert the query filter to Conjunctive Normal Form (CNF). During query processing, columns can be pre-filtered by intersecting the bitmap indexes of all values that match the eligible filters, often greatly reducing the raw number of rows which need to be scanned. But this effect only happens for the top level filter, or individual clauses of a top level 'and' filter. As such, filters in CNF potentially have a higher chance to utilize a large amount of bitmap indexes on string columns during pre-filtering. However, this setting should be used with great caution, as it can sometimes have a negative effect on performance, and in some cases, the act of computing CNF of a filter can be expensive. We recommend hand tuning your filters to produce an optimal form if possible, or at least verifying through experimentation that using this parameter actually improves your query performance with no ill-effects.| |secondaryPartitionPruning|`true`|Enable secondary partition pruning on the Broker. The Broker will always prune unnecessary segments from the input scan based on a filter on time intervals, but if the data is further partitioned with hash or range partitioning, this option will enable additional pruning based on a filter on secondary partition dimensions.| |enableJoinLeftTableScanDirect|`false`|This flag applies to queries which have joins. For joins, where left child is a simple scan with a filter, by default, druid will run the scan as a query and the join the results to the right child on broker. Setting this flag to true overrides that behavior and druid will attempt to push the join to data servers instead. Please note that the flag could be applicable to queries even if there is no explicit join. since queries can internally translated into a join by the SQL planner.| -|logQueryExceptionStackTrace | `false` | Flag indicating whether to log the stack trace of the exception (if any) produced by the query. Primarily used for debugging. When set to false, only the exception class and message will be logged. When set to true, the exception stack trace will also be logged | +|enableQueryDebugging| `false` | Flag indicating whether to enable debugging outputs for the query. When set to false, no additional logs or metrics will be produced (logs produced will be entirely dependent on your logging level). When set to true, the following addition logs and metrics will be produced:
- Log the stack trace of the exception (if any) produced by the query | ## Query-type-specific parameters diff --git a/processing/src/main/java/org/apache/druid/query/QueryContexts.java b/processing/src/main/java/org/apache/druid/query/QueryContexts.java index 6c37ae360a0b..879734ddb211 100644 --- a/processing/src/main/java/org/apache/druid/query/QueryContexts.java +++ b/processing/src/main/java/org/apache/druid/query/QueryContexts.java @@ -65,7 +65,7 @@ public class QueryContexts public static final String RETURN_PARTIAL_RESULTS_KEY = "returnPartialResults"; public static final String USE_CACHE_KEY = "useCache"; public static final String SECONDARY_PARTITION_PRUNING_KEY = "secondaryPartitionPruning"; - public static final String LOG_QUERY_EXCEPTION_STACK_TRACE_KEY = "logQueryExceptionStackTrace"; + public static final String ENABLE_QUERY_DEBUGGING = "enableQueryDebugging"; public static final String BY_SEGMENT_KEY = "bySegment"; public static final String BROKER_SERVICE_NAME = "brokerService"; @@ -89,7 +89,7 @@ public class QueryContexts public static final boolean DEFAULT_ENABLE_SQL_JOIN_LEFT_SCAN_DIRECT = false; public static final boolean DEFAULT_USE_FILTER_CNF = false; public static final boolean DEFAULT_SECONDARY_PARTITION_PRUNING = true; - public static final boolean DEFAULT_LOG_QUERY_EXCEPTION_STACK_TRACE = false; + public static final boolean DEFAULT_ENABLE_QUERY_DEBUGGING = false; @SuppressWarnings("unused") // Used by Jackson serialization public enum Vectorize @@ -324,9 +324,9 @@ public static boolean isSecondaryPartitionPruningEnabled(Query query) return parseBoolean(query, SECONDARY_PARTITION_PRUNING_KEY, DEFAULT_SECONDARY_PARTITION_PRUNING); } - public static boolean isLogQueryExceptionStackTrace(Query query) + public static boolean isEnableQueryDebugging(Query query) { - return parseBoolean(query, LOG_QUERY_EXCEPTION_STACK_TRACE_KEY, DEFAULT_LOG_QUERY_EXCEPTION_STACK_TRACE); + return parseBoolean(query, ENABLE_QUERY_DEBUGGING, DEFAULT_ENABLE_QUERY_DEBUGGING); } public static Query withMaxScatterGatherBytes(Query query, long maxScatterGatherBytesLimit) diff --git a/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java b/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java index c7896a29f6a4..aae62d6e1740 100644 --- a/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java +++ b/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java @@ -179,7 +179,7 @@ public void testGetBrokerServiceName_withNonStringValue() } @Test - public void testDefaultLogQueryExceptionStackTrace() + public void testDefaultEnableQueryDebugging() { Query query = new TestQuery( new TableDataSource("test"), @@ -187,18 +187,18 @@ public void testDefaultLogQueryExceptionStackTrace() false, ImmutableMap.of() ); - Assert.assertFalse(QueryContexts.isLogQueryExceptionStackTrace(query)); + Assert.assertFalse(QueryContexts.isEnableQueryDebugging(query)); } @Test - public void testEnabledLogQueryExceptionStackTrace() + public void testEnableQueryDebuggingSetToTrue() { Query query = new TestQuery( new TableDataSource("test"), new MultipleIntervalSegmentSpec(ImmutableList.of(Intervals.of("0/100"))), false, - ImmutableMap.of(QueryContexts.LOG_QUERY_EXCEPTION_STACK_TRACE_KEY, true) + ImmutableMap.of(QueryContexts.ENABLE_QUERY_DEBUGGING, true) ); - Assert.assertTrue(QueryContexts.isLogQueryExceptionStackTrace(query)); + Assert.assertTrue(QueryContexts.isEnableQueryDebugging(query)); } } diff --git a/server/src/main/java/org/apache/druid/server/QueryLifecycle.java b/server/src/main/java/org/apache/druid/server/QueryLifecycle.java index e1eb87bd5fa0..d5c08bc27e30 100644 --- a/server/src/main/java/org/apache/druid/server/QueryLifecycle.java +++ b/server/src/main/java/org/apache/druid/server/QueryLifecycle.java @@ -317,7 +317,7 @@ public void emitLogsAndMetrics( if (e != null) { statsMap.put("exception", e.toString()); - if (QueryContexts.isLogQueryExceptionStackTrace(baseQuery)) { + if (QueryContexts.isEnableQueryDebugging(baseQuery)) { log.error(e, "Exception while processing queryId [%s]", baseQuery.getId()); } else { log.noStackTrace().error(e, "Exception while processing queryId [%s]", baseQuery.getId()); From 6afc791025563249fc6f40400ce41e6fc7a844ea Mon Sep 17 00:00:00 2001 From: Maytas Monsereenusorn Date: Thu, 5 Aug 2021 16:49:37 +0700 Subject: [PATCH 4/4] address comments --- docs/querying/query-context.md | 2 +- .../main/java/org/apache/druid/query/QueryContexts.java | 8 ++++---- .../java/org/apache/druid/query/QueryContextsTest.java | 6 +++--- .../main/java/org/apache/druid/server/QueryLifecycle.java | 2 +- 4 files changed, 9 insertions(+), 9 deletions(-) diff --git a/docs/querying/query-context.md b/docs/querying/query-context.md index bc41e74ae508..b46b40fa67cf 100644 --- a/docs/querying/query-context.md +++ b/docs/querying/query-context.md @@ -61,7 +61,7 @@ Unless otherwise noted, the following parameters apply to all query types. |useFilterCNF|`false`| If true, Druid will attempt to convert the query filter to Conjunctive Normal Form (CNF). During query processing, columns can be pre-filtered by intersecting the bitmap indexes of all values that match the eligible filters, often greatly reducing the raw number of rows which need to be scanned. But this effect only happens for the top level filter, or individual clauses of a top level 'and' filter. As such, filters in CNF potentially have a higher chance to utilize a large amount of bitmap indexes on string columns during pre-filtering. However, this setting should be used with great caution, as it can sometimes have a negative effect on performance, and in some cases, the act of computing CNF of a filter can be expensive. We recommend hand tuning your filters to produce an optimal form if possible, or at least verifying through experimentation that using this parameter actually improves your query performance with no ill-effects.| |secondaryPartitionPruning|`true`|Enable secondary partition pruning on the Broker. The Broker will always prune unnecessary segments from the input scan based on a filter on time intervals, but if the data is further partitioned with hash or range partitioning, this option will enable additional pruning based on a filter on secondary partition dimensions.| |enableJoinLeftTableScanDirect|`false`|This flag applies to queries which have joins. For joins, where left child is a simple scan with a filter, by default, druid will run the scan as a query and the join the results to the right child on broker. Setting this flag to true overrides that behavior and druid will attempt to push the join to data servers instead. Please note that the flag could be applicable to queries even if there is no explicit join. since queries can internally translated into a join by the SQL planner.| -|enableQueryDebugging| `false` | Flag indicating whether to enable debugging outputs for the query. When set to false, no additional logs or metrics will be produced (logs produced will be entirely dependent on your logging level). When set to true, the following addition logs and metrics will be produced:
- Log the stack trace of the exception (if any) produced by the query | +|debug| `false` | Flag indicating whether to enable debugging outputs for the query. When set to false, no additional logs will be produced (logs produced will be entirely dependent on your logging level). When set to true, the following addition logs will be produced:
- Log the stack trace of the exception (if any) produced by the query | ## Query-type-specific parameters diff --git a/processing/src/main/java/org/apache/druid/query/QueryContexts.java b/processing/src/main/java/org/apache/druid/query/QueryContexts.java index 879734ddb211..4a293e56cf7a 100644 --- a/processing/src/main/java/org/apache/druid/query/QueryContexts.java +++ b/processing/src/main/java/org/apache/druid/query/QueryContexts.java @@ -65,7 +65,7 @@ public class QueryContexts public static final String RETURN_PARTIAL_RESULTS_KEY = "returnPartialResults"; public static final String USE_CACHE_KEY = "useCache"; public static final String SECONDARY_PARTITION_PRUNING_KEY = "secondaryPartitionPruning"; - public static final String ENABLE_QUERY_DEBUGGING = "enableQueryDebugging"; + public static final String ENABLE_DEBUG = "debug"; public static final String BY_SEGMENT_KEY = "bySegment"; public static final String BROKER_SERVICE_NAME = "brokerService"; @@ -89,7 +89,7 @@ public class QueryContexts public static final boolean DEFAULT_ENABLE_SQL_JOIN_LEFT_SCAN_DIRECT = false; public static final boolean DEFAULT_USE_FILTER_CNF = false; public static final boolean DEFAULT_SECONDARY_PARTITION_PRUNING = true; - public static final boolean DEFAULT_ENABLE_QUERY_DEBUGGING = false; + public static final boolean DEFAULT_ENABLE_DEBUG = false; @SuppressWarnings("unused") // Used by Jackson serialization public enum Vectorize @@ -324,9 +324,9 @@ public static boolean isSecondaryPartitionPruningEnabled(Query query) return parseBoolean(query, SECONDARY_PARTITION_PRUNING_KEY, DEFAULT_SECONDARY_PARTITION_PRUNING); } - public static boolean isEnableQueryDebugging(Query query) + public static boolean isDebug(Query query) { - return parseBoolean(query, ENABLE_QUERY_DEBUGGING, DEFAULT_ENABLE_QUERY_DEBUGGING); + return parseBoolean(query, ENABLE_DEBUG, DEFAULT_ENABLE_DEBUG); } public static Query withMaxScatterGatherBytes(Query query, long maxScatterGatherBytesLimit) diff --git a/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java b/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java index aae62d6e1740..764a81aec3ff 100644 --- a/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java +++ b/processing/src/test/java/org/apache/druid/query/QueryContextsTest.java @@ -187,7 +187,7 @@ public void testDefaultEnableQueryDebugging() false, ImmutableMap.of() ); - Assert.assertFalse(QueryContexts.isEnableQueryDebugging(query)); + Assert.assertFalse(QueryContexts.isDebug(query)); } @Test @@ -197,8 +197,8 @@ public void testEnableQueryDebuggingSetToTrue() new TableDataSource("test"), new MultipleIntervalSegmentSpec(ImmutableList.of(Intervals.of("0/100"))), false, - ImmutableMap.of(QueryContexts.ENABLE_QUERY_DEBUGGING, true) + ImmutableMap.of(QueryContexts.ENABLE_DEBUG, true) ); - Assert.assertTrue(QueryContexts.isEnableQueryDebugging(query)); + Assert.assertTrue(QueryContexts.isDebug(query)); } } diff --git a/server/src/main/java/org/apache/druid/server/QueryLifecycle.java b/server/src/main/java/org/apache/druid/server/QueryLifecycle.java index d5c08bc27e30..23be4e5bd3d8 100644 --- a/server/src/main/java/org/apache/druid/server/QueryLifecycle.java +++ b/server/src/main/java/org/apache/druid/server/QueryLifecycle.java @@ -317,7 +317,7 @@ public void emitLogsAndMetrics( if (e != null) { statsMap.put("exception", e.toString()); - if (QueryContexts.isEnableQueryDebugging(baseQuery)) { + if (QueryContexts.isDebug(baseQuery)) { log.error(e, "Exception while processing queryId [%s]", baseQuery.getId()); } else { log.noStackTrace().error(e, "Exception while processing queryId [%s]", baseQuery.getId());