Skip to content

Commit 373a1d7

Browse files
arhimondrNikhilCollooru
arhimondr
authored and
NikhilCollooru
committed
Record CPU time on various planning stages
1 parent af6399a commit 373a1d7

File tree

11 files changed

+99
-37
lines changed

11 files changed

+99
-37
lines changed

‎presto-common/src/main/java/com/facebook/presto/common/RuntimeMetricName.java

+3
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,9 @@ private RuntimeMetricName()
5050
public static final String SCAN_STAGE_SCHEDULER_CPU_TIME_NANOS = "scanStageSchedulerCpuTimeNanos";
5151
public static final String SCAN_STAGE_SCHEDULER_WALL_TIME_NANOS = "scanStageSchedulerWallTimeNanos";
5252
public static final String SCAN_STAGE_SCHEDULER_BLOCKED_TIME_NANOS = "scanStageSchedulerBlockedTimeNanos";
53+
public static final String ANALYZE_TIME_NANOS = "analyzeTimeNanos";
54+
public static final String PLAN_AND_OPTIMIZE_TIME_NANOS = "planAndOptimizeTimeNanos";
55+
public static final String CREATE_SCHEDULER_TIME_NANOS = "createSchedulerTimeNanos";
5356
public static final String LOGICAL_PLANNER_TIME_NANOS = "logicalPlannerTimeNanos";
5457
public static final String OPTIMIZER_TIME_NANOS = "optimizerTimeNanos";
5558
public static final String GET_CANONICAL_INFO_TIME_NANOS = "getCanonicalInfoTimeNanos";

‎presto-common/src/main/java/com/facebook/presto/common/RuntimeStats.java

+33-5
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,8 @@
1919
import com.fasterxml.jackson.annotation.JsonCreator;
2020
import com.fasterxml.jackson.annotation.JsonValue;
2121

22+
import java.lang.management.ManagementFactory;
23+
import java.lang.management.ThreadMXBean;
2224
import java.util.Collections;
2325
import java.util.Map;
2426
import java.util.concurrent.ConcurrentHashMap;
@@ -34,6 +36,8 @@
3436
@ThriftStruct
3537
public class RuntimeStats
3638
{
39+
private static final ThreadMXBean THREAD_MX_BEAN = ManagementFactory.getThreadMXBean();
40+
3741
private final ConcurrentMap<String, RuntimeMetric> metrics = new ConcurrentHashMap<>();
3842

3943
public RuntimeStats()
@@ -130,18 +134,42 @@ public void update(RuntimeStats stats)
130134
stats.getMetrics().forEach((name, newMetric) -> metrics.computeIfAbsent(name, k -> new RuntimeMetric(name, newMetric.getUnit())).set(newMetric));
131135
}
132136

133-
public <V> V profileNanos(String tag, Supplier<V> supplier)
137+
public <V> V recordWallTime(String tag, Supplier<V> supplier)
134138
{
135139
long startTime = System.nanoTime();
136140
V result = supplier.get();
137141
addMetricValueIgnoreZero(tag, NANO, System.nanoTime() - startTime);
138142
return result;
139143
}
140144

141-
public void profileNanosVoid(String tag, Runnable runnable)
145+
public void recordWallTime(String tag, Runnable runnable)
142146
{
143-
long startTime = System.nanoTime();
144-
runnable.run();
145-
addMetricValueIgnoreZero(tag, NANO, System.nanoTime() - startTime);
147+
recordWallTime(tag, () -> {
148+
runnable.run();
149+
return null;
150+
});
151+
}
152+
153+
public <V> V recordWallAndCpuTime(String tag, Supplier<V> supplier)
154+
{
155+
long startWall = System.nanoTime();
156+
long startCpu = THREAD_MX_BEAN.getCurrentThreadCpuTime();
157+
158+
V result = supplier.get();
159+
160+
long endWall = System.nanoTime();
161+
long endCpu = THREAD_MX_BEAN.getCurrentThreadCpuTime();
162+
163+
addMetricValueIgnoreZero(tag, NANO, endWall - startWall);
164+
addMetricValueIgnoreZero(tag + "OnCpu", NANO, endCpu - startCpu);
165+
return result;
166+
}
167+
168+
public void recordWallAndCpuTime(String tag, Runnable runnable)
169+
{
170+
recordWallAndCpuTime(tag, () -> {
171+
runnable.run();
172+
return null;
173+
});
146174
}
147175
}

