From b0245de9c550b78e6aa7ab4b435c3cc07034d339 Mon Sep 17 00:00:00 2001 From: Ramesh Kumar Date: Fri, 22 Mar 2024 22:14:54 -0700 Subject: [PATCH] HIVE-27751 Log Query Compilation summary in an accumulated way (#4755) (Ramesh Kumar reviewed by Stamatis Zampetakis) --- .../apache/hadoop/hive/ql/log/PerfLogger.java | 22 +++ .../org/apache/hadoop/hive/ql/Compiler.java | 2 +- .../hive/ql/QueryCompilationSummaryHook.java | 130 ++++++++++++++++++ .../hadoop/hive/ql/parse/CalcitePlanner.java | 46 ++++--- .../hive/ql/parse/SemanticAnalyzer.java | 18 +++ .../clientpositive/querycompilesummaryhook.q | 8 ++ .../llap/querycompilesummaryhook.q.out | 86 ++++++++++++ 7 files changed, 291 insertions(+), 21 deletions(-) create mode 100644 ql/src/java/org/apache/hadoop/hive/ql/QueryCompilationSummaryHook.java create mode 100644 ql/src/test/queries/clientpositive/querycompilesummaryhook.q create mode 100644 ql/src/test/results/clientpositive/llap/querycompilesummaryhook.q.out 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 cc57e9b42b00..530a114b9503 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 @@ 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 9d677cd6d249..930c14139fbe 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 @@ private void handleException(Exception e) throws CommandProcessorException { } 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 @@ private void cleanUp(Throwable compileException, boolean parsed, boolean deferCl } } - double duration = perfLogger.perfLogEnd(CLASS_NAME, PerfLogger.COMPILE) / 1000.00; ImmutableMap 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 000000000000..4e542b0b4c31 --- /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 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 subSteps; + + public CompileStep(String name) { + this.name = name; + subSteps = new ArrayList<>(); + } + public void addSubStep(CompileStep subStep) { + subSteps.add(subStep); + } + public List 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 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 3f49e1098daa..ef4252995f38 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 @@ private static RelOptPlanner createPlanner( @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 @@ Operator genOPTree(ASTNode ast, PlannerContext plannerCtx) throws SemanticExcept 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 @@ Operator genOPTree(ASTNode ast, PlannerContext plannerCtx) throws SemanticExcept 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 @@ protected CalcitePlannerAction( @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 RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema, SchemaPlu 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 RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema, SchemaPlu 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 RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema, SchemaPlu 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 RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema, SchemaPlu 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 RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema, SchemaPlu // 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 RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema, SchemaPlu 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 RelNode apply(RelOptCluster cluster, RelOptSchema relOptSchema, SchemaPlu } 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 @@ protected RelNode applyPreJoinOrderingTransforms(RelNode basePlan, RelMetadataPr // 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 @@ protected RelNode applyPreJoinOrderingTransforms(RelNode basePlan, RelMetadataPr 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 @@ private boolean isMaterializedViewMaintenance() { 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 @@ protected RelNode applyMaterializedViewRewriting(RelOptPlanner planner, RelNode 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 @@ protected RelNode applyMaterializedViewRewriting(RelOptPlanner planner, RelNode optCluster.invalidateMetadataQuery(); RelMetadataQuery.THREAD_PROVIDERS.set(JaninoRelMetadataProvider.of(mdProvider)); - perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.OPTIMIZER, "Calcite: View-based rewriting"); - List materializedViewsUsedOriginalPlan = getMaterializedViewsUsed(calcitePreMVRewritingPlan); List
materializedViewsUsedAfterRewrite = getMaterializedViewsUsed(basePlan); if (materializedViewsUsedOriginalPlan.size() == materializedViewsUsedAfterRewrite.size()) { @@ -2140,7 +2153,6 @@ private RelNode applyMaterializedViewRewritingByText( * @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 @@ private RelNode applyJoinOrderingTransform(RelNode basePlan, RelMetadataProvider 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 @@ private RelNode applyJoinOrderingTransform(RelNode basePlan, RelMetadataProvider throw e; } } - perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.OPTIMIZER, "Calcite: Join Reordering"); return calciteOptimizedPlan; } @@ -2196,7 +2206,6 @@ private RelNode applyJoinOrderingTransform(RelNode basePlan, RelMetadataProvider * @return */ private RelNode applyPostJoinOrderingTransform(RelNode basePlan, RelMetadataProvider mdProvider, RexExecutor executorProvider) { - PerfLogger perfLogger = SessionState.getPerfLogger(); final HepProgramBuilder program = new HepProgramBuilder(); @@ -2321,10 +2330,7 @@ private RelNode applyPostJoinOrderingTransform(RelNode basePlan, RelMetadataProv } // 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 dd3f75fa6652..7d7c5f4fe626 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.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 @@ protected void compilePlan(ParseContext pCtx) throws SemanticException{ @SuppressWarnings("checkstyle:methodlength") void analyzeInternal(ASTNode ast, Supplier 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 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE } 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 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE 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 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE 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(joinContext.keySet()), @@ -13267,8 +13276,10 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE } } } + 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 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE 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 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE setColumnAccessInfo(columnAccessAnalyzer.analyzeColumnAccess(this.getColumnAccessInfo())); } } + perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.LOGICAL_OPTIMIZATION); if (forViewCreation) { return; @@ -13328,9 +13342,12 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE // 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 @@ void analyzeInternal(ASTNode ast, Supplier pcf) throws SemanticE } } } + perfLogger.perfLogEnd(this.getClass().getName(), PerfLogger.POST_PROCESSING); } private void putAccessedColumnsToReadEntity(Set 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 000000000000..3f25d26bb693 --- /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 000000000000..bfddd1a083fa --- /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 +