You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by yi...@apache.org on 2022/12/06 06:32:24 UTC
[doris] branch master updated: [Exec](Profile) Register to Fetch Result time and Write Result time in FE to debug (#14832)
This is an automated email from the ASF dual-hosted git repository.
yiguolei pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/doris.git
The following commit(s) were added to refs/heads/master by this push:
new fb78807430 [Exec](Profile) Register to Fetch Result time and Write Result time in FE to debug (#14832)
fb78807430 is described below
commit fb78807430115b635c16d1510a04d81bb3e2ee98
Author: HappenLee <ha...@hotmail.com>
AuthorDate: Tue Dec 6 14:32:18 2022 +0800
[Exec](Profile) Register to Fetch Result time and Write Result time in FE to debug (#14832)
---
.../doris/common/util/QueryPlannerProfile.java | 30 ++++++++++++++++++++--
.../java/org/apache/doris/qe/StmtExecutor.java | 8 ++++++
2 files changed, 36 insertions(+), 2 deletions(-)
diff --git a/fe/fe-core/src/main/java/org/apache/doris/common/util/QueryPlannerProfile.java b/fe/fe-core/src/main/java/org/apache/doris/common/util/QueryPlannerProfile.java
index 6ea3efa560..df5ae5aee2 100644
--- a/fe/fe-core/src/main/java/org/apache/doris/common/util/QueryPlannerProfile.java
+++ b/fe/fe-core/src/main/java/org/apache/doris/common/util/QueryPlannerProfile.java
@@ -30,7 +30,11 @@ public class QueryPlannerProfile {
public static final String KEY_ANALYSIS = "Analysis Time";
public static final String KEY_PLAN = "Plan Time";
public static final String KEY_SCHEDULE = "Schedule Time";
- public static final String KEY_FETCH = "Wait and Fetch Result Time";
+ public static final String KEY_WAIT_AND_FETCH = "Wait and Fetch Result Time";
+
+ public static final String KEY_FETCH = "Fetch Result Time";
+
+ public static final String KEY_WRITE = "Write Result Time";
// timestamp of query begin
private long queryBeginTime = -1;
@@ -43,6 +47,12 @@ public class QueryPlannerProfile {
// Query result fetch end time
private long queryFetchResultFinishTime = -1;
+ private long tempStarTime = -1;
+
+ private long queryFetchResultConsumeTime = 0;
+
+ private long queryWriteResultConsumeTime = 0;
+
public void setQueryBeginTime() {
this.queryBeginTime = TimeUtils.getStartTime();
}
@@ -63,6 +73,18 @@ public class QueryPlannerProfile {
this.queryFetchResultFinishTime = TimeUtils.getStartTime();
}
+ public void setTempStartTime() {
+ this.tempStarTime = TimeUtils.getStartTime();
+ }
+
+ public void freshFetchResultConsumeTime() {
+ this.queryFetchResultConsumeTime += TimeUtils.getStartTime() - tempStarTime;
+ }
+
+ public void freshWriteResultConsumeTime() {
+ this.queryWriteResultConsumeTime += TimeUtils.getStartTime() - tempStarTime;
+ }
+
public long getQueryBeginTime() {
return queryBeginTime;
}
@@ -99,6 +121,10 @@ public class QueryPlannerProfile {
plannerProfile.addInfoString(KEY_ANALYSIS, getPrettyQueryAnalysisFinishTime());
plannerProfile.addInfoString(KEY_PLAN, getPrettyQueryPlanFinishTime());
plannerProfile.addInfoString(KEY_SCHEDULE, getPrettyQueryScheduleFinishTime());
- plannerProfile.addInfoString(KEY_FETCH, getPrettyQueryFetchResultFinishTime());
+ plannerProfile.addInfoString(KEY_FETCH,
+ RuntimeProfile.printCounter(queryFetchResultConsumeTime, TUnit.TIME_NS));
+ plannerProfile.addInfoString(KEY_WRITE,
+ RuntimeProfile.printCounter(queryWriteResultConsumeTime, TUnit.TIME_NS));
+ plannerProfile.addInfoString(KEY_WAIT_AND_FETCH, getPrettyQueryFetchResultFinishTime());
}
}
diff --git a/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java b/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java
index f06fcbb1ec..a4a8c44496 100644
--- a/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java
+++ b/fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java
@@ -1135,12 +1135,19 @@ public class StmtExecutor implements ProfileWriter {
Span fetchResultSpan = context.getTracer().spanBuilder("fetch result").setParent(Context.current()).startSpan();
try (Scope scope = fetchResultSpan.makeCurrent()) {
while (true) {
+ // register the fetch result time.
+ plannerProfile.setTempStartTime();
batch = coord.getNext();
+ plannerProfile.freshFetchResultConsumeTime();
+
// for outfile query, there will be only one empty batch send back with eos flag
if (batch.getBatch() != null) {
if (cacheAnalyzer != null) {
cacheAnalyzer.copyRowBatch(batch);
}
+
+ // register send field result time.
+ plannerProfile.setTempStartTime();
// For some language driver, getting error packet after fields packet
// will be recognized as a success result
// so We need to send fields after first batch arrived
@@ -1155,6 +1162,7 @@ public class StmtExecutor implements ProfileWriter {
for (ByteBuffer row : batch.getBatch().getRows()) {
channel.sendOnePacket(row);
}
+ plannerProfile.freshWriteResultConsumeTime();
context.updateReturnRows(batch.getBatch().getRows().size());
}
if (batch.isEos()) {
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org