‎presto-common/src/test/java/com/facebook/presto/common/TestRuntimeStats.java

+20-7
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,9 @@
1919
import static com.facebook.presto.common.RuntimeUnit.BYTE;
2020
import static com.facebook.presto.common.RuntimeUnit.NANO;
2121
import static com.facebook.presto.common.RuntimeUnit.NONE;
22+
import static com.google.common.util.concurrent.Uninterruptibles.sleepUninterruptibly;
23+
import static java.util.concurrent.TimeUnit.MILLISECONDS;
24+
import static org.assertj.core.api.Assertions.assertThat;
2225
import static org.testng.Assert.assertEquals;
2326
import static org.testng.Assert.assertNull;
2427

@@ -238,21 +241,31 @@ public void testReturnUnmodifiedMetrics()
238241
}
239242

240243
@Test
241-
public void testProfileNano()
244+
public void testRecordWallTime()
242245
{
243246
RuntimeStats stats = new RuntimeStats();
244-
int status = stats.profileNanos(TEST_METRIC_NAME_NANO_3, () -> 1);
245247

246-
assert stats.getMetric(TEST_METRIC_NAME_NANO_3).getSum() < ONE_SECOND_IN_NANOS;
247-
assertEquals(status, 1);
248+
assertEquals(stats.recordWallTime(TEST_METRIC_NAME_NANO_3, () -> 1), 1);
249+
assertThat(stats.getMetric(TEST_METRIC_NAME_NANO_3).getSum()).isLessThan(ONE_SECOND_IN_NANOS);
250+
251+
stats.recordWallTime(TEST_METRIC_NAME_NANO_2, () -> {});
252+
assertThat(stats.getMetric(TEST_METRIC_NAME_NANO_2).getSum()).isLessThan(ONE_SECOND_IN_NANOS);
248253
}
249254

250255
@Test
251-
public void testProfileNanoVoid()
256+
public void testRecordWallAndCpuTime()
252257
{
253258
RuntimeStats stats = new RuntimeStats();
254-
stats.profileNanosVoid(TEST_METRIC_NAME_NANO_3, () -> {});
255259

256-
assert stats.getMetric(TEST_METRIC_NAME_NANO_3).getSum() < ONE_SECOND_IN_NANOS;
260+
assertEquals(stats.recordWallAndCpuTime(TEST_METRIC_NAME_NANO_1, () -> {
261+
sleepUninterruptibly(100, MILLISECONDS);
262+
return 1;
263+
}), 1);
264+
assertThat(stats.getMetric(TEST_METRIC_NAME_NANO_1).getSum()).isGreaterThanOrEqualTo(MILLISECONDS.toNanos(100));
265+
assertThat(stats.getMetric(TEST_METRIC_NAME_NANO_1 + "OnCpu").getSum()).isLessThan(MILLISECONDS.toNanos(100));
266+
267+
stats.recordWallAndCpuTime(TEST_METRIC_NAME_NANO_2, () -> sleepUninterruptibly(100, MILLISECONDS));
268+
assertThat(stats.getMetric(TEST_METRIC_NAME_NANO_2).getSum()).isGreaterThanOrEqualTo(MILLISECONDS.toNanos(100));
269+
assertThat(stats.getMetric(TEST_METRIC_NAME_NANO_2 + "OnCpu").getSum()).isLessThan(MILLISECONDS.toNanos(100));
257270
}
258271
}

‎presto-hive-metastore/src/main/java/com/facebook/presto/hive/metastore/SemiTransactionalHiveMetastore.java

