This is an automated email from the ASF dual-hosted git repository.
rameshkumar pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/hive.git
The following commit(s) were added to refs/heads/master by this push:
new b0245de9c55 HIVE-27751 Log Query Compilation summary in an accumulated
way (#4755) (Ramesh Kumar reviewed by Stamatis Zampetakis)
b0245de9c55 is described below
commit b0245de9c550b78e6aa7ab4b435c3cc07034d339
Author: Ramesh Kumar <[email protected]>
AuthorDate: Fri Mar 22 22:14:54 2024 -0700
HIVE-27751 Log Query Compilation summary in an accumulated way (#4755)
(Ramesh Kumar reviewed by Stamatis Zampetakis)
---
.../org/apache/hadoop/hive/ql/log/PerfLogger.java | 22 ++++
.../java/org/apache/hadoop/hive/ql/Compiler.java | 2 +-
.../hive/ql/QueryCompilationSummaryHook.java | 130 +++++++++++++++++++++
.../hadoop/hive/ql/parse/CalcitePlanner.java | 46 ++++----
.../hadoop/hive/ql/parse/SemanticAnalyzer.java | 18 +++
.../clientpositive/querycompilesummaryhook.q | 8 ++
.../llap/querycompilesummaryhook.q.out | 86 ++++++++++++++
7 files changed, 291 insertions(+), 21 deletions(-)
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 cc57e9b42b0..530a114b950 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
@@ -40,10 +40,32 @@ import java.util.concurrent.ConcurrentHashMap;
public class PerfLogger {
public static final String ACQUIRE_READ_WRITE_LOCKS =
"acquireReadWriteLocks";
public static final String COMPILE = "compile";
+ public static final String COMPILE_STEP = "Compile Step";
public static final String WAIT_COMPILE = "waitCompile";
public static final String PARSE = "parse";
public static final String ANALYZE = "semanticAnalyze";
public static final String OPTIMIZER = "optimizer";
+ public static final String GENERATE_RESOLVED_PARSETREE = "Generate Resolved
ParseTree";
+ public static final String LOGICALPLAN_AND_HIVE_OPERATOR_TREE = "Logical
Plan and hive Operator Tree";
+ public static final String DEDUCE_RESULTSET_SCHEMA = "Deduce
ResultsetSchema";
+ public static final String PARSE_CONTEXT_GENERATION = "Parse Context
generation";
+ public static final String SAVE_AND_VALIDATE_VIEW = "Save and Validate View
Creation";
+ public static final String LOGICAL_OPTIMIZATION = "Logical Optimization";
+ public static final String PHYSICAL_OPTIMIZATION = "Physical Optimization";
+ public static final String POST_PROCESSING = "Post Processing";
+ public static final String GENERATE_LOGICAL_PLAN = "Generate Logical Plan";
+ public static final String GENERATE_OPERATOR_TREE = "Generate Operator Tree";
+ public static final String VIEW_REWRITING = "Calcite: View-based rewriting";
+ public static final String PLAN_GENERATION = "Calcite: Plan generation";
+ public static final String MV_REWRITE_FIELD_TRIMMER = "MV Rewrite and Field
Trimmer";
+ public static final String REMOVING_SUBQUERY = "Removing SubQuery";
+ public static final String DECORRELATION = "Decorrelation";
+ public static final String VALIDATE_QUERY_MATERIALIZATION = "Validate Query
Materialization";
+ public static final String PREJOIN_ORDERING = "Calcite: Prejoin ordering
transformation";
+ public static final String MV_REWRITING = "MV Rewriting";
+ public static final String JOIN_REORDERING = "Calcite: Join Reordering";
+ public static final String POSTJOIN_ORDERING = "Calcite: Postjoin ordering
transformation";
+ public static final String HIVE_SORT_PREDICATES = "Hive Sort Predicates";
public static final String MATERIALIZED_VIEWS_REGISTRY_REFRESH =
"MaterializedViewsRegistryRefresh";
public static final String DO_AUTHORIZATION = "doAuthorization";
public static final String DRIVER_EXECUTE = "Driver.execute";
diff --git a/ql/src/java/org/apache/hadoop/hive/ql/Compiler.java
b/ql/src/java/org/apache/hadoop/hive/ql/Compiler.java
index 9d677cd6d24..930c14139fb 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/Compiler.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/Compiler.java
@@ -482,6 +482,7 @@ public class Compiler {
}
private void cleanUp(Throwable compileException, boolean parsed, boolean
deferClose) {
+ double duration = perfLogger.perfLogEnd(CLASS_NAME, PerfLogger.COMPILE) /
1000.00;
// Trigger post compilation hook. Note that if the compilation fails here
then
// before/after execution hook will never be executed.
if (parsed) {
@@ -492,7 +493,6 @@ public class Compiler {
}
}
- double duration = perfLogger.perfLogEnd(CLASS_NAME, PerfLogger.COMPILE) /
1000.00;
ImmutableMap<String, Long> compileHMSTimings =
Hive.dumpMetaCallTimingWithoutEx("compilation");
driverContext.getQueryDisplay().setHmsTimings(QueryDisplay.Phase.COMPILATION,
compileHMSTimings);
diff --git
a/ql/src/java/org/apache/hadoop/hive/ql/QueryCompilationSummaryHook.java
b/ql/src/java/org/apache/hadoop/hive/ql/QueryCompilationSummaryHook.java
new file mode 100644
index 00000000000..4e542b0b4c3
--- /dev/null
+++ b/ql/src/java/org/apache/hadoop/hive/ql/QueryCompilationSummaryHook.java
@@ -0,0 +1,130 @@
+/*
+ * 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.hadoop.hive.ql;
+
+import org.apache.hadoop.hive.ql.hooks.QueryLifeTimeHook;
+import org.apache.hadoop.hive.ql.hooks.QueryLifeTimeHookContext;
+import org.apache.hadoop.hive.ql.log.PerfLogger;
+import org.apache.hadoop.hive.ql.session.SessionState;
+
+import java.util.ArrayList;
+import java.util.List;
+
+import static
org.apache.hadoop.hive.common.log.InPlaceUpdate.MIN_TERMINAL_WIDTH;
+
+public class QueryCompilationSummaryHook implements QueryLifeTimeHook {
+ private static final String OPERATION_SUMMARY = "%-84s %9s";
+ private static final String QUERY_COMPILATION_SUMMARY = "Query Compilation
Summary";
+ private static final String LINE_SEPARATOR = "line.separator";
+ private static final String TOTAL_COMPILATION_TIME = "Total Compilation
Time";
+ private static final List<CompileStep> compileSteps = new ArrayList<>();
+ private static final String SEPARATOR = new String(new
char[MIN_TERMINAL_WIDTH]).replace("\0", "-");
+
+
+ private String format(String value, long number) {
+ return String.format(OPERATION_SUMMARY, value, number + "ms");
+ }
+ @Override
+ public void beforeCompile(QueryLifeTimeHookContext ctx) {
+
+ }
+
+ @Override
+ public void afterCompile(QueryLifeTimeHookContext ctx, boolean hasError) {
+ printCompileSummary();
+ }
+
+ @Override
+ public void beforeExecution(QueryLifeTimeHookContext ctx) {
+
+ }
+
+ @Override
+ public void afterExecution(QueryLifeTimeHookContext ctx, boolean hasError)
{
+
+ }
+
+ private static final class CompileStep {
+ final private String name;
+ final private List<CompileStep> subSteps;
+
+ public CompileStep(String name) {
+ this.name = name;
+ subSteps = new ArrayList<>();
+ }
+ public void addSubStep(CompileStep subStep) {
+ subSteps.add(subStep);
+ }
+ public List<CompileStep> getSubSteps() {
+ return subSteps;
+ }
+ }
+
+ static {
+ compileSteps.add(new CompileStep(PerfLogger.PARSE));
+ compileSteps.add(new
CompileStep(PerfLogger.GENERATE_RESOLVED_PARSETREE));
+ CompileStep logicalPlanAndOpTree = new
CompileStep(PerfLogger.LOGICALPLAN_AND_HIVE_OPERATOR_TREE);
+ CompileStep logicalPlan = new
CompileStep(PerfLogger.GENERATE_LOGICAL_PLAN);
+ logicalPlanAndOpTree.addSubStep(logicalPlan);
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.PLAN_GENERATION));
+ logicalPlan.addSubStep(new
CompileStep(PerfLogger.MV_REWRITE_FIELD_TRIMMER));
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.REMOVING_SUBQUERY));
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.DECORRELATION));
+ logicalPlan.addSubStep(new
CompileStep(PerfLogger.VALIDATE_QUERY_MATERIALIZATION));
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.PREJOIN_ORDERING));
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.MV_REWRITING));
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.JOIN_REORDERING));
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.POSTJOIN_ORDERING));
+ logicalPlan.addSubStep(new CompileStep(PerfLogger.HIVE_SORT_PREDICATES));
+ logicalPlanAndOpTree.addSubStep(new
CompileStep(PerfLogger.GENERATE_OPERATOR_TREE));
+ compileSteps.add(logicalPlanAndOpTree);
+ compileSteps.add(new CompileStep(PerfLogger.DEDUCE_RESULTSET_SCHEMA));
+ compileSteps.add(new CompileStep(PerfLogger.PARSE_CONTEXT_GENERATION));
+ compileSteps.add(new CompileStep(PerfLogger.SAVE_AND_VALIDATE_VIEW));
+ compileSteps.add(new CompileStep(PerfLogger.LOGICAL_OPTIMIZATION));
+ compileSteps.add(new CompileStep(PerfLogger.PHYSICAL_OPTIMIZATION));
+ compileSteps.add(new CompileStep(PerfLogger.POST_PROCESSING));
+ }
+
+ public void printCompileSummary() {
+ StringBuilder compileSummary = new StringBuilder();
+ compileSummary.append(QUERY_COMPILATION_SUMMARY);
+ compileSummary.append(System.getProperty(LINE_SEPARATOR));
+ compileSummary.append(SEPARATOR);
+ compileSummary.append(System.getProperty(LINE_SEPARATOR));
+ PerfLogger perfLogger = SessionState.getPerfLogger();
+ appendCompileSteps(compileSummary, perfLogger, "", compileSteps);
+ compileSummary.append(format(TOTAL_COMPILATION_TIME,
perfLogger.getDuration(PerfLogger.COMPILE)));
+ compileSummary.append(System.getProperty(LINE_SEPARATOR));
+ compileSummary.append(SEPARATOR);
+ SessionState.getConsole().printInfo(compileSummary.toString(), false);
+ }
+
+ public void appendCompileSteps(StringBuilder compileSummary, PerfLogger
perfLogger, String prefix,
+ List<CompileStep> currentLevelCompileSteps)
{
+ int counter = 1;
+ for (CompileStep compileStep : currentLevelCompileSteps) {
+ compileSummary.append(format(PerfLogger.COMPILE_STEP + " - " +
+ prefix + counter + " " + compileStep.name,
+ perfLogger.getDuration(compileStep.name)));
+ compileSummary.append(System.getProperty(LINE_SEPARATOR));
+ appendCompileSteps(compileSummary, perfLogger, prefix + counter + ".",
compileStep.getSubSteps());
+ ++counter;
+ }
+ }
+}
diff --git a/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java
b/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java
index 3f49e1098da..ef4252995f3 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/parse/CalcitePlanner.java
@@ -534,6 +534,7 @@ public class CalcitePlanner extends SemanticAnalyzer {
@SuppressWarnings("rawtypes")
Operator genOPTree(ASTNode ast, PlannerContext plannerCtx) throws
SemanticException {
final Operator sinkOp;
+ PerfLogger perfLogger = SessionState.getPerfLogger();
if (!runCBO) {
sinkOp = super.genOPTree(ast, plannerCtx);
@@ -567,8 +568,11 @@ public class CalcitePlanner extends SemanticAnalyzer {
try {
// 0. Gen Optimized Plan
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.GENERATE_LOGICAL_PLAN);
RelNode newPlan = logicalPlan();
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.GENERATE_LOGICAL_PLAN);
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.GENERATE_OPERATOR_TREE);
if (this.conf.getBoolVar(HiveConf.ConfVars.HIVE_CBO_RETPATH_HIVEOP))
{
if (cboCtx.type == PreCboCtx.Type.VIEW && !materializedView) {
throw new SemanticException("Create view is not supported in cbo
return path.");
@@ -665,6 +669,7 @@ public class CalcitePlanner extends SemanticAnalyzer {
LOG.trace(newAST.dump());
}
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.GENERATE_OPERATOR_TREE);
} catch (Exception e) {
LOG.error("CBO failed, skipping CBO. ", e);
@@ -1602,6 +1607,8 @@ public class CalcitePlanner extends SemanticAnalyzer {
@Override
public RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema,
SchemaPlus rootSchema) {
+ PerfLogger perfLogger = SessionState.getPerfLogger();
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.PLAN_GENERATION);
RelNode calcitePlan;
subqueryId = -1;
@@ -1616,7 +1623,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
this.relOptSchema = relOptSchema;
this.functionHelper = new HiveFunctionHelper(rexBuilder);
- PerfLogger perfLogger = SessionState.getPerfLogger();
// 1. Gen Calcite Plan
perfLogger.perfLogBegin(this.getClass().getName(), PerfLogger.OPTIMIZER);
try {
@@ -1632,12 +1638,13 @@ public class CalcitePlanner extends SemanticAnalyzer {
semanticException = e;
throw new RuntimeException(e);
}
- perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.OPTIMIZER,
"Calcite: Plan generation");
if (LOG.isDebugEnabled()) {
LOG.debug("Initial CBO Plan:\n" + RelOptUtil.toString(calcitePlan));
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.PLAN_GENERATION);
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.MV_REWRITE_FIELD_TRIMMER);
// Create executor
RexExecutor executorProvider = new HiveRexExecutorImpl();
calcitePlan.getCluster().getPlanner().setExecutor(executorProvider);
@@ -1654,8 +1661,10 @@ public class CalcitePlanner extends SemanticAnalyzer {
HiveRelFieldTrimmer.get()
.trim(HiveRelFactories.HIVE_BUILDER.create(optCluster, null),
calcitePlan, this.columnAccessInfo,
this.viewProjectToTableSchema);
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.MV_REWRITE_FIELD_TRIMMER);
//Remove subquery
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.REMOVING_SUBQUERY);
if (LOG.isDebugEnabled()) {
LOG.debug("Plan before removing subquery:\n" +
RelOptUtil.toString(calcitePlan));
}
@@ -1663,10 +1672,13 @@ public class CalcitePlanner extends SemanticAnalyzer {
if (LOG.isDebugEnabled()) {
LOG.debug("Plan after removing subquery:\n" +
RelOptUtil.toString(calcitePlan));
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.REMOVING_SUBQUERY);
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.DECORRELATION);
calcitePlan = HiveRelDecorrelator.decorrelateQuery(calcitePlan);
if (LOG.isDebugEnabled()) {
LOG.debug("Plan after decorrelation:\n" +
RelOptUtil.toString(calcitePlan));
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.DECORRELATION);
// Validate query materialization for query results caching. This check
needs
// to occur before constant folding, which may remove some function calls
@@ -1675,21 +1687,26 @@ public class CalcitePlanner extends SemanticAnalyzer {
// for rewriting, it should pass all checks done for query results
caching
// and on top of that we should check that it only contains operators
that
// are supported by the rewriting algorithm.
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.VALIDATE_QUERY_MATERIALIZATION);
HiveRelOptMaterializationValidator materializationValidator = new
HiveRelOptMaterializationValidator();
materializationValidator.validate(calcitePlan);
setInvalidResultCacheReason(
materializationValidator.getResultCacheInvalidReason());
setMaterializationValidationResult(
materializationValidator.getAutomaticRewritingValidationResult());
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.VALIDATE_QUERY_MATERIALIZATION);
// 2. Apply pre-join order optimizations
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.PREJOIN_ORDERING);
calcitePlan = applyPreJoinOrderingTransforms(calcitePlan,
mdProvider.getMetadataProvider(), executorProvider);
if (LOG.isDebugEnabled()) {
LOG.debug("Plan after pre-join transformations:\n" +
RelOptUtil.toString(calcitePlan));
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.PREJOIN_ORDERING);
// 3. Materialized view based rewriting
// We disable it for CTAS and MV creation queries (trying to avoid any
problem
// due to data freshness)
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.MV_REWRITING);
if
(conf.getBoolVar(ConfVars.HIVE_MATERIALIZED_VIEW_ENABLE_AUTO_REWRITING) &&
!getQB().isMaterializedView() &&
!ctx.isLoadingMaterializedView() && !getQB().isCTAS() &&
getQB().hasTableDefined() &&
@@ -1700,10 +1717,12 @@ public class CalcitePlanner extends SemanticAnalyzer {
LOG.debug("Plan after view-based rewriting:\n" +
RelOptUtil.toString(calcitePlan));
}
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.MV_REWRITING);
// 4. Apply join order optimizations: reordering MST algorithm
// If join optimizations failed because of missing stats, we continue
with
// the rest of optimizations
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.JOIN_REORDERING);
if (profilesCBO.contains(ExtendedCBOProfile.JOIN_REORDERING)) {
calcitePlan = applyJoinOrderingTransform(calcitePlan,
mdProvider.getMetadataProvider(), executorProvider);
if (LOG.isDebugEnabled()) {
@@ -1712,12 +1731,17 @@ public class CalcitePlanner extends SemanticAnalyzer {
} else {
disableSemJoinReordering = false;
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.JOIN_REORDERING);
// 5. Apply post-join order optimizations
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.POSTJOIN_ORDERING);
calcitePlan = applyPostJoinOrderingTransform(calcitePlan,
mdProvider.getMetadataProvider(), executorProvider);
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.POSTJOIN_ORDERING);
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.HIVE_SORT_PREDICATES);
if
(conf.getBoolVar(HiveConf.ConfVars.HIVE_OPTIMIZE_SORT_PREDS_WITH_STATS)) {
calcitePlan = calcitePlan.accept(new
HiveFilterSortPredicates(noColsMissingStats));
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.HIVE_SORT_PREDICATES);
if (LOG.isDebugEnabled()) {
LOG.debug("Plan after post-join transformations:\n" +
RelOptUtil.toString(calcitePlan));
}
@@ -1739,9 +1763,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
// TODO: Decorelation of subquery should be done before attempting
// Partition Pruning; otherwise Expression evaluation may try to execute
// corelated sub query.
-
- PerfLogger perfLogger = SessionState.getPerfLogger();
-
final int maxCNFNodeCount =
conf.getIntVar(HiveConf.ConfVars.HIVE_CBO_CNF_NODES_LIMIT);
final int minNumORClauses =
conf.getIntVar(HiveConf.ConfVars.HIVE_POINT_LOOKUP_OPTIMIZER_MIN);
final boolean allowDisjunctivePredicates =
conf.getBoolVar(ConfVars.HIVE_JOIN_DISJ_TRANSITIVE_PREDICATES_PUSHDOWN);
@@ -1939,10 +1960,7 @@ public class CalcitePlanner extends SemanticAnalyzer {
HiveRemoveEmptySingleRules.CORRELATE_RIGHT_INSTANCE);
// Trigger program
- perfLogger.perfLogBegin(this.getClass().getName(), PerfLogger.OPTIMIZER);
basePlan = executeProgram(basePlan, program.build(), mdProvider,
executorProvider);
- perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.OPTIMIZER,
- "Calcite: Prejoin ordering transformation");
return basePlan;
}
@@ -1959,7 +1977,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
protected RelNode applyMaterializedViewRewriting(RelOptPlanner planner,
RelNode basePlan,
RelMetadataProvider mdProvider, RexExecutor executorProvider) {
final RelOptCluster optCluster = basePlan.getCluster();
- final PerfLogger perfLogger = SessionState.getPerfLogger();
final boolean useMaterializedViewsRegistry =
!conf.get(HiveConf.ConfVars.HIVE_SERVER2_MATERIALIZED_VIEWS_REGISTRY_IMPL.varname).equals("DUMMY");
@@ -1993,8 +2010,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
return calcitePreMVRewritingPlan;
}
- perfLogger.perfLogBegin(this.getClass().getName(), PerfLogger.OPTIMIZER);
-
// We need to expand IN/BETWEEN expressions when materialized view
rewriting
// is triggered since otherwise this may prevent some rewritings from
happening
HepProgramBuilder program = new HepProgramBuilder();
@@ -2043,8 +2058,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
optCluster.invalidateMetadataQuery();
RelMetadataQuery.THREAD_PROVIDERS.set(JaninoRelMetadataProvider.of(mdProvider));
- perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.OPTIMIZER,
"Calcite: View-based rewriting");
-
List<Table> materializedViewsUsedOriginalPlan =
getMaterializedViewsUsed(calcitePreMVRewritingPlan);
List<Table> materializedViewsUsedAfterRewrite =
getMaterializedViewsUsed(basePlan);
if (materializedViewsUsedOriginalPlan.size() ==
materializedViewsUsedAfterRewrite.size()) {
@@ -2140,7 +2153,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
* @return
*/
private RelNode applyJoinOrderingTransform(RelNode basePlan,
RelMetadataProvider mdProvider, RexExecutor executorProvider) {
- PerfLogger perfLogger = SessionState.getPerfLogger();
final HepProgramBuilder program = new HepProgramBuilder();
// Remove Projects between Joins so that JoinToMultiJoinRule can merge
them to MultiJoin.
@@ -2165,7 +2177,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
generatePartialProgram(program, false, HepMatchOrder.BOTTOM_UP,
new JoinToMultiJoinRule(HiveJoin.class), new
LoptOptimizeJoinRule(HiveRelFactories.HIVE_BUILDER));
- perfLogger.perfLogBegin(this.getClass().getName(), PerfLogger.OPTIMIZER);
RelNode calciteOptimizedPlan;
try {
calciteOptimizedPlan = executeProgram(basePlan, program.build(),
mdProvider, executorProvider);
@@ -2179,7 +2190,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
throw e;
}
}
- perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.OPTIMIZER,
"Calcite: Join Reordering");
return calciteOptimizedPlan;
}
@@ -2196,7 +2206,6 @@ public class CalcitePlanner extends SemanticAnalyzer {
* @return
*/
private RelNode applyPostJoinOrderingTransform(RelNode basePlan,
RelMetadataProvider mdProvider, RexExecutor executorProvider) {
- PerfLogger perfLogger = SessionState.getPerfLogger();
final HepProgramBuilder program = new HepProgramBuilder();
@@ -2321,10 +2330,7 @@ public class CalcitePlanner extends SemanticAnalyzer {
}
// Trigger program
- perfLogger.perfLogBegin(this.getClass().getName(), PerfLogger.OPTIMIZER);
basePlan = executeProgram(basePlan, program.build(), mdProvider,
executorProvider);
- perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.OPTIMIZER,
- "Calcite: Postjoin ordering transformation");
return basePlan;
}
diff --git a/ql/src/java/org/apache/hadoop/hive/ql/parse/SemanticAnalyzer.java
b/ql/src/java/org/apache/hadoop/hive/ql/parse/SemanticAnalyzer.java
index dd3f75fa665..7d7c5f4fe62 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/parse/SemanticAnalyzer.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/parse/SemanticAnalyzer.java
@@ -181,6 +181,7 @@ import org.apache.hadoop.hive.ql.lib.SemanticGraphWalker;
import org.apache.hadoop.hive.ql.lockmgr.DbTxnManager;
import org.apache.hadoop.hive.ql.lockmgr.HiveTxnManager;
import org.apache.hadoop.hive.ql.lockmgr.LockException;
+import org.apache.hadoop.hive.ql.log.PerfLogger;
import org.apache.hadoop.hive.ql.metadata.MaterializationValidationResult;
import org.apache.hadoop.hive.ql.metadata.DefaultConstraint;
import org.apache.hadoop.hive.ql.metadata.DummyPartition;
@@ -13118,6 +13119,8 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
@SuppressWarnings("checkstyle:methodlength")
void analyzeInternal(ASTNode ast, Supplier<PlannerContext> pcf) throws
SemanticException {
LOG.info("Starting Semantic Analysis");
+ PerfLogger perfLogger = SessionState.getPerfLogger();
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.GENERATE_RESOLVED_PARSETREE);
// 1. Generate Resolved Parse tree from syntax tree
boolean needsTransform = needsTransform();
//change the location of position alias process here
@@ -13168,8 +13171,10 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
} else {
astForMasking = ast;
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.GENERATE_RESOLVED_PARSETREE);
// 2. Gen OP Tree from resolved Parse Tree
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.LOGICALPLAN_AND_HIVE_OPERATOR_TREE);
sinkOp = genOPTree(ast, plannerCtx);
boolean usesMasking = false;
@@ -13216,8 +13221,10 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
return;
}
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.LOGICALPLAN_AND_HIVE_OPERATOR_TREE);
// 3. Deduce Resultset Schema
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.DEDUCE_RESULTSET_SCHEMA);
if ((forViewCreation || createVwDesc != null) &&
!this.ctx.isCboSucceeded()) {
resultSchema =
convertRowSchemaToViewSchema(opParseCtx.get(sinkOp).getRowResolver());
} else {
@@ -13232,8 +13239,10 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
HiveConf.getBoolVar(conf,
HiveConf.ConfVars.HIVE_RESULTSET_USE_UNIQUE_COLUMN_NAMES));
}
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.DEDUCE_RESULTSET_SCHEMA);
// 4. Generate Parse Context for Optimizer & Physical compiler
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.PARSE_CONTEXT_GENERATION);
copyInfoToQueryProperties(queryProperties);
ParseContext pCtx = new ParseContext(queryState, opToPartPruner,
opToPartList, topOps,
new HashSet<JoinOperator>(joinContext.keySet()),
@@ -13267,8 +13276,10 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
}
}
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.PARSE_CONTEXT_GENERATION);
// 5. Take care of view creation
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.SAVE_AND_VALIDATE_VIEW);
if (createVwDesc != null) {
if (ctx.getExplainAnalyze() == AnalyzeState.RUNNING) {
return;
@@ -13284,9 +13295,11 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
createVwDesc.setTablesUsed(pCtx.getTablesUsed());
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.SAVE_AND_VALIDATE_VIEW);
// If we're creating views and ColumnAccessInfo is already created, we
should not run these, since
// it means that in step 2, the ColumnAccessInfo was already created
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.LOGICAL_OPTIMIZATION);
if (!forViewCreation || getColumnAccessInfo() == null) {
// 6. Generate table access stats if required
if (HiveConf.getBoolVar(this.conf,
HiveConf.ConfVars.HIVE_STATS_COLLECT_TABLEKEYS)) {
@@ -13321,6 +13334,7 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
setColumnAccessInfo(columnAccessAnalyzer.analyzeColumnAccess(this.getColumnAccessInfo()));
}
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.LOGICAL_OPTIMIZATION);
if (forViewCreation) {
return;
@@ -13328,9 +13342,12 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
// 9. Optimize Physical op tree & Translate to target execution engine (MR,
// TEZ..)
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.PHYSICAL_OPTIMIZATION);
compilePlan(pCtx);
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.PHYSICAL_OPTIMIZATION);
//find all Acid FileSinkOperatorS
+ perfLogger.perfLogBegin(this.getClass().getName(),
PerfLogger.POST_PROCESSING);
new QueryPlanPostProcessor(rootTasks, acidFileSinks, ctx.getExecutionId());
// 10. Attach CTAS/Insert-Commit-hooks for Storage Handlers
@@ -13372,6 +13389,7 @@ public class SemanticAnalyzer extends
BaseSemanticAnalyzer {
}
}
}
+ perfLogger.perfLogEnd(this.getClass().getName(),
PerfLogger.POST_PROCESSING);
}
private void putAccessedColumnsToReadEntity(Set<ReadEntity> inputs,
ColumnAccessInfo columnAccessInfo) {
diff --git a/ql/src/test/queries/clientpositive/querycompilesummaryhook.q
b/ql/src/test/queries/clientpositive/querycompilesummaryhook.q
new file mode 100644
index 00000000000..3f25d26bb69
--- /dev/null
+++ b/ql/src/test/queries/clientpositive/querycompilesummaryhook.q
@@ -0,0 +1,8 @@
+--! qt:replace:/( *)(\d+)ms/#Masked#/
+set
hive.query.lifetime.hooks=org.apache.hadoop.hive.ql.QueryCompilationSummaryHook;
+
+create table tbl_n1 (n bigint, t string);
+
+explain
+select n, t from tbl_n1 where n = 1;
+
diff --git
a/ql/src/test/results/clientpositive/llap/querycompilesummaryhook.q.out
b/ql/src/test/results/clientpositive/llap/querycompilesummaryhook.q.out
new file mode 100644
index 00000000000..bfddd1a083f
--- /dev/null
+++ b/ql/src/test/results/clientpositive/llap/querycompilesummaryhook.q.out
@@ -0,0 +1,86 @@
+Query Compilation Summary
+----------------------------------------------------------------------------------------------
+Compile Step - 1 parse#Masked#
+Compile Step - 2 Generate Resolved ParseTree#Masked#
+Compile Step - 3 Logical Plan and hive Operator Tree#Masked#
+Compile Step - 3.1 Generate Logical Plan#Masked#
+Compile Step - 3.1.1 Calcite: Plan generation#Masked#
+Compile Step - 3.1.2 MV Rewrite and Field Trimmer#Masked#
+Compile Step - 3.1.3 Removing SubQuery#Masked#
+Compile Step - 3.1.4 Decorrelation#Masked#
+Compile Step - 3.1.5 Validate Query Materialization#Masked#
+Compile Step - 3.1.6 Calcite: Prejoin ordering transformation#Masked#
+Compile Step - 3.1.7 MV Rewriting#Masked#
+Compile Step - 3.1.8 Calcite: Join Reordering#Masked#
+Compile Step - 3.1.9 Calcite: Postjoin ordering transformation#Masked#
+Compile Step - 3.1.10 Hive Sort Predicates#Masked#
+Compile Step - 3.2 Generate Operator Tree#Masked#
+Compile Step - 4 Deduce ResultsetSchema#Masked#
+Compile Step - 5 Parse Context generation#Masked#
+Compile Step - 6 Save and Validate View Creation#Masked#
+Compile Step - 7 Logical Optimization#Masked#
+Compile Step - 8 Physical Optimization#Masked#
+Compile Step - 9 Post Processing#Masked#
+Total Compilation Time#Masked#
+----------------------------------------------------------------------------------------------
+PREHOOK: query: create table tbl_n1 (n bigint, t string)
+PREHOOK: type: CREATETABLE
+PREHOOK: Output: database:default
+PREHOOK: Output: default@tbl_n1
+POSTHOOK: query: create table tbl_n1 (n bigint, t string)
+POSTHOOK: type: CREATETABLE
+POSTHOOK: Output: database:default
+POSTHOOK: Output: default@tbl_n1
+Query Compilation Summary
+----------------------------------------------------------------------------------------------
+Compile Step - 1 parse#Masked#
+Compile Step - 2 Generate Resolved ParseTree#Masked#
+Compile Step - 3 Logical Plan and hive Operator Tree#Masked#
+Compile Step - 3.1 Generate Logical Plan#Masked#
+Compile Step - 3.1.1 Calcite: Plan generation#Masked#
+Compile Step - 3.1.2 MV Rewrite and Field Trimmer#Masked#
+Compile Step - 3.1.3 Removing SubQuery#Masked#
+Compile Step - 3.1.4 Decorrelation#Masked#
+Compile Step - 3.1.5 Validate Query Materialization#Masked#
+Compile Step - 3.1.6 Calcite: Prejoin ordering transformation#Masked#
+Compile Step - 3.1.7 MV Rewriting#Masked#
+Compile Step - 3.1.8 Calcite: Join Reordering#Masked#
+Compile Step - 3.1.9 Calcite: Postjoin ordering transformation#Masked#
+Compile Step - 3.1.10 Hive Sort Predicates#Masked#
+Compile Step - 3.2 Generate Operator Tree#Masked#
+Compile Step - 4 Deduce ResultsetSchema#Masked#
+Compile Step - 5 Parse Context generation#Masked#
+Compile Step - 6 Save and Validate View Creation#Masked#
+Compile Step - 7 Logical Optimization#Masked#
+Compile Step - 8 Physical Optimization#Masked#
+Compile Step - 9 Post Processing#Masked#
+Total Compilation Time#Masked#
+----------------------------------------------------------------------------------------------
+PREHOOK: query: explain
+select n, t from tbl_n1 where n = 1
+PREHOOK: type: QUERY
+PREHOOK: Input: default@tbl_n1
+#### A masked pattern was here ####
+POSTHOOK: query: explain
+select n, t from tbl_n1 where n = 1
+POSTHOOK: type: QUERY
+POSTHOOK: Input: default@tbl_n1
+#### A masked pattern was here ####
+STAGE DEPENDENCIES:
+ Stage-0 is a root stage
+
+STAGE PLANS:
+ Stage: Stage-0
+ Fetch Operator
+ limit: -1
+ Processor Tree:
+ TableScan
+ alias: tbl_n1
+ filterExpr: (n = 1L) (type: boolean)
+ Filter Operator
+ predicate: (n = 1L) (type: boolean)
+ Select Operator
+ expressions: 1L (type: bigint), t (type: string)
+ outputColumnNames: _col0, _col1
+ ListSink
+
