背景
本文基于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次。