背景
本文基于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 buffer
context.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 null
if (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: true
Planner:
- -- 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: 5803
Reason:
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: 0ns
Fragment 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 B
Pipeline (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: 0
RESULT_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: 60ns
UniqueMetrics:
result sink:
- AppendChunkTime: 5.859ms
- ResultRendTime: 33.463us
- TupleConvertTime: 5.856ms
- NumSentRows: 38
CHUNK_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: 29ns
UniqueMetrics:
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: 131ns
UniqueMetrics:
- CommonSubExprComputeTime: 251ns
- ExprComputeTime: 2.494us
CHUNK_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: 160ns
UniqueMetrics:
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: 521ns
UniqueMetrics:
- 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次。
1653
扫一扫
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
