Skip to content

Commit

Permalink
Produce all query timings for query regardless of state
Browse files Browse the repository at this point in the history 
Instead of delaying production of state timings until each state is complete,
produce final duration for completed states, partial duration for current state,
and zero duration for future states.

This simplifies the code, and always gives up to date data for the current
state. This does not have a large impact as these stats are use for informational
purposes and for final events (which would have final data).
  • Loading branch information
@dain
dain committed Dec 18, 2018
1 parent 90dae1b commit b9d8db7
Show file tree
Hide file tree
Showing 7 changed files with 39 additions and 78 deletions.
6 changes: 3 additions & 3 deletions presto-main/src/main/java/com/facebook/presto/event/QueryMonitor.java
View file
Expand Up @@ -210,8 +210,8 @@ private QueryStatistics createQueryStatistics(QueryInfo queryInfo)
ofMillis(queryStats.getTotalCpuTime().toMillis()),
ofMillis(queryStats.getTotalScheduledTime().toMillis()),
ofMillis(queryStats.getQueuedTime().toMillis()),
Optional.ofNullable(queryStats.getAnalysisTime()).map(duration -> ofMillis(duration.toMillis())),
Optional.ofNullable(queryStats.getDistributedPlanningTime()).map(duration -> ofMillis(duration.toMillis())),
Optional.of(ofMillis(queryStats.getAnalysisTime().toMillis())),
Optional.of(ofMillis(queryStats.getDistributedPlanningTime().toMillis())),
queryStats.getPeakUserMemoryReservation().toBytes(),
queryStats.getPeakTotalMemoryReservation().toBytes(),
queryStats.getPeakTaskTotalMemory().toBytes(),
Expand Down Expand Up @@ -363,7 +363,7 @@ private static void logQueryTimeline(QueryInfo queryInfo)
}

// planning duration -- start to end of planning
long planning = max(queryStats.getTotalPlanningTime() == null ? 0 : queryStats.getTotalPlanningTime().toMillis(), 0);
long planning = queryStats.getTotalPlanningTime().toMillis();

List<StageInfo> stages = StageInfo.getAllStages(queryInfo.getOutputStage());
// long lastSchedulingCompletion = 0;
Expand Down
10 changes: 5 additions & 5 deletions presto-main/src/main/java/com/facebook/presto/execution/QueryStateMachine.java
View file
Expand Up @@ -471,12 +471,12 @@ private QueryStats getQueryStats(Optional<StageInfo> rootStage)

queryStateTimer.getElapsedTime(),
queryStateTimer.getQueuedTime(),
queryStateTimer.getResourceWaitingTime().orElse(null),
queryStateTimer.getResourceWaitingTime(),
queryStateTimer.getExecutionTime(),
queryStateTimer.getAnalysisTime().orElse(null),
queryStateTimer.getDistributedPlanningTime().orElse(null),
queryStateTimer.getPlanningTime().orElse(null),
queryStateTimer.getFinishingTime().orElse(null),
queryStateTimer.getAnalysisTime(),
queryStateTimer.getDistributedPlanningTime(),
queryStateTimer.getPlanningTime(),
queryStateTimer.getFinishingTime(),

totalTasks,
runningTasks,
Expand Down
20 changes: 10 additions & 10 deletions presto-main/src/main/java/com/facebook/presto/execution/QueryStateTimer.java
View file
Expand Up @@ -192,19 +192,19 @@ public Duration getQueuedTime()
return getElapsedTime();
}

public Optional<Duration> getResourceWaitingTime()
public Duration getResourceWaitingTime()
{
return Optional.ofNullable(resourceWaitingTime.get());
return getDuration(resourceWaitingTime, beginResourceWaitingNanos);
}

public Optional<Duration> getPlanningTime()
public Duration getPlanningTime()
{
return Optional.ofNullable(planningTime.get());
return getDuration(planningTime, beginPlanningNanos);
}

public Optional<Duration> getFinishingTime()
public Duration getFinishingTime()
{
return Optional.ofNullable(finishingTime.get());
return getDuration(finishingTime, beginFinishingNanos);
}