+2-2
Original file line numberDiff line numberDiff line change
@@ -202,7 +202,7 @@ public synchronized Optional<Table> getTable(MetastoreContext metastoreContext,
202202
checkReadable();
203203
Action<TableAndMore> tableAction = tableActions.get(hiveTableHandle.getSchemaTableName());
204204
if (tableAction == null) {
205-
return metastoreContext.getRuntimeStats().profileNanos(GET_TABLE_TIME_NANOS, () -> delegate.getTable(metastoreContext, hiveTableHandle));
205+
return metastoreContext.getRuntimeStats().recordWallTime(GET_TABLE_TIME_NANOS, () -> delegate.getTable(metastoreContext, hiveTableHandle));
206206
}
207207
switch (tableAction.getType()) {
208208
case ADD:
@@ -761,7 +761,7 @@ public synchronized Map<String, Optional<Partition>> getPartitionsByNames(Metast
761761
resultBuilder.put(partitionNameWithVersion.getPartitionName(), getPartitionFromPartitionAction(partitionAction));
762762
}
763763
}
764-
Map<String, Optional<Partition>> delegateResult = metastoreContext.getRuntimeStats().profileNanos(GET_PARTITIONS_BY_NAMES_TIME_NANOS, () -> delegate.getPartitionsByNames(metastoreContext, databaseName, tableName, partitionNamesToQuery.build()));
764+
Map<String, Optional<Partition>> delegateResult = metastoreContext.getRuntimeStats().recordWallTime(GET_PARTITIONS_BY_NAMES_TIME_NANOS, () -> delegate.getPartitionsByNames(metastoreContext, databaseName, tableName, partitionNamesToQuery.build()));
765765
resultBuilder.putAll(delegateResult);
766766

767767
cacheLastDataCommitTimes(delegateResult, databaseName, tableName);

‎presto-main/src/main/java/com/facebook/presto/execution/SqlQueryExecution.java

+21-7
Original file line numberDiff line numberDiff line change
@@ -87,10 +87,13 @@
8787
import static com.facebook.presto.SystemSessionProperties.isEagerPlanValidationEnabled;
8888
import static com.facebook.presto.SystemSessionProperties.isLogInvokedFunctionNamesEnabled;
8989
import static com.facebook.presto.SystemSessionProperties.isSpoolingOutputBufferEnabled;
90+
import static com.facebook.presto.common.RuntimeMetricName.ANALYZE_TIME_NANOS;
91+
import static com.facebook.presto.common.RuntimeMetricName.CREATE_SCHEDULER_TIME_NANOS;
9092
import static com.facebook.presto.common.RuntimeMetricName.FRAGMENT_PLAN_TIME_NANOS;
9193
import static com.facebook.presto.common.RuntimeMetricName.GET_CANONICAL_INFO_TIME_NANOS;
9294
import static com.facebook.presto.common.RuntimeMetricName.LOGICAL_PLANNER_TIME_NANOS;
9395
import static com.facebook.presto.common.RuntimeMetricName.OPTIMIZER_TIME_NANOS;
96+
import static com.facebook.presto.common.RuntimeMetricName.PLAN_AND_OPTIMIZE_TIME_NANOS;
9497
import static com.facebook.presto.execution.QueryStateMachine.pruneHistogramsFromStatsAndCosts;
9598
import static com.facebook.presto.execution.buffer.OutputBuffers.BROADCAST_PARTITION_ID;
9699
import static com.facebook.presto.execution.buffer.OutputBuffers.createInitialEmptyOutputBuffers;
@@ -207,7 +210,9 @@ private SqlQueryExecution(
207210
Thread.currentThread(),
208211
timeoutThreadExecutor,
209212
getQueryAnalyzerTimeout(getSession()))) {
210-
this.queryAnalysis = queryAnalyzer.analyze(analyzerContext, preparedQuery);
213+
this.queryAnalysis = getSession()
214+
.getRuntimeStats()
215+
.recordWallAndCpuTime(ANALYZE_TIME_NANOS, () -> queryAnalyzer.analyze(analyzerContext, preparedQuery));
211216
}
212217

213218
stateMachine.setUpdateType(queryAnalysis.getUpdateType());
@@ -482,7 +487,7 @@ public void start()
482487
metadata.beginQuery(getSession(), plan.getConnectors());
483488

484489
// plan distribution of query
485-
planDistribution(plan);
490+
getSession().getRuntimeStats().recordWallAndCpuTime(CREATE_SCHEDULER_TIME_NANOS, () -> createQueryScheduler(plan));
486491

