Starrocks中的 Query Profile以及explain analyze及trace命令中的区别
背景
本文基于Starrocks 3.5.5
现有公司因为业务的不同，可能会更加关系单个SQL 的RT，因为如果一个SQL的RT比较大的话，影响的就是这个业务，从而影响收入，所以对于这方面我们就比较关心，
而最近在基于Starrocks做计算存储引擎的时候，遇到了一些问题。时间上超过了2秒，因此需要分析一下对应SQL的指标。
最直接的就是开启 Query Profile,比如说做一下配置:
SET enable_profile = true;
SET global big_query_profile_threshold = '1s';
SET runtime_profile_report_interval = 30;
这个在对应的UI界面（http://<fe_ip>:<fe_http_port>）就能看到Profile
当然还有ANALYZE PROFILE,explain analyze和trace命令,这里就来分析一下三者的差别， 其中以以下SQL为例：
SELECT `SCHEMA_NAME` FROM `INFORMATION_SCHEMA`.`SCHEMATA` WHERE SCHEMA_NAME = 'fin_config';
结论
- 开启
Query Profile会得得到更多的明细信息，以及每个阶段所用的耗时,适合对该SQL的每个算子的各个指标全方位的分析
此种方法会有BE端的信息更新过来，但是这个信息只存在内存，FE重启之后就不复存在。 EXPLAIN ANALYZE展示的是大概的查询执行计划执行信息，比如说 Summary和fragementANALYZE PROFILE展示的和explain analyze一样，但是指标比explain analyze更加丰富trace展示的是某个局部指标，比如说 某个规则的耗时
对于每个方法所对应指标信息如下见下面的 其他
分析
开启Query Profile
通过访问http://<fe_ip>:<fe_http_port>/query_profile?query_id可以获取到对应的profile，
对应到Fe端是QueryProfileAction类接受请求：
QueryProfileAction 里有对应的 “/query_profile” Get请求
对应的Get方法response为executeGet方法：
String queryProfileStr = ProfileManager.getInstance().getProfile(queryId);if (queryProfileStr != null) {appendCopyButton(response.getContent());appendQueryProfile(response.getContent(), queryProfileStr);getPageFooter(response.getContent());writeResponse(request, response);
这里ProfileManager.getInstance().getProfile(queryId)会获取对应的 Profile.
runtimeProfile数据流
FrontendServiceImpl.reportExecStatus||\/
DefaultCoordinator.updateFragmentExecStatus(params)||\/
QueryRuntimeProfile.updateProfile(execState, params) // 这里会 runtime_profile_report_interval 判断||\/
saveRunningProfile||\/
ProfileManager.pushProfile(profilingPlan, profile);
这里会把 BE端 Fragment 实力的 运行指标都给返回给 FE端.
EXPLAIN ANALYZE
具体语法参考Simulate a query for Profile Analysis Using EXPLAIN ANALYZE
直接转到StarRocks.g4
queryStatement: (explainDesc | optimizerTrace) ? queryRelation outfile?;
...
explainDesc: (DESC | DESCRIBE | EXPLAIN) (LOGICAL | ANALYZE | VERBOSE | COSTS | SCHEDULER)?;
...
optimizerTrace: TRACE (ALL | LOGS | TIMES | VALUES | REASON) identifier?;
通过AstBuilder.visitQueryStatement 解析完后:
@Override
public ParseNode visitQueryStatement(StarRocksParser.QueryStatementContext context) {QueryRelation queryRelation = (QueryRelation) visit(context.queryRelation());QueryStatement queryStatement = new QueryStatement(queryRelation);if (context.outfile() != null) {queryStatement.setOutFileClause((OutFileClause) visit(context.outfile()));}if (context.explainDesc() != null) {queryStatement.setIsExplain(true, getExplainType(context.explainDesc()));}if (context.optimizerTrace() != null) {String module = "base";if (context.optimizerTrace().identifier() != null) {module = ((Identifier) visit(context.optimizerTrace().identifier())).getValue();}queryStatement.setIsTrace(getTraceMode(context.optimizerTrace()), module);}return queryStatement;
}
可以看到queryStatement.setIsExplain(true, getExplainType(context.explainDesc()))这个方法：
public void setIsExplain(boolean isExplain, ExplainLevel explainLevel) {this.isExplain = isExplain;this.explainLevel = explainLevel;}
会把isExplain设置为true,
之后数据流会转到StmtExecutor.execute方法,最终会调用handleQueryStmt方法：
private void handleQueryStmt(ExecPlan execPlan) throws Exception {// Every time set no send flag and clean all data in buffercontext.getMysqlChannel().reset();boolean isExplainAnalyze = parsedStmt.isExplain()&& StatementBase.ExplainLevel.ANALYZE.equals(parsedStmt.getExplainLevel());boolean isSchedulerExplain = parsedStmt.isExplain()&& StatementBase.ExplainLevel.SCHEDULER.equals(parsedStmt.getExplainLevel());boolean isOutfileQuery = (parsedStmt instanceof QueryStatement) && ((QueryStatement) parsedStmt).hasOutFileClause();if (isOutfileQuery) {Map<TableName, Table> tables = AnalyzerUtils.collectAllTable(parsedStmt);boolean hasTemporaryTable = tables.values().stream().anyMatch(t -> t.isTemporaryTable());if (hasTemporaryTable) {throw new SemanticException("temporary table doesn't support select outfile statement");}}boolean executeInFe = !isExplainAnalyze && !isSchedulerExplain && !isOutfileQuery&& canExecuteInFe(context, execPlan.getPhysicalPlan());if (isExplainAnalyze) {context.getSessionVariable().setEnableProfile(true);context.getSessionVariable().setEnableAsyncProfile(false);context.getSessionVariable().setPipelineProfileLevel(1);} else if (isSchedulerExplain) {// Do nothing.} else if (parsedStmt.isExplain()) {String explainString = buildExplainString(execPlan, ResourceGroupClassifier.QueryType.SELECT,parsedStmt.getExplainLevel());if (executeInFe) {explainString = "EXECUTE IN FE\n" + explainString;}handleExplainStmt(explainString);return;}... StatementBase queryStmt = parsedStmt;List<PlanFragment> fragments = execPlan.getFragments();List<ScanNode> scanNodes = execPlan.getScanNodes();TDescriptorTable descTable = execPlan.getDescTbl().toThrift();List<String> colNames = execPlan.getColNames();List<Expr> outputExprs = execPlan.getOutputExprs();if (executeInFe) {coord = new FeExecuteCoordinator(context, execPlan);} else {coord = getCoordinatorFactory().createQueryScheduler(context, fragments, scanNodes, descTable);}QeProcessorImpl.INSTANCE.registerQuery(context.getExecutionId(),new QeProcessorImpl.QueryInfo(context, originStmt.originStmt, coord));if (isSchedulerExplain) {coord.startSchedulingWithoutDeploy();handleExplainStmt(coord.getSchedulerExplain());return;}coord.exec();coord.setTopProfileSupplier(this::buildTopLevelProfile);coord.setExecPlan(execPlan);对于 explain analyze 会进行如下配置:
context.getSessionVariable().setEnableProfile(true);context.getSessionVariable().setEnableAsyncProfile(false);context.getSessionVariable().setPipelineProfileLevel(1);
且会走到 coord.exec();这里会有调度的部分，如以下：
try (Timer timer = Tracers.watchScope(Tracers.Module.SCHEDULER, "Prepare")) {prepareExec();}try (Timer timer = Tracers.watchScope(Tracers.Module.SCHEDULER, "Deploy")) {deliverExecFragments(needDeploy);}
而在handleQueryStmt下后有finally的处理：
else if (context.isProfileEnabled()) {isAsync = tryProcessProfileAsync(execPlan, i);if (parsedStmt.isExplain() &&StatementBase.ExplainLevel.ANALYZE.equals(parsedStmt.getExplainLevel())) {if (coord != null && coord.isShortCircuit()) {throw new UserException("short circuit point query doesn't suppot explain analyze stmt, " +"you can set it off by using set enable_short_circuit=false");}handleExplainStmt(ExplainAnalyzer.analyze(ProfilingExecPlan.buildFrom(execPlan), profile, null));}}
ExplainAnalyzer.analyze这里就是返回的Explain String
ANALYZE PROFILE
直接跳转到Starrocks.g4:
analyzeProfileStatement: ANALYZE PROFILE FROM string| ANALYZE PROFILE FROM string ',' INTEGER_VALUE (',' INTEGER_VALUE)*;之后到AstBuilder的如下方法:
@Override
public ParseNode visitAnalyzeProfileStatement(StarRocksParser.AnalyzeProfileStatementContext context) {StringLiteral stringLiteral = (StringLiteral) visit(context.string());List<Integer> planNodeIds = Lists.newArrayList();if (context.INTEGER_VALUE() != null) {planNodeIds = context.INTEGER_VALUE().stream().map(ParseTree::getText).map(Integer::parseInt).collect(toList());}return new AnalyzeProfileStmt(stringLiteral.getStringValue(), planNodeIds, createPos(context));
}之后再到StmtExecutor.handleAnalyzeProfileStmt方法:
private void handleAnalyzeProfileStmt() throws IOException, UserException {AnalyzeProfileStmt analyzeProfileStmt = (AnalyzeProfileStmt) parsedStmt;String queryId = analyzeProfileStmt.getQueryId();List<Integer> planNodeIds = analyzeProfileStmt.getPlanNodeIds();ProfileManager.ProfileElement profileElement = ProfileManager.getInstance().getProfileElement(queryId);Preconditions.checkNotNull(profileElement, "query not exists");// For short circuit query, 'ProfileElement#plan' is nullif (profileElement.plan == null) {throw new UserException("short circuit point query doesn't suppot analyze profile stmt, " +"you can set it off by using set enable_short_circuit=false");}handleExplainStmt(ExplainAnalyzer.analyze(profileElement.plan,RuntimeProfileParser.parseFrom(CompressionUtils.gzipDecompressString(profileElement.profileContent)),planNodeIds));}
这里通过ProfileManager.getInstance().getProfileElement(queryId)获取到对应的profile,
之后再通过ExplainAnalyzer.analyze获取对应的explain string.
TRACE
具体语法参考query_trace_profile
和 EXPLAIN ANALYZE的逻辑一样，通过AstBuilder.visitQueryStatement 解析完后,走的是queryStatement.setIsTrace(getTraceMode(context.optimizerTrace()), module);这个逻辑：
public void setIsTrace(Tracers.Mode mode, String module) {this.isExplain = true;this.traceMode = mode;this.traceModule = module;}可以看到这里的isExplain为true.
而handleQueryStmt方法为:
} else if (parsedStmt.isExplain()) {String explainString = buildExplainString(execPlan, ResourceGroupClassifier.QueryType.SELECT,parsedStmt.getExplainLevel());if (executeInFe) {explainString = "EXECUTE IN FE\n" + explainString;}handleExplainStmt(explainString);return;
}
这里的buildExplainString方法，会根据trace的mode来进行explain String的构建。
其他
- 开启
Query Profile指标
| Query:Summary:- Query ID: 135d8852-62fd-11f0-b356-00163e164034- Start Time: 2025-07-17 18:59:13- End Time: 2025-07-17 18:59:14- Total: 268ms- Query Type: Query- Query State: Finished- StarRocks Version: 3.3.5-6d81f75- User: sr_read_write- Default Db- Sql Statement: SELECT `COLUMN_NAME`, `DATA_TYPE`, `ORDINAL_POSITION`, `COLUMN_SIZE`, `DECIMAL_DIGITS`, `IS_NULLABLE`, `COLUMN_KEY`, `COLUMN_COMMENT` FROM `information_schema`.`COLUMNS` WHERE `TABLE_SCHEMA`='lendtrade' AND `TABLE_NAME`='tr_tran_proc_db_sub';- Variables: parallel_fragment_exec_instance_num=8,max_parallel_scan_instance_num=-1,pipeline_dop=0,enable_adaptive_sink_dop=true,enable_runtime_adaptive_dop=false,runtime_profile_report_interval=10,resource_group=default_wg- NonDefaultSessionVariables: {"sql_mode_v2":{"defaultValue":32,"actualValue":2097184},"big_query_profile_threshold":{"defaultValue":"0s","actualValue":"30s"},"character_set_results":{"defaultValue":"utf8","actualValue":"NULL"},"parallel_fragment_exec_instance_num":{"defaultValue":1,"actualValue":8},"enable_adaptive_sink_dop":{"defaultValue":false,"actualValue":true},"enable_profile":{"defaultValue":false,"actualValue":true}}- Collect Profile Time: 2ms- IsProfileAsync: truePlanner:- -- Parser[1] 0- -- Total[1] 0- -- Analyzer[1] 0- -- Lock[1] 0- -- AnalyzeDatabase[1] 0- -- AnalyzeTemporaryTable[1] 0- -- AnalyzeTable[1] 0- -- Transformer[1] 0- -- Optimizer[1] 0- -- MVPreprocess[1] 0- -- MVChooseCandidates[1] 0- -- MVGenerateMvPlan[1] 0- -- MVValidateMv[1] 0- -- MVProcessWithView[1] 0- -- MVTextRewrite[1] 0- -- RuleBaseOptimize[1] 0- -- CostBaseOptimize[1] 0- -- PhysicalRewrite[1] 0- -- PlanValidate[1] 0- -- InputDependenciesChecker[1] 0- -- TypeChecker[1] 0- -- CTEUniqueChecker[1] 0- -- ColumnReuseChecker[1] 0- -- ExecPlanBuild[1] 0- -- Pending[1] 0- -- Prepare[1] 0- -- Deploy[1] 23ms- -- DeployLockInternalTime[1] 23ms- -- DeploySerializeConcurrencyTime[1] 0- -- DeployStageByStageTime[3] 0- -- DeployWaitTime[3] 23ms- -- DeployAsyncSendTime[1] 0- DeployDataSize: 5803Reason:Execution:- Topology: {"rootId":1,"nodes":[{"id":1,"name":"PROJECT","properties":{"sinkIds":[],"displayMem":false},"children":[0]},{"id":0,"name":"SCHEMA_SCAN","properties":{"displayMem":false},"children":[]}]}- FrontendProfileMergeTime: 732.454us- QueryAllocatedMemoryUsage: 1015.680 KB- QueryCumulativeCpuTime: 11.169ms- QueryCumulativeNetworkTime: 0ns- QueryCumulativeOperatorTime: 240.565ms- QueryCumulativeScanTime: 229.352ms- QueryDeallocatedMemoryUsage: 840.773 KB- QueryExecutionWallTime: 257.617ms- QueryPeakMemoryUsagePerNode: 485.695 KB- QueryPeakScheduleTime: 42.480us- QuerySpillBytes: 0.000 B- QuerySumMemoryUsage: 485.695 KB- ResultDeliverTime: 0nsFragment 0:- BackendAddresses: 172.17.172.252:9060- InstanceIds: 135d8852-62fd-11f0-b356-00163e164035- BackendNum: 1- BackendProfileMergeTime: 541.804us- FragmentInstancePrepareTime: 16.399ms- prepare-fragment-ctx: 922ns- prepare-pipeline-driver: 3.447ms- prepare-pipeline-driver-factory: 8.697ms- prepare-query-ctx: 3.826us- prepare-runtime-state: 4.247ms- InitialProcessDriverCount: 0- InitialProcessMem: 15.307 GB- InstanceAllocatedMemoryUsage: 1015.680 KB- InstanceDeallocatedMemoryUsage: 840.773 KB- InstanceNum: 1- InstancePeakMemoryUsage: 478.039 KB- JITCounter: 0- JITTotalCostTime: 0ns- QueryMemoryLimit: -1.000 BPipeline (id=0):- isGroupExecution: false- ActiveTime: 11.183ms- BlockByInputEmpty: 2- BlockByOutputFull: 0- BlockByPrecondition: 0- DegreeOfParallelism: 1- DriverPrepareTime: 3.445ms- DriverTotalTime: 240.546ms- OverheadTime: 0ns- PeakDriverQueueSize: 0- PendingTime: 229.320ms- InputEmptyTime: 229.323ms- FirstInputEmptyTime: 229.245ms- FollowupInputEmptyTime: 78.368us- OutputFullTime: 0ns- PendingFinishTime: 0ns- PreconditionBlockTime: 0ns- ScheduleCount: 3- ScheduleTime: 42.480us- TotalDegreeOfParallelism: 1- YieldByLocalWait: 0- YieldByPreempt: 0- YieldByTimeLimit: 0RESULT_SINK (plan_node_id=-1):CommonMetrics:- IsFinalSink- CloseTime: 7.404us- OperatorAllocatedMemoryUsage: 19.320 KB- OperatorDeallocatedMemoryUsage: 20.281 KB- OperatorPeakMemoryUsage: 0.000 B- OperatorTotalTime: 5.905ms- PrepareTime: 3.384ms- PullChunkNum: 0- PullRowNum: 0- PullTotalTime: 0ns- PushChunkNum: 1- PushRowNum: 38- PushTotalTime: 5.897ms- SetFinishedTime: 30ns- SetFinishingTime: 60nsUniqueMetrics:result sink:- AppendChunkTime: 5.859ms- ResultRendTime: 33.463us- TupleConvertTime: 5.856ms- NumSentRows: 38CHUNK_ACCUMULATE (plan_node_id=-1):CommonMetrics:- IsSubordinate- CloseTime: 161ns- OperatorTotalTime: 1.133us- PrepareTime: 5.921us- PullChunkNum: 1- PullRowNum: 38- PullTotalTime: 280ns- PushChunkNum: 1- PushRowNum: 38- PushTotalTime: 613ns- SetFinishedTime: 50ns- SetFinishingTime: 29nsUniqueMetrics:PROJECT (plan_node_id=1):CommonMetrics:- CloseTime: 5.650us- OperatorAllocatedMemoryUsage: 1.016 KB- OperatorDeallocatedMemoryUsage: 416.000 B- OperatorPeakMemoryUsage: 640.000 B- OperatorTotalTime: 12.503us- PrepareTime: 7.204us- PullChunkNum: 1- PullRowNum: 38- PullTotalTime: 230ns- PushChunkNum: 1- PushRowNum: 38- PushTotalTime: 6.351us- RuntimeBloomFilterNum: 0- RuntimeInFilterNum: 0- SetFinishedTime: 141ns- SetFinishingTime: 131nsUniqueMetrics:- CommonSubExprComputeTime: 251ns- ExprComputeTime: 2.494usCHUNK_ACCUMULATE (plan_node_id=0):CommonMetrics:- IsSubordinate- CloseTime: 301ns- OperatorTotalTime: 2.636us- PrepareTime: 11.191us- PullChunkNum: 1- PullRowNum: 38- PullTotalTime: 191ns- PushChunkNum: 1- PushRowNum: 38- PushTotalTime: 1.823us- SetFinishedTime: 161ns- SetFinishingTime: 160nsUniqueMetrics:SCHEMA_SCAN (plan_node_id=0):CommonMetrics:- CloseTime: 64.822us- OperatorAllocatedMemoryUsage: 839.242 KB- OperatorDeallocatedMemoryUsage: 552.344 KB- OperatorPeakMemoryUsage: 307.672 KB- OperatorTotalTime: 5.292ms- PrepareTime: 16.070us- PullChunkNum: 1- PullRowNum: 38- PullTotalTime: 5.226ms- PushChunkNum: 0- PushRowNum: 0- PushTotalTime: 0ns- SetFinishedTime: 231ns- SetFinishingTime: 521nsUniqueMetrics:- MorselQueueType: fixed_morsel_queue- ChunkBufferCapacity: 64- DefaultChunkBufferCapacity: 64- FERPC: 211.509ms- FillChunk: 4.506ms- FilterTime: 12.890ms- IOTaskExecTime: 229.309ms- IOTaskWaitTime: 42.740us- MorselsCount: 1- PeakChunkBufferMemoryUsage: 250.513 KB- PeakChunkBufferSize: 1- PeakIOTasks: 1- PeakScanTaskQueueSize: 0- PrepareChunkSourceTime: 5.204ms- ScanTime: 229.352ms- SubmitTaskCount: 2- SubmitTaskTime: 8.015us- TabletCount: 1|
EXPLAIN ANALYZE
+-------------------------------------------------------------------------------------------------------------------------------------+
| Explain String |
+-------------------------------------------------------------------------------------------------------------------------------------+
| Summary |
| QueryId: 6b148971-71e6-11f0-8cea-00163e39052a |
| Version: 3.3.5-6d81f75 |
| State: Finished |
| TotalTime: 2s51ms |
| ExecutionTime: 0ns [Scan: 0ns (NaN%), Network: 0ns (NaN%), ResultDeliverTime: 0ns (NaN%), ScheduleTime: 0ns (NaN%)] |
| CollectProfileTime: 2s1ms |
| FrontendProfileMergeTime: 361.325us |
| QueryPeakMemoryUsage: ?, QueryAllocatedMemoryUsage: 0.000 B |
| Top Most Time-consuming Nodes: |
| 1. RESULT_SINK: 0ns (NaN%) |
| 2. SCHEMA_SCAN (id=0) : 0ns (NaN%) |
| Top Most Memory-consuming Nodes: |
| NonDefaultVariables: |
| big_query_profile_threshold: 0s -> 30s |
| enable_adaptive_sink_dop: false -> true |
| enable_async_profile: true -> false |
| enable_profile: false -> true |
| parallel_fragment_exec_instance_num: 1 -> 8 |
| Fragment 0 |
| │ BackendNum: 1 |
| │ InstancePeakMemoryUsage: ?, InstanceAllocatedMemoryUsage: ? |
| │ PrepareTime: ? |
| │ MissingInstanceIds: 6b148971-71e6-11f0-8cea-00163e39052b |
| └──RESULT_SINK |
| │ SinkType: MYSQL_PROTOCAL |
| └──SCHEMA_SCAN (id=0) |
| Estimates: [row: 1, cpu: ?, memory: ?, network: ?, cost: 0.0] |
| TotalTime: 0ns (NaN%) [CPUTime: ?] |
| OutputRows: ? |
| |
+-------------------------------------------------------------------------------------------------------------------------------------+
ANALYZE PROFILE展示的和explain analyze一样，但是指标比explain analyze更加丰富
+-----------------------------------------------------------------------------------------------------------------------------------------------------------+
| Explain String |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------+
| Summary |
| QueryId: 135d8852-62fd-11f0-b356-00163e164034 |
| Version: 3.3.5-6d81f75 |
| State: Finished |
| TotalTime: 268ms |
| ExecutionTime: 257.617ms [Scan: 229.352ms (89.03%), Network: 0ns (0.00%), ResultDeliverTime: 0ns (0.00%), ScheduleTime: 42.480us (0.02%)] |
| CollectProfileTime: 2ms |
| FrontendProfileMergeTime: 732.454us |
| QueryPeakMemoryUsage: ?, QueryAllocatedMemoryUsage: 1015.680 KB |
| Top Most Time-consuming Nodes: |
| 1. SCHEMA_SCAN (id=0) : 234.646ms (97.54%) |
| 2. RESULT_SINK: 5.906ms (2.46%) |
| 3. PROJECT (id=1) : 12.503us (0.01%) |
| Top Most Memory-consuming Nodes: |
| NonDefaultVariables: |
| big_query_profile_threshold: 0s -> 30s |
| character_set_results: utf8 -> NULL |
| enable_adaptive_sink_dop: false -> true |
| enable_profile: false -> true |
| parallel_fragment_exec_instance_num: 1 -> 8 |
| sql_mode_v2: 32 -> 2097184 |
| Fragment 0 |
| │ BackendNum: 1 |
| │ InstancePeakMemoryUsage: 478.038 KB, InstanceAllocatedMemoryUsage: 1015.680 KB |
| │ PrepareTime: 16.399ms |
| └──RESULT_SINK |
| │ TotalTime: 5.906ms (2.46%) [CPUTime: 5.906ms] |
| │ OutputRows: 38 |
| │ SinkType: MYSQL_PROTOCAL |
| └──PROJECT (id=1) |
| │ Estimates: [row: ?, cpu: ?, memory: ?, network: ?, cost: ?] |
| │ TotalTime: 12.503us (0.01%) [CPUTime: 12.503us] |
| │ OutputRows: 38 |
| │ Expression: [4: COLUMN_NAME, 5: ORDINAL_POSITION, 7: IS_NULLABLE, 8: DATA_TYPE, ...] |
| └──SCHEMA_SCAN (id=0) |
| Estimates: [row: 1, cpu: ?, memory: ?, network: ?, cost: 0.0] |
| TotalTime: 234.646ms (97.54%) [CPUTime: 5.294ms, ScanTime: 229.352ms] |
| OutputRows: 38 |
| SubordinateOperators: |
| CHUNK_ACCUMULATE |
| Detail Timers: [ScanTime = IOTaskExecTime + IOTaskWaitTime] |
| FERPC: 211.509ms |
| IOTaskExecTime: 229.309ms |
| IOTaskWaitTime: 42.740us |
| |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------+
trace展示的是某个局部，比如说 某个规则的耗时
MySQL [(none)]> trace times SCHEDULE SELECT `SCHEMA_NAME` FROM `INFORMATION_SCHEMA`.`SCHEMATA` WHERE SCHEMA_NAME = 'fin_config';
+--------------------------------------------------+
| Explain String |
+--------------------------------------------------+
| 0ms|-- Parser[1] 0 |
| 0ms|-- Total[1] 0 |
| 0ms| -- Analyzer[1] 0 |
| 0ms| -- Lock[1] 0 |
| 0ms| -- AnalyzeDatabase[1] 0 |
| 0ms| -- AnalyzeTemporaryTable[1] 0 |
| 0ms| -- AnalyzeTable[1] 0 |
| 0ms| -- Transformer[1] 0 |
| 0ms| -- Optimizer[1] 0 |
| 0ms| -- MVPreprocess[1] 0 |
| 0ms| -- MVChooseCandidates[1] 0 |
| 0ms| -- MVGenerateMvPlan[1] 0 |
| 0ms| -- MVValidateMv[1] 0 |
| 0ms| -- MVProcessWithView[1] 0 |
| 0ms| -- MVTextRewrite[1] 0 |
| 0ms| -- RuleBaseOptimize[1] 0 |
| 0ms| -- CostBaseOptimize[1] 0 |
| 1ms| -- PhysicalRewrite[1] 0 |
| 1ms| -- PlanValidate[1] 0 |
| 1ms| -- InputDependenciesChecker[1] 0 |
| 1ms| -- TypeChecker[1] 0 |
| 1ms| -- CTEUniqueChecker[1] 0 |
| 1ms| -- ColumnReuseChecker[1] 0 |
| 1ms| -- ExecPlanBuild[1] 0 |
| Tracer Cost: 9us |
+--------------------------------------------------+MySQL [(none)]> trace times OPTIMIZER SELECT `SCHEMA_NAME` FROM `INFORMATION_SCHEMA`.`SCHEMATA` WHERE SCHEMA_NAME = 'fin_config';
+----------------------------------------------------------+
| Explain String |
+----------------------------------------------------------+
| 0ms|-- Parser[1] 0 |
| 0ms|-- Total[1] 0 |
| 0ms| -- Analyzer[1] 0 |
| 0ms| -- Lock[1] 0 |
| 0ms| -- AnalyzeDatabase[1] 0 |
| 0ms| -- AnalyzeTemporaryTable[1] 0 |
| 0ms| -- AnalyzeTable[1] 0 |
| 0ms| -- Transformer[1] 0 |
| 0ms| -- Optimizer[1] 0 |
| 0ms| -- MVPreprocess[1] 0 |
| 0ms| -- MVChooseCandidates[1] 0 |
| 0ms| -- MVGenerateMvPlan[1] 0 |
| 0ms| -- MVValidateMv[1] 0 |
| 0ms| -- MVProcessWithView[1] 0 |
| 0ms| -- MVTextRewrite[1] 0 |
| 0ms| -- RuleBaseOptimize[1] 0 |
| 0ms| -- RewriteTreeTask[59] 0 |
| 0ms| -- PushDownPredicateProjectRule[1] 0 |
| 0ms| -- PushDownPredicateScanRule[1] 0 |
| 0ms| -- MergeTwoProjectRule[2] 0 |
| 0ms| -- PruneProjectColumnsRule[2] 0 |
| 0ms| -- PruneScanColumnRule[2] 0 |
| 0ms| -- PruneSubfieldRule[1] 0 |
| 0ms| -- PruneProjectRule[2] 0 |
| 0ms| -- MergeProjectWithChildRule[1] 0 |
| 0ms| -- CostBaseOptimize[1] 0 |
| 0ms| -- OptimizeGroupTask[1] 0 |
| 0ms| -- OptimizeExpressionTask[1] 0 |
| 0ms| -- DeriveStatsTask[1] 0 |
| 0ms| -- ApplyRuleTask[1] 0 |
| 0ms| -- SchemaScanImplementationRule[1] 0 |
| 0ms| -- EnforceAndCostTask[1] 0 |
| 0ms| -- PhysicalRewrite[1] 0 |
| 1ms| -- PlanValidate[1] 0 |
| 1ms| -- InputDependenciesChecker[1] 0 |
| 1ms| -- TypeChecker[1] 0 |
| 1ms| -- CTEUniqueChecker[1] 0 |
| 1ms| -- ColumnReuseChecker[1] 0 |
| 1ms| -- ExecPlanBuild[1] 0 |
| Tracer Cost: 21us |
+----------------------------------------------------------+其中这里面的[1] 数字代码该规则被应用的次数，如 PhysicalRewrite[1]则表示 改规则被应用了1次。