public Duration getExecutionTime()
Expand All @@ -217,14 +217,14 @@ public Optional<DateTime> getEndTime()
return toDateTime(endNanos);
}

public Optional<Duration> getAnalysisTime()
public Duration getAnalysisTime()
{
return Optional.ofNullable(analysisTime.get());
return getDuration(analysisTime, beginAnalysisNanos);
}

public Optional<Duration> getDistributedPlanningTime()
public Duration getDistributedPlanningTime()
{
return Optional.ofNullable(distributedPlanningTime.get());
return getDuration(distributedPlanningTime, beginDistributedPlanningNanos);
}

public DateTime getLastHeartbeat()
Expand Down
22 changes: 9 additions & 13 deletions presto-main/src/main/java/com/facebook/presto/execution/QueryStats.java
View file
Expand Up @@ -154,14 +154,14 @@ public QueryStats(
this.lastHeartbeat = requireNonNull(lastHeartbeat, "lastHeartbeat is null");
this.endTime = endTime;

this.elapsedTime = elapsedTime;
this.queuedTime = queuedTime;
this.resourceWaitingTime = resourceWaitingTime;
this.elapsedTime = requireNonNull(elapsedTime, "elapsedTime is null");
this.queuedTime = requireNonNull(queuedTime, "queuedTime is null");
this.resourceWaitingTime = requireNonNull(resourceWaitingTime, "resourceWaitingTime is null");
this.executionTime = requireNonNull(executionTime, "executionTime is null");
this.analysisTime = analysisTime;
this.distributedPlanningTime = distributedPlanningTime;
this.totalPlanningTime = totalPlanningTime;
this.finishingTime = finishingTime;
this.analysisTime = requireNonNull(analysisTime, "analysisTime is null");
this.distributedPlanningTime = requireNonNull(distributedPlanningTime, "distributedPlanningTime is null");
this.totalPlanningTime = requireNonNull(totalPlanningTime, "totalPlanningTime is null");
this.finishingTime = requireNonNull(finishingTime, "finishingTime is null");

checkArgument(totalTasks >= 0, "totalTasks is negative");
this.totalTasks = totalTasks;
Expand Down Expand Up @@ -225,8 +225,8 @@ public static QueryStats immediateFailureQueryStats()
new Duration(0, MILLISECONDS),
new Duration(0, MILLISECONDS),
new Duration(0, MILLISECONDS),
null,
null,
new Duration(0, MILLISECONDS),
new Duration(0, MILLISECONDS),
new Duration(0, MILLISECONDS),
new Duration(0, MILLISECONDS),
0,
Expand Down Expand Up @@ -300,10 +300,6 @@ public Duration getResourceWaitingTime()
@JsonProperty
public Duration getQueuedTime()
{
if (queuedTime == null) {
// counter-intuitively, this means that the query is still queued
return elapsedTime;
}
return queuedTime;
}

Expand Down
6 changes: 3 additions & 3 deletions presto-main/src/main/java/com/facebook/presto/server/BasicQueryStats.java
View file
Expand Up @@ -90,9 +90,9 @@ public BasicQueryStats(
this.createTime = createTime;
this.endTime = endTime;

this.queuedTime = queuedTime;
this.elapsedTime = elapsedTime;
this.executionTime = executionTime;
this.queuedTime = requireNonNull(queuedTime, "queuedTime is null");
this.elapsedTime = requireNonNull(elapsedTime, "elapsedTime is null");
this.executionTime = requireNonNull(executionTime, "executionTime is null");

checkArgument(totalDrivers >= 0, "totalDrivers is negative");
this.totalDrivers = totalDrivers;
Expand Down
50 changes: 6 additions & 44 deletions presto-main/src/test/java/com/facebook/presto/execution/TestQueryStateMachine.java
View file
Expand Up @@ -166,16 +166,10 @@ private void assertAllTimeSpentInQueueing(QueryState expectedState, Consumer<Que

QueryStats queryStats = stateMachine.getQueryInfo(Optional.empty()).getQueryStats();
assertEquals(queryStats.getQueuedTime(), new Duration(7, MILLISECONDS));
if (queryStats.getResourceWaitingTime() != null) {
assertEquals(queryStats.getResourceWaitingTime(), new Duration(0, MILLISECONDS));
}
if (queryStats.getTotalPlanningTime() != null) {
assertEquals(queryStats.getTotalPlanningTime(), new Duration(0, MILLISECONDS));
}
assertEquals(queryStats.getResourceWaitingTime(), new Duration(0, MILLISECONDS));
assertEquals(queryStats.getTotalPlanningTime(), new Duration(0, MILLISECONDS));
assertEquals(queryStats.getExecutionTime(), new Duration(0, MILLISECONDS));
if (queryStats.getFinishingTime() != null) {
assertEquals(queryStats.getFinishingTime(), new Duration(0, MILLISECONDS));
}
assertEquals(queryStats.getFinishingTime(), new Duration(0, MILLISECONDS));
}

@Test
Expand Down Expand Up @@ -409,42 +403,10 @@ private static void assertState(QueryStateMachine stateMachine, QueryState expec
QueryStats queryStats = queryInfo.getQueryStats();
assertNotNull(queryStats.getElapsedTime());
assertNotNull(queryStats.getQueuedTime());
assertNotNull(queryStats.getResourceWaitingTime());
assertNotNull(queryStats.getExecutionTime());
if (queryInfo.getState() == QUEUED) {
assertNull(queryStats.getResourceWaitingTime());
assertNull(queryStats.getTotalPlanningTime());
assertNull(queryStats.getFinishingTime());
}
else if (queryInfo.getState() == WAITING_FOR_RESOURCES) {
assertNull(queryStats.getResourceWaitingTime());
assertNull(queryStats.getTotalPlanningTime());
assertNull(queryStats.getFinishingTime());
}
else if (queryInfo.getState() == PLANNING) {
assertNotNull(queryStats.getResourceWaitingTime());
assertNull(queryStats.getTotalPlanningTime());
assertNull(queryStats.getFinishingTime());
}
else if (queryInfo.getState() == STARTING) {
assertNotNull(queryStats.getResourceWaitingTime());
assertNotNull(queryStats.getTotalPlanningTime());
assertNull(queryStats.getFinishingTime());
}
else if (queryInfo.getState() == RUNNING) {
assertNotNull(queryStats.getResourceWaitingTime());
assertNotNull(queryStats.getTotalPlanningTime());
assertNull(queryStats.getFinishingTime());
}
else if (queryInfo.getState() == FINISHING) {
assertNotNull(queryStats.getResourceWaitingTime());
assertNotNull(queryStats.getTotalPlanningTime());
assertNull(queryStats.getFinishingTime());
}
else {
assertNotNull(queryStats.getResourceWaitingTime());
assertNotNull(queryStats.getTotalPlanningTime());
assertNotNull(queryStats.getFinishingTime());
}
assertNotNull(queryStats.getTotalPlanningTime());
assertNotNull(queryStats.getFinishingTime());

assertNotNull(queryStats.getCreateTime());
if (queryInfo.getState() == QUEUED || queryInfo.getState() == WAITING_FOR_RESOURCES) {
Expand Down
3 changes: 3 additions & 0 deletions ...s/src/test/resources/com/facebook/presto/tests/querystats/single_query_info_response.json
View file
Expand Up @@ -27,10 +27,13 @@
"lastHeartbeat": "2015-05-06T09:42:00.010Z",
"endTime": "2015-05-05T16:01:17.125Z",
"elapsedTime": "134.00ms",
"resourceWaitingTime": "11.00ms",
"queuedTime": "2.11ms",
"executionTime": "13.00ms",
"analysisTime": "7.47ms",
"distributedPlanningTime": "311.77us",
"totalPlanningTime": "9.99ms",
"finishingTime": "17.00ms",
"totalTasks": 1,
"runningTasks": 0,
"completedTasks": 1,
Expand Down

0 comments on commit b9d8db7

Please sign in to comment.