487492
// transition to starting
488493
if (!stateMachine.transitionToStarting()) {
@@ -544,14 +549,23 @@ public void addFinalQueryInfoListener(StateChangeListener<QueryInfo> stateChange
544549
}
545550

546551
private PlanRoot createLogicalPlanAndOptimize()
552+
{
553+
return stateMachine.getSession()
554+
.getRuntimeStats()
555+
.recordWallAndCpuTime(
556+
PLAN_AND_OPTIMIZE_TIME_NANOS,
557+
this::doCreateLogicalPlanAndOptimize);
558+
}
559+
560+
private PlanRoot doCreateLogicalPlanAndOptimize()
547561
{
548562
try {
549563
// time analysis phase
550564
stateMachine.beginAnalysis();
551565

552566
PlanNode planNode = stateMachine.getSession()
553567
.getRuntimeStats()
554-
.profileNanos(
568+
.recordWallAndCpuTime(
555569
LOGICAL_PLANNER_TIME_NANOS,
556570
() -> queryAnalyzer.plan(this.analyzerContext, queryAnalysis));
557571

@@ -567,14 +581,14 @@ private PlanRoot createLogicalPlanAndOptimize()
567581
costCalculator,
568582
false);
569583

570-
Plan plan = getSession().getRuntimeStats().profileNanos(
584+
Plan plan = getSession().getRuntimeStats().recordWallAndCpuTime(
571585
OPTIMIZER_TIME_NANOS,
572586
() -> optimizer.validateAndOptimizePlan(planNode, OPTIMIZED_AND_VALIDATED));
573587

574588
queryPlan.set(plan);
575589
stateMachine.setPlanStatsAndCosts(plan.getStatsAndCosts());
576590
stateMachine.setPlanIdNodeMap(plan.getPlanIdNodeMap());
577-
List<CanonicalPlanWithInfo> canonicalPlanWithInfos = getSession().getRuntimeStats().profileNanos(
591+
List<CanonicalPlanWithInfo> canonicalPlanWithInfos = getSession().getRuntimeStats().recordWallAndCpuTime(
578592
GET_CANONICAL_INFO_TIME_NANOS,
579593
() -> getCanonicalInfo(getSession(), plan.getRoot(), planCanonicalInfoProvider));
580594
stateMachine.setPlanCanonicalInfo(canonicalPlanWithInfos);
@@ -590,7 +604,7 @@ private PlanRoot createLogicalPlanAndOptimize()
590604
// fragment the plan
591605
// the variableAllocator is finally passed to SqlQueryScheduler for runtime cost-based optimizations
592606
variableAllocator.set(new VariableAllocator(plan.getTypes().allVariables()));
593-
SubPlan fragmentedPlan = getSession().getRuntimeStats().profileNanos(
607+
SubPlan fragmentedPlan = getSession().getRuntimeStats().recordWallAndCpuTime(
594608
FRAGMENT_PLAN_TIME_NANOS,
595609
() -> planFragmenter.createSubPlans(stateMachine.getSession(), plan, false, idAllocator, variableAllocator.get(), stateMachine.getWarningCollector()));
596610

@@ -620,7 +634,7 @@ private PlanRoot runCreateLogicalPlanAsync()
620634
}
621635
}
622636

623-
private void planDistribution(PlanRoot plan)
637+
private void createQueryScheduler(PlanRoot plan)
624638
{
625639
CloseableSplitSourceProvider splitSourceProvider = new CloseableSplitSourceProvider(splitManager::getSplits);
626640

‎presto-main/src/main/java/com/facebook/presto/metadata/MetadataManager.java

+1-1
Original file line numberDiff line numberDiff line change
@@ -1051,7 +1051,7 @@ private MaterializedViewStatus getMaterializedViewStatus(Session session, Qualif
10511051
ConnectorId connectorId = materializedViewHandle.get().getConnectorId();
10521052
ConnectorMetadata metadata = getMetadata(session, connectorId);
10531053

1054-
return session.getRuntimeStats().profileNanos(
1054+
return session.getRuntimeStats().recordWallTime(
10551055
GET_MATERIALIZED_VIEW_STATUS_TIME_NANOS,
10561056
() -> metadata.getMaterializedViewStatus(session.toConnectorSession(connectorId), toSchemaTableName(materializedViewName), baseQueryDomain));
10571057
}

‎presto-main/src/main/java/com/facebook/presto/sql/analyzer/MetadataExtractor.java

+2-2
Original file line numberDiff line numberDiff line change
@@ -84,7 +84,7 @@ private void populateMetadataHandle(Session session, Statement statement, Metada
8484
}
8585

8686
metadataHandle.addViewDefinition(tableName, executor.get().submit(() -> {
87-
Optional<ViewDefinition> optionalView = session.getRuntimeStats().profileNanos(
87+
Optional<ViewDefinition> optionalView = session.getRuntimeStats().recordWallTime(
8888
GET_VIEW_TIME_NANOS,
8989
() -> metadataResolver.getView(tableName));
9090
if (optionalView.isPresent()) {
@@ -109,7 +109,7 @@ private void populateMetadataHandle(Session session, Statement statement, Metada
109109
}));
110110

111111
metadataHandle.addMaterializedViewDefinition(tableName, executor.get().submit(() -> {
112-
Optional<MaterializedViewDefinition> optionalMaterializedView = session.getRuntimeStats().profileNanos(
112+
Optional<MaterializedViewDefinition> optionalMaterializedView = session.getRuntimeStats().recordWallTime(
113113
GET_MATERIALIZED_VIEW_TIME_NANOS,
114114
() -> metadataResolver.getMaterializedView(tableName));
115115
if (optionalMaterializedView.isPresent()) {

‎presto-main/src/main/java/com/facebook/presto/sql/analyzer/QueryExplainer.java

+8-4
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,8 @@
4747
import java.util.Optional;
4848

4949
import static com.facebook.presto.SystemSessionProperties.isVerboseOptimizerInfoEnabled;
50+
import static com.facebook.presto.common.RuntimeMetricName.ANALYZE_TIME_NANOS;
51+
import static com.facebook.presto.common.RuntimeMetricName.FRAGMENT_PLAN_TIME_NANOS;
5052
import static com.facebook.presto.common.RuntimeMetricName.LOGICAL_PLANNER_TIME_NANOS;
5153
import static com.facebook.presto.common.RuntimeMetricName.OPTIMIZER_TIME_NANOS;
5254
import static com.facebook.presto.spi.StandardErrorCode.NOT_SUPPORTED;
@@ -200,7 +202,8 @@ public Plan getLogicalPlan(Session session, Statement statement, List<Expression
200202
public Plan getLogicalPlan(Session session, Statement statement, List<Expression> parameters, WarningCollector warningCollector, PlanNodeIdAllocator idAllocator)
201203
{
202204
// analyze statement
203-
Analysis analysis = analyze(session, statement, parameters, warningCollector);
205+
Analysis analysis = session.getRuntimeStats()
206+
.recordWallAndCpuTime(ANALYZE_TIME_NANOS, () -> analyze(session, statement, parameters, warningCollector));
204207

205208
final VariableAllocator planVariableAllocator = new VariableAllocator();
206209
LogicalPlanner logicalPlanner = new LogicalPlanner(
@@ -210,7 +213,7 @@ public Plan getLogicalPlan(Session session, Statement statement, List<Expression
210213
planVariableAllocator,
211214
sqlParser);
212215

213-
PlanNode planNode = session.getRuntimeStats().profileNanos(
216+
PlanNode planNode = session.getRuntimeStats().recordWallAndCpuTime(
214217
LOGICAL_PLANNER_TIME_NANOS,
215218
() -> logicalPlanner.plan(analysis));
216219

@@ -226,7 +229,7 @@ public Plan getLogicalPlan(Session session, Statement statement, List<Expression
226229
costCalculator,
227230
true);
228231

229-
return session.getRuntimeStats().profileNanos(
232+
return session.getRuntimeStats().recordWallAndCpuTime(
230233
OPTIMIZER_TIME_NANOS,
231234
() -> optimizer.validateAndOptimizePlan(planNode, OPTIMIZED_AND_VALIDATED));
232235
}
@@ -235,6 +238,7 @@ public SubPlan getDistributedPlan(Session session, Statement statement, List<Exp
235238
{
236239
PlanNodeIdAllocator idAllocator = new PlanNodeIdAllocator();
237240
Plan plan = getLogicalPlan(session, statement, parameters, warningCollector, idAllocator);
238-
return planFragmenter.createSubPlans(session, plan, false, idAllocator, warningCollector);
241+
return session.getRuntimeStats()
242+
.recordWallAndCpuTime(FRAGMENT_PLAN_TIME_NANOS, () -> planFragmenter.createSubPlans(session, plan, false, idAllocator, warningCollector));
239243
}
240244
}

‎presto-main/src/main/java/com/facebook/presto/testing/LocalQueryRunner.java

+2-2
Original file line numberDiff line numberDiff line change
@@ -1170,7 +1170,7 @@ public Plan createPlan(Session session, @Language("SQL") String sql, List<PlanOp
11701170
QueryAnalysis queryAnalysis = queryAnalyzer.analyze(analyzerContext, preparedQuery);
11711171
checkAccessPermissions(queryAnalysis.getAccessControlReferences());
11721172

1173-
PlanNode planNode = session.getRuntimeStats().profileNanos(
1173+
PlanNode planNode = session.getRuntimeStats().recordWallAndCpuTime(
11741174
LOGICAL_PLANNER_TIME_NANOS,
11751175
() -> queryAnalyzer.plan(analyzerContext, queryAnalysis));
11761176

@@ -1186,7 +1186,7 @@ public Plan createPlan(Session session, @Language("SQL") String sql, List<PlanOp
11861186
costCalculator,
11871187
preparedQuery.getWrappedStatement() instanceof Explain);
11881188

1189-
return session.getRuntimeStats().profileNanos(
1189+
return session.getRuntimeStats().recordWallAndCpuTime(
11901190
OPTIMIZER_TIME_NANOS,
11911191
() -> optimizer.validateAndOptimizePlan(planNode, stage));
11921192
}

‎presto-main/src/main/java/com/facebook/presto/util/MetadataUtils.java

+5-5
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,7 @@ public static Optional<ViewDefinition> getViewDefinition(Session session, Metada
6060
return metadataHandle.getViewDefinition(viewName);
6161
}
6262

63-
return session.getRuntimeStats().profileNanos(
63+
return session.getRuntimeStats().recordWallTime(
6464
GET_VIEW_TIME_NANOS,
6565
() -> metadataResolver.getView(viewName));
6666
}
@@ -71,14 +71,14 @@ public static Optional<MaterializedViewDefinition> getMaterializedViewDefinition
7171
return metadataHandle.getMaterializedViewDefinition(viewName);
7272
}
7373

74-
return session.getRuntimeStats().profileNanos(
74+
return session.getRuntimeStats().recordWallTime(
7575
GET_MATERIALIZED_VIEW_TIME_NANOS,
7676
() -> metadataResolver.getMaterializedView(viewName));
7777
}
7878

7979
public static TableColumnMetadata getTableColumnMetadata(Session session, MetadataResolver metadataResolver, QualifiedObjectName tableName)
8080
{
81-
Optional<TableHandle> tableHandle = session.getRuntimeStats().profileNanos(
81+
Optional<TableHandle> tableHandle = session.getRuntimeStats().recordWallTime(
8282
GET_TABLE_HANDLE_TIME_NANOS,
8383
() -> metadataResolver.getTableHandle(tableName));
8484

@@ -92,11 +92,11 @@ public static TableColumnMetadata getTableColumnMetadata(Session session, Metada
9292
throw new SemanticException(MISSING_TABLE, "Table %s does not exist", tableName);
9393
}
9494

95-
Map<String, ColumnHandle> columnHandles = session.getRuntimeStats().profileNanos(
95+
Map<String, ColumnHandle> columnHandles = session.getRuntimeStats().recordWallTime(
9696
GET_COLUMN_HANDLE_TIME_NANOS,
9797
() -> metadataResolver.getColumnHandles(tableHandle.get()));
9898

99-
List<ColumnMetadata> columnsMetadata = session.getRuntimeStats().profileNanos(
99+
List<ColumnMetadata> columnsMetadata = session.getRuntimeStats().recordWallTime(
100100
GET_COLUMN_METADATA_TIME_NANOS,
101101
() -> metadataResolver.getColumns(tableHandle.get()));
102102

0 commit comments

Comments
 (0)