HIVE-19133 : HS2 WebUI phase-wise performance metrics not showing correctly (Bharathkrishna Guruvayoor Murali reviewed by Zoltan Haindrich, Vihang Karajgaonkar)
Project: http://git-wip-us.apache.org/repos/asf/hive/repo Commit: http://git-wip-us.apache.org/repos/asf/hive/commit/e89f98c4 Tree: http://git-wip-us.apache.org/repos/asf/hive/tree/e89f98c4 Diff: http://git-wip-us.apache.org/repos/asf/hive/diff/e89f98c4 Branch: refs/heads/storage-branch-2.6 Commit: e89f98c448d1c95bd92275575f2caa02537e8803 Parents: da10aab Author: Bharathkrishna Guruvayoor Murali <[email protected]> Authored: Wed Apr 25 10:47:42 2018 -0700 Committer: Vihang Karajgaonkar <[email protected]> Committed: Wed Apr 25 10:47:48 2018 -0700 ---------------------------------------------------------------------- .../apache/hadoop/hive/ql/log/PerfLogger.java | 2 -- .../hive/jdbc/miniHS2/TestHs2Metrics.java | 1 - .../TestOperationLoggingAPIWithMr.java | 1 - .../TestOperationLoggingAPIWithTez.java | 1 - .../service/cli/session/TestQueryDisplay.java | 7 +++++++ .../java/org/apache/hadoop/hive/ql/Driver.java | 22 ++++++++------------ .../service/cli/operation/SQLOperation.java | 11 +++++----- 7 files changed, 21 insertions(+), 24 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/hive/blob/e89f98c4/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java ---------------------------------------------------------------------- diff --git a/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java b/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java index c1e1b7f..3d6315c 100644 --- a/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java +++ b/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java @@ -51,14 +51,12 @@ public class PerfLogger { public static final String SERIALIZE_PLAN = "serializePlan"; public static final String DESERIALIZE_PLAN = "deserializePlan"; public static final String CLONE_PLAN = "clonePlan"; - public static final String TASK = "task."; public static final String RELEASE_LOCKS = "releaseLocks"; public static final String PRUNE_LISTING = "prune-listing"; public static final String PARTITION_RETRIEVING = "partition-retrieving"; public static final String PRE_HOOK = "PreHook."; public static final String POST_HOOK = "PostHook."; public static final String FAILURE_HOOK = "FailureHook."; - public static final String DRIVER_RUN = "Driver.run"; public static final String TEZ_COMPILER = "TezCompiler"; public static final String TEZ_SUBMIT_TO_RUNNING = "TezSubmitToRunningDag"; public static final String TEZ_BUILD_DAG = "TezBuildDag"; http://git-wip-us.apache.org/repos/asf/hive/blob/e89f98c4/itests/hive-unit/src/test/java/org/apache/hive/jdbc/miniHS2/TestHs2Metrics.java ---------------------------------------------------------------------- diff --git a/itests/hive-unit/src/test/java/org/apache/hive/jdbc/miniHS2/TestHs2Metrics.java b/itests/hive-unit/src/test/java/org/apache/hive/jdbc/miniHS2/TestHs2Metrics.java index 0ec23e1..9686445 100644 --- a/itests/hive-unit/src/test/java/org/apache/hive/jdbc/miniHS2/TestHs2Metrics.java +++ b/itests/hive-unit/src/test/java/org/apache/hive/jdbc/miniHS2/TestHs2Metrics.java @@ -109,7 +109,6 @@ public class TestHs2Metrics { MetricsTestUtils.verifyMetricsJson(json, MetricsTestUtils.TIMER, "api_hs2_sql_operation_PENDING", 1); MetricsTestUtils.verifyMetricsJson(json, MetricsTestUtils.TIMER, "api_hs2_sql_operation_RUNNING", 1); MetricsTestUtils.verifyMetricsJson(json, MetricsTestUtils.COUNTER, "hs2_completed_sql_operation_FINISHED", 1); - MetricsTestUtils.verifyMetricsJson(json, MetricsTestUtils.TIMER, "api_Driver.run", 1); //but there should be no more active calls. MetricsTestUtils.verifyMetricsJson(json, MetricsTestUtils.COUNTER, "active_calls_api_semanticAnalyze", 0); http://git-wip-us.apache.org/repos/asf/hive/blob/e89f98c4/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java ---------------------------------------------------------------------- diff --git a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java index a6aa846..c7dade3 100644 --- a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java +++ b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java @@ -59,7 +59,6 @@ public class TestOperationLoggingAPIWithMr extends OperationLoggingAPITestBase { expectedLogsPerformance = new String[]{ "<PERFLOG method=compile from=org.apache.hadoop.hive.ql.Driver>", "<PERFLOG method=parse from=org.apache.hadoop.hive.ql.Driver>", - "<PERFLOG method=Driver.run from=org.apache.hadoop.hive.ql.Driver>", "<PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>" }; hiveConf = new HiveConf(); http://git-wip-us.apache.org/repos/asf/hive/blob/e89f98c4/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java ---------------------------------------------------------------------- diff --git a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java index 388486d..28eeda1 100644 --- a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java +++ b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java @@ -49,7 +49,6 @@ public class TestOperationLoggingAPIWithTez extends OperationLoggingAPITestBase expectedLogsPerformance = new String[]{ "<PERFLOG method=compile from=org.apache.hadoop.hive.ql.Driver>", "<PERFLOG method=parse from=org.apache.hadoop.hive.ql.Driver>", - "<PERFLOG method=Driver.run from=org.apache.hadoop.hive.ql.Driver>", "from=org.apache.hadoop.hive.ql.exec.tez.monitoring.TezJobMonitor", "org.apache.tez.common.counters.DAGCounter", "NUM_SUCCEEDED_TASKS", http://git-wip-us.apache.org/repos/asf/hive/blob/e89f98c4/itests/hive-unit/src/test/java/org/apache/hive/service/cli/session/TestQueryDisplay.java ---------------------------------------------------------------------- diff --git a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/session/TestQueryDisplay.java b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/session/TestQueryDisplay.java index 22f953f..8b28e2d 100644 --- a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/session/TestQueryDisplay.java +++ b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/session/TestQueryDisplay.java @@ -20,6 +20,7 @@ package org.apache.hive.service.cli.session; import org.apache.hadoop.hive.conf.HiveConf; import org.apache.hadoop.hive.ql.QueryDisplay; import org.apache.hadoop.hive.ql.QueryInfo; +import org.apache.hadoop.hive.ql.log.PerfLogger; import org.apache.hadoop.hive.ql.plan.api.StageType; import org.apache.hadoop.hive.ql.session.SessionState; import org.apache.hive.service.cli.OperationHandle; @@ -182,6 +183,12 @@ public class TestQueryDisplay { Assert.assertTrue(qDisplay1.getPerfLogStarts(QueryDisplay.Phase.COMPILATION).size() > 0); Assert.assertTrue(qDisplay1.getPerfLogEnds(QueryDisplay.Phase.COMPILATION).size() > 0); + Assert.assertTrue(qDisplay1.getPerfLogStarts(QueryDisplay.Phase.COMPILATION).containsKey(PerfLogger.COMPILE)); + Assert.assertFalse(qDisplay1.getPerfLogStarts(QueryDisplay.Phase.EXECUTION).containsKey(PerfLogger.COMPILE)); + Assert.assertTrue(qDisplay1.getPerfLogStarts(QueryDisplay.Phase.EXECUTION).containsKey(PerfLogger.DRIVER_EXECUTE)); + Assert.assertFalse(qDisplay1.getPerfLogStarts(QueryDisplay.Phase.COMPILATION) + .containsKey(PerfLogger.DRIVER_EXECUTE)); + Assert.assertEquals(qDisplay1.getTaskDisplays().size(), 1); QueryDisplay.TaskDisplay tInfo1 = qDisplay1.getTaskDisplays().get(0); Assert.assertEquals(tInfo1.getTaskId(), "Stage-0"); http://git-wip-us.apache.org/repos/asf/hive/blob/e89f98c4/ql/src/java/org/apache/hadoop/hive/ql/Driver.java ---------------------------------------------------------------------- diff --git a/ql/src/java/org/apache/hadoop/hive/ql/Driver.java b/ql/src/java/org/apache/hadoop/hive/ql/Driver.java index a35a215..4e8dbe2 100644 --- a/ql/src/java/org/apache/hadoop/hive/ql/Driver.java +++ b/ql/src/java/org/apache/hadoop/hive/ql/Driver.java @@ -489,8 +489,7 @@ public class Driver implements IDriver { // interrupted, it should be set to true if the compile is called within another method like // runInternal, which defers the close to the called in that method. private void compile(String command, boolean resetTaskIds, boolean deferClose) throws CommandProcessorResponse { - PerfLogger perfLogger = SessionState.getPerfLogger(true); - perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.DRIVER_RUN); + PerfLogger perfLogger = SessionState.getPerfLogger(); perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.COMPILE); lDrvState.stateLock.lock(); try { @@ -660,7 +659,7 @@ public class Driver implements IDriver { // get the output schema schema = getSchema(sem, conf); - plan = new QueryPlan(queryStr, sem, perfLogger.getStartTime(PerfLogger.DRIVER_RUN), queryId, + plan = new QueryPlan(queryStr, sem, queryDisplay.getQueryStartTime(), queryId, queryState.getHiveOperation(), schema); @@ -1650,7 +1649,7 @@ public class Driver implements IDriver { metrics.incrementCounter(MetricsConstant.WAITING_COMPILE_OPS, 1); } - PerfLogger perfLogger = SessionState.getPerfLogger(); + PerfLogger perfLogger = SessionState.getPerfLogger(true); perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.WAIT_COMPILE); final ReentrantLock compileLock = tryAcquireCompileLock(isParallelEnabled, command); @@ -1676,7 +1675,6 @@ public class Driver implements IDriver { } finally { compileLock.unlock(); } - //Save compile-time PerfLogging for WebUI. //Execution-time Perf logs are done by either another thread's PerfLogger //or a reset PerfLogger. @@ -1784,19 +1782,18 @@ public class Driver implements IDriver { throw createProcessorResponse(12); } - PerfLogger perfLogger = null; - if (!alreadyCompiled) { // compile internal will automatically reset the perf logger compileInternal(command, true); - // then we continue to use this perf logger - perfLogger = SessionState.getPerfLogger(); } else { - // reuse existing perf logger. - perfLogger = SessionState.getPerfLogger(); // Since we're reusing the compiled plan, we need to update its start time for current run - plan.setQueryStartTime(perfLogger.getStartTime(PerfLogger.DRIVER_RUN)); + plan.setQueryStartTime(queryDisplay.getQueryStartTime()); } + + //Reset the PerfLogger so that it doesn't retain any previous values. + // Any value from compilation phase can be obtained through the map set in queryDisplay during compilation. + PerfLogger perfLogger = SessionState.getPerfLogger(true); + // the reason that we set the txn manager for the cxt here is because each // query has its own ctx object. The txn mgr is shared across the // same instance of Driver, which can run multiple queries. @@ -1829,7 +1826,6 @@ public class Driver implements IDriver { throw handleHiveException(e, 12); } - perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.DRIVER_RUN); queryDisplay.setPerfLogStarts(QueryDisplay.Phase.EXECUTION, perfLogger.getStartTimes()); queryDisplay.setPerfLogEnds(QueryDisplay.Phase.EXECUTION, perfLogger.getEndTimes()); http://git-wip-us.apache.org/repos/asf/hive/blob/e89f98c4/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java ---------------------------------------------------------------------- diff --git a/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java b/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java index 5fc935b..85f92d2 100644 --- a/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java +++ b/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java @@ -263,8 +263,9 @@ public class SQLOperation extends ExecuteStatementOperation { // 1) ThreadLocal Hive object needs to be set in background thread // 2) The metastore client in Hive is associated with right user. // 3) Current UGI will get used by metastore when metastore is in embedded mode - Runnable work = new BackgroundWork(getCurrentUGI(), parentSession.getSessionHive(), - SessionState.getPerfLogger(), SessionState.get(), asyncPrepare); + Runnable work = + new BackgroundWork(getCurrentUGI(), parentSession.getSessionHive(), SessionState.get(), + asyncPrepare); try { // This submit blocks if no background threads are available to run this operation @@ -282,16 +283,14 @@ public class SQLOperation extends ExecuteStatementOperation { private final class BackgroundWork implements Runnable { private final UserGroupInformation currentUGI; private final Hive parentHive; - private final PerfLogger parentPerfLogger; private final SessionState parentSessionState; private final boolean asyncPrepare; private BackgroundWork(UserGroupInformation currentUGI, - Hive parentHive, PerfLogger parentPerfLogger, + Hive parentHive, SessionState parentSessionState, boolean asyncPrepare) { this.currentUGI = currentUGI; this.parentHive = parentHive; - this.parentPerfLogger = parentPerfLogger; this.parentSessionState = parentSessionState; this.asyncPrepare = asyncPrepare; } @@ -304,7 +303,7 @@ public class SQLOperation extends ExecuteStatementOperation { Hive.set(parentHive); // TODO: can this result in cross-thread reuse of session state? SessionState.setCurrentSessionState(parentSessionState); - PerfLogger.setPerfLogger(parentPerfLogger); + PerfLogger.setPerfLogger(SessionState.getPerfLogger()); LogUtils.registerLoggingContext(queryState.getConf()); try { if (asyncPrepare) {
