Skip to content

Commit

Permalink
[Impl](Nereids) add nereids gc cost time and be fold const cost time …
Browse files Browse the repository at this point in the history
…to profile (apache#42007)

add Nereids GarbageCollect Time and Nereids BeFoldConst Time to profile
  • Loading branch information
LiBinfeng-01 committed Oct 28, 2024
1 parent cea29ac commit f2b13a8
Show file tree
Hide file tree
Showing 4 changed files with 63 additions and 1 deletion.
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,8 @@ public class SummaryProfile {
public static final String NEREIDS_OPTIMIZE_TIME = "Nereids Optimize Time";
public static final String NEREIDS_TRANSLATE_TIME = "Nereids Translate Time";
public static final String NEREIDS_DISTRIBUTE_TIME = "Nereids Distribute Time";
public static final String NEREIDS_GARBAGE_COLLECT_TIME = "Nereids GarbageCollect Time";
public static final String NEREIDS_BE_FOLD_CONST_TIME = "Nereids BeFoldConst Time";

public static final String FRAGMENT_COMPRESSED_SIZE = "Fragment Compressed Size";
public static final String FRAGMENT_RPC_COUNT = "Fragment RPC Count";
Expand Down Expand Up @@ -229,6 +231,10 @@ public class SummaryProfile {
private long nereidsOptimizeFinishTime = -1;
@SerializedName(value = "nereidsTranslateFinishTime")
private long nereidsTranslateFinishTime = -1;
@SerializedName(value = "nereidsGarbageCollectionTime")
private long nereidsGarbageCollectionTime = -1;
@SerializedName(value = "nereidsBeFoldConstTime")
private long nereidsBeFoldConstTime = 0;
private long nereidsDistributeFinishTime = -1;
// timestamp of query begin
@SerializedName(value = "queryBeginTime")
Expand Down Expand Up @@ -408,6 +414,8 @@ private void updateExecutionSummaryProfile() {
executionSummaryProfile.addInfoString(NEREIDS_OPTIMIZE_TIME, getPrettyNereidsOptimizeTime());
executionSummaryProfile.addInfoString(NEREIDS_TRANSLATE_TIME, getPrettyNereidsTranslateTime());
executionSummaryProfile.addInfoString(NEREIDS_DISTRIBUTE_TIME, getPrettyNereidsDistributeTime());
executionSummaryProfile.addInfoString(NEREIDS_GARBAGE_COLLECT_TIME, getPrettyNereidsGarbageCollectionTime());
executionSummaryProfile.addInfoString(NEREIDS_BE_FOLD_CONST_TIME, getPrettyNereidsBeFoldConstTime());
executionSummaryProfile.addInfoString(ANALYSIS_TIME,
getPrettyTime(queryAnalysisFinishTime, queryBeginTime, TUnit.TIME_MS));
executionSummaryProfile.addInfoString(PLAN_TIME,
Expand Down Expand Up @@ -513,6 +521,14 @@ public void setNereidsTranslateTime() {
this.nereidsTranslateFinishTime = TimeUtils.getStartTimeMs();
}

public void setNereidsGarbageCollectionTime(long nereidsGarbageCollectionTime) {
this.nereidsGarbageCollectionTime = nereidsGarbageCollectionTime;
}

public void sumBeFoldTime(long beFoldConstTimeOnce) {
this.nereidsBeFoldConstTime += beFoldConstTimeOnce;
}

public void setNereidsDistributeTime() {
this.nereidsDistributeFinishTime = TimeUtils.getStartTimeMs();
}
Expand Down Expand Up @@ -765,6 +781,14 @@ public String getPrettyNereidsTranslateTime() {
return getPrettyTime(nereidsTranslateFinishTime, nereidsOptimizeFinishTime, TUnit.TIME_MS);
}

public String getPrettyNereidsGarbageCollectionTime() {
return RuntimeProfile.printCounter(nereidsGarbageCollectionTime, TUnit.TIME_MS);
}

public String getPrettyNereidsBeFoldConstTime() {
return RuntimeProfile.printCounter(nereidsBeFoldConstTime, TUnit.TIME_MS);
}

public String getPrettyNereidsDistributeTime() {
return getPrettyTime(nereidsDistributeFinishTime, nereidsTranslateFinishTime, TUnit.TIME_MS);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -82,6 +82,8 @@
import org.apache.logging.log4j.Logger;

import java.io.IOException;
import java.lang.management.GarbageCollectorMXBean;
import java.lang.management.ManagementFactory;
import java.nio.ByteBuffer;
import java.util.ArrayList;
import java.util.List;
Expand Down Expand Up @@ -187,6 +189,7 @@ public Plan planWithLock(LogicalPlan plan, PhysicalProperties requireProperties,
ExplainLevel explainLevel, boolean showPlanProcess,
Consumer<Plan> lockCallback) {
try {
long beforePlanGcTime = getGarbageCollectionTime();
if (plan instanceof LogicalSqlCache) {
rewrittenPlan = analyzedPlan = plan;
LogicalSqlCache logicalSqlCache = (LogicalSqlCache) plan;
Expand Down Expand Up @@ -214,6 +217,10 @@ public Plan planWithLock(LogicalPlan plan, PhysicalProperties requireProperties,
try (Lock lock = new Lock(plan, cascadesContext)) {
Plan resultPlan = planWithoutLock(plan, explainLevel, showPlanProcess, requireProperties);
lockCallback.accept(resultPlan);
if (statementContext.getConnectContext().getExecutor() != null) {
statementContext.getConnectContext().getExecutor().getSummaryProfile()
.setNereidsGarbageCollectionTime(getGarbageCollectionTime() - beforePlanGcTime);
}
return resultPlan;
}
} finally {
Expand Down Expand Up @@ -536,6 +543,15 @@ private PhysicalPlan chooseBestPlan(Group rootGroup, PhysicalProperties physical
}
}

private long getGarbageCollectionTime() {
List<GarbageCollectorMXBean> gcMxBeans = ManagementFactory.getGarbageCollectorMXBeans();
long initialGCTime = 0;
for (GarbageCollectorMXBean gcBean : gcMxBeans) {
initialGCTime += gcBean.getCollectionTime();
}
return initialGCTime;
}

/**
* getting hints explain string, which specified by enumerate and show in lists
* @param hints hint map recorded in statement context
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -268,7 +268,6 @@ private static boolean shouldSkipFold(Expression expr) {

private static Map<String, Expression> evalOnBE(Map<String, Map<String, TExpr>> paramMap,
Map<String, Expression> constMap, ConnectContext context) {

Map<String, Expression> resultMap = new HashMap<>();
try {
List<Long> backendIds = Env.getCurrentSystemInfo().getAllBackendIds(true);
Expand Down Expand Up @@ -300,7 +299,14 @@ private static Map<String, Expression> evalOnBE(Map<String, Map<String, TExpr>>

Future<PConstantExprResult> future = BackendServiceProxy.getInstance().foldConstantExpr(brpcAddress,
tParams);
long beFoldStartTime = 0L;
if (context.getSessionVariable().enableProfile()) {
beFoldStartTime = TimeUtils.getStartTimeMs();
}
PConstantExprResult result = future.get(5, TimeUnit.SECONDS);
if (context.getExecutor() != null && context.getSessionVariable().enableProfile()) {
context.getExecutor().getSummaryProfile().sumBeFoldTime(TimeUtils.getStartTimeMs() - beFoldStartTime);
}

if (result.getStatus().getStatusCode() == 0) {
for (Entry<String, InternalService.PExprResultMap> e : result.getExprResultMapMap().entrySet()) {
Expand Down
16 changes: 16 additions & 0 deletions regression-test/suites/query_profile/test_profile.groovy
Original file line number Diff line number Diff line change
Expand Up @@ -79,6 +79,22 @@ suite('test_profile') {
}
assertTrue(isRecorded)

sql "set enable_nereids_planner=true"
sql "set enable_fallback_to_original_planner=false"

int randomInt = Math.random() * 2000000000
profile("test_profile_time_${randomInt}") {
run {
sql "/* test_profile_time_${randomInt} */ select ${randomInt} from test_profile"
}

check { profileString, exception ->
log.info(profileString)
assertTrue(profileString.contains("Nereids GarbageCollect Time"))
assertTrue(profileString.contains("Nereids BeFoldConst Time"))
}
}

sql """ SET enable_profile = false """
sql """ DROP TABLE IF EXISTS test_profile """
}

0 comments on commit f2b13a8

Please sign in to comment.