Repository: phoenix Updated Branches: refs/heads/master bca79af4a -> 1f54dfe76
First pass at PHOENIX-1198: added custom annotations to client-side log lines that are within the scope of a user operation Project: http://git-wip-us.apache.org/repos/asf/phoenix/repo Commit: http://git-wip-us.apache.org/repos/asf/phoenix/commit/1f54dfe7 Tree: http://git-wip-us.apache.org/repos/asf/phoenix/tree/1f54dfe7 Diff: http://git-wip-us.apache.org/repos/asf/phoenix/diff/1f54dfe7 Branch: refs/heads/master Commit: 1f54dfe7691e73f21bea2a67a1fb42edac706641 Parents: bca79af Author: Eli Levine <elilev...@apache.org> Authored: Fri Sep 19 16:13:05 2014 -0700 Committer: Eli Levine <elilev...@apache.org> Committed: Fri Sep 19 16:13:05 2014 -0700 ---------------------------------------------------------------------- .../phoenix/trace/PhoenixTracingEndToEndIT.java | 2 +- .../apache/phoenix/cache/ServerCacheClient.java | 23 +++++++--- .../apache/phoenix/execute/HashJoinPlan.java | 16 +++++-- .../org/apache/phoenix/query/QueryServices.java | 1 + .../org/apache/phoenix/trace/TraceReader.java | 24 ++++++++--- .../org/apache/phoenix/trace/util/Tracing.java | 3 +- .../java/org/apache/phoenix/util/LogUtil.java | 34 +++++++++++++++ .../org/apache/phoenix/util/LogUtilTest.java | 45 ++++++++++++++++++++ .../org/apache/phoenix/trace/TracingCompat.java | 2 +- 9 files changed, 131 insertions(+), 19 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/it/java/org/apache/phoenix/trace/PhoenixTracingEndToEndIT.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/it/java/org/apache/phoenix/trace/PhoenixTracingEndToEndIT.java b/phoenix-core/src/it/java/org/apache/phoenix/trace/PhoenixTracingEndToEndIT.java index 0fc80ed..87d80da 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/trace/PhoenixTracingEndToEndIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/trace/PhoenixTracingEndToEndIT.java @@ -467,4 +467,4 @@ public class PhoenixTracingEndToEndIT extends BaseTracingTestIT { } } -} \ No newline at end of file +} http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/main/java/org/apache/phoenix/cache/ServerCacheClient.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/main/java/org/apache/phoenix/cache/ServerCacheClient.java b/phoenix-core/src/main/java/org/apache/phoenix/cache/ServerCacheClient.java index f4be508..1301fb7 100644 --- a/phoenix-core/src/main/java/org/apache/phoenix/cache/ServerCacheClient.java +++ b/phoenix-core/src/main/java/org/apache/phoenix/cache/ServerCacheClient.java @@ -17,6 +17,9 @@ */ package org.apache.phoenix.cache; +import static java.util.Collections.emptyMap; +import static org.apache.phoenix.util.LogUtil.addCustomAnnotations; + import java.io.Closeable; import java.io.IOException; import java.sql.SQLException; @@ -164,7 +167,7 @@ public class ServerCacheClient { if ( ! servers.contains(entry) && keyRanges.intersect(entry.getRegionInfo().getStartKey(), entry.getRegionInfo().getEndKey())) { // Call RPC once per server servers.add(entry); - if (LOG.isDebugEnabled()) {LOG.debug("Adding cache entry to be sent for " + entry);} + if (LOG.isDebugEnabled()) {LOG.debug(addCustomAnnotations("Adding cache entry to be sent for " + entry, connection.getCustomTracingAnnotations()));} final byte[] key = entry.getRegionInfo().getStartKey(); final HTableInterface htable = services.getTable(cacheUsingTableRef.getTable().getPhysicalName().getBytes()); closeables.add(htable); @@ -217,7 +220,7 @@ public class ServerCacheClient { } })); } else { - if (LOG.isDebugEnabled()) {LOG.debug("NOT adding cache entry to be sent for " + entry + " since one already exists for that entry");} + if (LOG.isDebugEnabled()) {LOG.debug(addCustomAnnotations("NOT adding cache entry to be sent for " + entry + " since one already exists for that entry", connection.getCustomTracingAnnotations()));} } } @@ -256,7 +259,7 @@ public class ServerCacheClient { } } } - if (LOG.isDebugEnabled()) {LOG.debug("Cache " + cacheId + " successfully added to servers.");} + if (LOG.isDebugEnabled()) {LOG.debug(addCustomAnnotations("Cache " + cacheId + " successfully added to servers.", connection.getCustomTracingAnnotations()));} return hashCacheSpec; } @@ -282,7 +285,7 @@ public class ServerCacheClient { * this, we iterate through the current metadata boundaries and remove the cache once for each * server that we originally sent to. */ - if (LOG.isDebugEnabled()) {LOG.debug("Removing Cache " + cacheId + " from servers.");} + if (LOG.isDebugEnabled()) {LOG.debug(addCustomAnnotations("Removing Cache " + cacheId + " from servers.", connection.getCustomTracingAnnotations()));} for (HRegionLocation entry : locations) { if (remainingOnServers.contains(entry)) { // Call once per server try { @@ -309,12 +312,20 @@ public class ServerCacheClient { remainingOnServers.remove(entry); } catch (Throwable t) { lastThrowable = t; - LOG.error("Error trying to remove hash cache for " + entry, t); + Map<String, String> customAnnotations = emptyMap(); + if (connection != null) { + customAnnotations = connection.getCustomTracingAnnotations(); + } + LOG.error(addCustomAnnotations("Error trying to remove hash cache for " + entry, customAnnotations), t); } } } if (!remainingOnServers.isEmpty()) { - LOG.warn("Unable to remove hash cache for " + remainingOnServers, lastThrowable); + Map<String, String> customAnnotations = emptyMap(); + if (connection != null) { + customAnnotations = connection.getCustomTracingAnnotations(); + } + LOG.warn(addCustomAnnotations("Unable to remove hash cache for " + remainingOnServers, customAnnotations), lastThrowable); } } finally { Closeables.closeQuietly(iterateOverTable); http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/main/java/org/apache/phoenix/execute/HashJoinPlan.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/main/java/org/apache/phoenix/execute/HashJoinPlan.java b/phoenix-core/src/main/java/org/apache/phoenix/execute/HashJoinPlan.java index 2cf89fb..6154c88 100644 --- a/phoenix-core/src/main/java/org/apache/phoenix/execute/HashJoinPlan.java +++ b/phoenix-core/src/main/java/org/apache/phoenix/execute/HashJoinPlan.java @@ -17,10 +17,14 @@ */ package org.apache.phoenix.execute; +import static java.util.Collections.emptyMap; +import static org.apache.phoenix.util.LogUtil.addCustomAnnotations; + import java.sql.ParameterMetaData; import java.sql.SQLException; import java.util.ArrayList; import java.util.List; +import java.util.Map; import java.util.concurrent.ExecutionException; import java.util.concurrent.ExecutorService; import java.util.concurrent.Future; @@ -33,9 +37,9 @@ import org.apache.hadoop.hbase.filter.CompareFilter.CompareOp; import org.apache.hadoop.hbase.io.ImmutableBytesWritable; import org.apache.phoenix.cache.ServerCacheClient.ServerCache; import org.apache.phoenix.compile.ExplainPlan; +import org.apache.phoenix.compile.FromCompiler; import org.apache.phoenix.compile.GroupByCompiler.GroupBy; import org.apache.phoenix.compile.OrderByCompiler.OrderBy; -import org.apache.phoenix.compile.FromCompiler; import org.apache.phoenix.compile.QueryPlan; import org.apache.phoenix.compile.RowProjector; import org.apache.phoenix.compile.ScanRanges; @@ -48,15 +52,16 @@ import org.apache.phoenix.expression.InListExpression; import org.apache.phoenix.expression.LiteralExpression; import org.apache.phoenix.hbase.index.util.ImmutableBytesPtr; import org.apache.phoenix.iterate.ResultIterator; +import org.apache.phoenix.jdbc.PhoenixConnection; import org.apache.phoenix.job.JobManager.JobCallable; import org.apache.phoenix.join.HashCacheClient; import org.apache.phoenix.join.HashJoinInfo; import org.apache.phoenix.join.TupleProjector; import org.apache.phoenix.parse.FilterableStatement; +import org.apache.phoenix.parse.HintNode.Hint; import org.apache.phoenix.parse.ParseNode; import org.apache.phoenix.parse.SQLParser; import org.apache.phoenix.parse.SelectStatement; -import org.apache.phoenix.parse.HintNode.Hint; import org.apache.phoenix.query.ConnectionQueryServices; import org.apache.phoenix.query.KeyRange; import org.apache.phoenix.query.QueryServices; @@ -127,6 +132,7 @@ public class HashJoinPlan implements QueryPlan { final ScanRanges ranges = plan.getContext().getScanRanges(); int count = joinIds.length; + final PhoenixConnection connection = getContext().getConnection(); ConnectionQueryServices services = getContext().getConnection().getQueryServices(); ExecutorService executor = services.getExecutor(); List<Future<ServerCache>> futures = new ArrayList<Future<ServerCache>>(count); @@ -152,7 +158,11 @@ public class HashJoinPlan implements QueryPlan { long endTime = System.currentTimeMillis(); boolean isSet = firstJobEndTime.compareAndSet(0, endTime); if (!isSet && (endTime - firstJobEndTime.get()) > maxServerCacheTimeToLive) { - LOG.warn("Hash plan [" + index + "] execution seems too slow. Earlier hash cache(s) might have expired on servers."); + Map<String, String> customAnnotations = emptyMap(); + if (connection != null) { + customAnnotations = connection.getCustomTracingAnnotations(); + } + LOG.warn(addCustomAnnotations("Hash plan [" + index + "] execution seems too slow. Earlier hash cache(s) might have expired on servers.", customAnnotations)); } return cache; } http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/main/java/org/apache/phoenix/query/QueryServices.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/main/java/org/apache/phoenix/query/QueryServices.java b/phoenix-core/src/main/java/org/apache/phoenix/query/QueryServices.java index 9594f33..a352f3a 100644 --- a/phoenix-core/src/main/java/org/apache/phoenix/query/QueryServices.java +++ b/phoenix-core/src/main/java/org/apache/phoenix/query/QueryServices.java @@ -132,6 +132,7 @@ public interface QueryServices extends SQLCloseable { public static final String TRACING_PAGE_SIZE_ATTRIB = "phoenix.trace.read.pagesize"; public static final String TRACING_PROBABILITY_THRESHOLD_ATTRIB = "phoenix.trace.probability.threshold"; public static final String TRACING_STATS_TABLE_NAME_ATTRIB = "phoenix.trace.statsTableName"; + public static final String TRACING_CUSTOM_ANNOTATION_ATTRIB_PREFIX = "phoenix.trace.custom.annotation."; public static final String USE_REVERSE_SCAN_ATTRIB = "phoenix.query.useReverseScan"; http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/main/java/org/apache/phoenix/trace/TraceReader.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/main/java/org/apache/phoenix/trace/TraceReader.java b/phoenix-core/src/main/java/org/apache/phoenix/trace/TraceReader.java index a397e39..f27cf5c 100644 --- a/phoenix-core/src/main/java/org/apache/phoenix/trace/TraceReader.java +++ b/phoenix-core/src/main/java/org/apache/phoenix/trace/TraceReader.java @@ -29,9 +29,11 @@ import java.util.TreeSet; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; +import org.apache.phoenix.jdbc.PhoenixConnection; import org.apache.phoenix.metrics.MetricInfo; import org.apache.phoenix.query.QueryServices; import org.apache.phoenix.query.QueryServicesOptions; +import org.apache.phoenix.util.LogUtil; import org.cloudera.htrace.Span; import com.google.common.base.Joiner; @@ -146,7 +148,7 @@ public class TraceReader { orphan.parent = spanInfo; spanInfo.children.add(orphan); // / its no longer an orphan - LOG.trace("Found parent for span: " + span); + LOG.trace(addCustomAnnotations("Found parent for span: " + span)); orphans.remove(i--); } } @@ -156,8 +158,8 @@ public class TraceReader { parentSpan.children.add(spanInfo); } else if (parent != Span.ROOT_SPAN_ID) { // add the span to the orphan pile to check for the remaining spans we see - LOG.info("No parent span found for span: " + span + " (root span id: " - + Span.ROOT_SPAN_ID + ")"); + LOG.info(addCustomAnnotations("No parent span found for span: " + span + " (root span id: " + + Span.ROOT_SPAN_ID + ")")); orphans.add(spanInfo); } @@ -213,7 +215,7 @@ public class TraceReader { + MetricInfo.TRACE.columnName + "=" + traceid + " AND " + MetricInfo.PARENT.columnName + "=" + parent + " AND " + MetricInfo.SPAN.columnName + "=" + span; - LOG.trace("Requesting columns with: " + request); + LOG.trace(addCustomAnnotations("Requesting columns with: " + request)); ResultSet results = conn.createStatement().executeQuery(request); List<String> cols = new ArrayList<String>(); while (results.next()) { @@ -222,12 +224,20 @@ public class TraceReader { } } if (cols.size() < count) { - LOG.error("Missing tags! Expected " + count + ", but only got " + cols.size() - + " tags from rquest " + request); + LOG.error(addCustomAnnotations("Missing tags! Expected " + count + ", but only got " + cols.size() + + " tags from rquest " + request)); } return cols; } - + + private String addCustomAnnotations(String logLine) throws SQLException { + if (conn.isWrapperFor(PhoenixConnection.class)) { + PhoenixConnection phxConn = conn.unwrap(PhoenixConnection.class); + logLine = LogUtil.addCustomAnnotations(logLine, phxConn.getCustomTracingAnnotations()); + } + return logLine; + } + /** * Holds information about a trace */ http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/main/java/org/apache/phoenix/trace/util/Tracing.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/main/java/org/apache/phoenix/trace/util/Tracing.java b/phoenix-core/src/main/java/org/apache/phoenix/trace/util/Tracing.java index c7c381e..d0677cf 100644 --- a/phoenix-core/src/main/java/org/apache/phoenix/trace/util/Tracing.java +++ b/phoenix-core/src/main/java/org/apache/phoenix/trace/util/Tracing.java @@ -37,6 +37,7 @@ import org.apache.phoenix.jdbc.PhoenixConnection; import org.apache.phoenix.query.QueryServices; import org.apache.phoenix.query.QueryServicesOptions; import org.apache.phoenix.trace.TracingCompat; +import org.apache.phoenix.util.StringUtil; import org.cloudera.htrace.Sampler; import org.cloudera.htrace.Span; import org.cloudera.htrace.Trace; @@ -320,4 +321,4 @@ public class Tracing { } initialized = true; } -} \ No newline at end of file +} http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/main/java/org/apache/phoenix/util/LogUtil.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/main/java/org/apache/phoenix/util/LogUtil.java b/phoenix-core/src/main/java/org/apache/phoenix/util/LogUtil.java new file mode 100644 index 0000000..256a260 --- /dev/null +++ b/phoenix-core/src/main/java/org/apache/phoenix/util/LogUtil.java @@ -0,0 +1,34 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.phoenix.util; + +import java.util.Map; + +public class LogUtil { + + private LogUtil() { + } + + public static String addCustomAnnotations(String logLine, Map<String, String> annotations) { + if (annotations == null || annotations.isEmpty()) { + return logLine; + } else { + return annotations.toString() + ' ' + logLine; + } + } +} http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-core/src/test/java/org/apache/phoenix/util/LogUtilTest.java ---------------------------------------------------------------------- diff --git a/phoenix-core/src/test/java/org/apache/phoenix/util/LogUtilTest.java b/phoenix-core/src/test/java/org/apache/phoenix/util/LogUtilTest.java new file mode 100644 index 0000000..ca9c820 --- /dev/null +++ b/phoenix-core/src/test/java/org/apache/phoenix/util/LogUtilTest.java @@ -0,0 +1,45 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.phoenix.util; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertTrue; + +import java.util.Map; + +import org.junit.Test; + +import com.google.common.collect.ImmutableMap; + +public class LogUtilTest { + + @Test + public void testAddCustomAnnotationsWithNull() { + String logLine = LogUtil.addCustomAnnotations("log line", null); + assertEquals(logLine, "log line"); + } + + @Test + public void testAddCustomAnnotations() { + Map<String, String> annotations = ImmutableMap.of("a1", "v1", "a2", "v2"); + String logLine = LogUtil.addCustomAnnotations("log line", annotations); + assertTrue(logLine.contains("log line")); + assertTrue(logLine.contains("a1=v1")); + assertTrue(logLine.contains("a2=v2")); + } +} http://git-wip-us.apache.org/repos/asf/phoenix/blob/1f54dfe7/phoenix-hadoop-compat/src/main/java/org/apache/phoenix/trace/TracingCompat.java ---------------------------------------------------------------------- diff --git a/phoenix-hadoop-compat/src/main/java/org/apache/phoenix/trace/TracingCompat.java b/phoenix-hadoop-compat/src/main/java/org/apache/phoenix/trace/TracingCompat.java index 032e38a..e0a3410 100644 --- a/phoenix-hadoop-compat/src/main/java/org/apache/phoenix/trace/TracingCompat.java +++ b/phoenix-hadoop-compat/src/main/java/org/apache/phoenix/trace/TracingCompat.java @@ -86,4 +86,4 @@ public class TracingCompat { public static final String getTraceMetricName(String traceId) { return METRIC_SOURCE_KEY + traceId; } -} \ No newline at end of file +}
