io.prestosql.event.QueryMonitor Maven / Gradle / Ivy
/*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package io.prestosql.event;
import com.google.common.collect.ImmutableList;
import com.google.common.collect.ImmutableMap;
import com.google.common.collect.ImmutableMultimap;
import com.google.common.collect.Multimap;
import com.google.common.collect.Multimaps;
import io.airlift.json.JsonCodec;
import io.airlift.log.Logger;
import io.airlift.node.NodeInfo;
import io.airlift.stats.Distribution;
import io.airlift.stats.Distribution.DistributionSnapshot;
import io.airlift.units.DataSize;
import io.prestosql.SessionRepresentation;
import io.prestosql.client.NodeVersion;
import io.prestosql.connector.CatalogName;
import io.prestosql.cost.StatsAndCosts;
import io.prestosql.eventlistener.EventListenerManager;
import io.prestosql.execution.Column;
import io.prestosql.execution.ExecutionFailureInfo;
import io.prestosql.execution.Input;
import io.prestosql.execution.QueryInfo;
import io.prestosql.execution.QueryStats;
import io.prestosql.execution.StageInfo;
import io.prestosql.execution.TaskInfo;
import io.prestosql.execution.TaskState;
import io.prestosql.metadata.Metadata;
import io.prestosql.metadata.SessionPropertyManager;
import io.prestosql.operator.OperatorStats;
import io.prestosql.operator.TableFinishInfo;
import io.prestosql.operator.TaskStats;
import io.prestosql.server.BasicQueryInfo;
import io.prestosql.spi.QueryId;
import io.prestosql.spi.eventlistener.QueryCompletedEvent;
import io.prestosql.spi.eventlistener.QueryContext;
import io.prestosql.spi.eventlistener.QueryCreatedEvent;
import io.prestosql.spi.eventlistener.QueryFailureInfo;
import io.prestosql.spi.eventlistener.QueryIOMetadata;
import io.prestosql.spi.eventlistener.QueryInputMetadata;
import io.prestosql.spi.eventlistener.QueryMetadata;
import io.prestosql.spi.eventlistener.QueryOutputMetadata;
import io.prestosql.spi.eventlistener.QueryStatistics;
import io.prestosql.spi.eventlistener.StageCpuDistribution;
import io.prestosql.spi.resourcegroups.QueryType;
import io.prestosql.spi.resourcegroups.ResourceGroupId;
import io.prestosql.sql.planner.PlanFragment;
import io.prestosql.sql.planner.plan.PlanFragmentId;
import io.prestosql.sql.planner.plan.PlanNode;
import io.prestosql.sql.planner.plan.PlanNodeId;
import io.prestosql.sql.planner.plan.PlanVisitor;
import io.prestosql.sql.planner.planprinter.ValuePrinter;
import io.prestosql.transaction.TransactionId;
import org.joda.time.DateTime;
import javax.inject.Inject;
import java.util.Collection;
import java.util.LinkedHashMap;
import java.util.List;
import java.util.Map;
import java.util.Objects;
import java.util.Optional;
import java.util.OptionalLong;
import java.util.stream.Collectors;
import static io.prestosql.execution.QueryState.QUEUED;
import static io.prestosql.execution.StageInfo.getAllStages;
import static io.prestosql.sql.planner.planprinter.PlanPrinter.textDistributedPlan;
import static java.lang.Math.max;
import static java.lang.Math.toIntExact;
import static java.time.Duration.ofMillis;
import static java.time.Instant.ofEpochMilli;
import static java.util.Objects.requireNonNull;
public class QueryMonitor
{
private static final Logger log = Logger.get(QueryMonitor.class);
private final JsonCodec stageInfoCodec;
private final JsonCodec operatorStatsCodec;
private final JsonCodec executionFailureInfoCodec;
private final JsonCodec statsAndCostsCodec;
private final EventListenerManager eventListenerManager;
private final String serverVersion;
private final String serverAddress;
private final String environment;
private final SessionPropertyManager sessionPropertyManager;
private final Metadata metadata;
private final int maxJsonLimit;
@Inject
public QueryMonitor(
JsonCodec stageInfoCodec,
JsonCodec operatorStatsCodec,
JsonCodec executionFailureInfoCodec,
JsonCodec statsAndCostsCodec,
EventListenerManager eventListenerManager,
NodeInfo nodeInfo,
NodeVersion nodeVersion,
SessionPropertyManager sessionPropertyManager,
Metadata metadata,
QueryMonitorConfig config)
{
this.eventListenerManager = requireNonNull(eventListenerManager, "eventListenerManager is null");
this.stageInfoCodec = requireNonNull(stageInfoCodec, "stageInfoCodec is null");
this.operatorStatsCodec = requireNonNull(operatorStatsCodec, "operatorStatsCodec is null");
this.statsAndCostsCodec = requireNonNull(statsAndCostsCodec, "statsAndCostsCodec is null");
this.executionFailureInfoCodec = requireNonNull(executionFailureInfoCodec, "executionFailureInfoCodec is null");
this.serverVersion = requireNonNull(nodeVersion, "nodeVersion is null").toString();
this.serverAddress = requireNonNull(nodeInfo, "nodeInfo is null").getExternalAddress();
this.environment = requireNonNull(nodeInfo, "nodeInfo is null").getEnvironment();
this.sessionPropertyManager = requireNonNull(sessionPropertyManager, "sessionPropertyManager is null");
this.metadata = requireNonNull(metadata, "metadata is null");
this.maxJsonLimit = toIntExact(requireNonNull(config, "config is null").getMaxOutputStageJsonSize().toBytes());
}
public void queryCreatedEvent(BasicQueryInfo queryInfo)
{
eventListenerManager.queryCreated(
new QueryCreatedEvent(
queryInfo.getQueryStats().getCreateTime().toDate().toInstant(),
createQueryContext(queryInfo.getSession(), queryInfo.getResourceGroupId(), queryInfo.getQueryType()),
new QueryMetadata(
queryInfo.getQueryId().toString(),
queryInfo.getSession().getTransactionId().map(TransactionId::toString),
queryInfo.getQuery(),
queryInfo.getUpdateType(),
queryInfo.getPreparedQuery(),
QUEUED.toString(),
ImmutableList.of(),
ImmutableList.of(),
queryInfo.getSelf(),
Optional.empty(),
Optional.empty())));
}
public void queryImmediateFailureEvent(BasicQueryInfo queryInfo, ExecutionFailureInfo failure)
{
eventListenerManager.queryCompleted(new QueryCompletedEvent(
new QueryMetadata(
queryInfo.getQueryId().toString(),
queryInfo.getSession().getTransactionId().map(TransactionId::toString),
queryInfo.getQuery(),
queryInfo.getUpdateType(),
queryInfo.getPreparedQuery(),
queryInfo.getState().toString(),
ImmutableList.of(),
ImmutableList.of(),
queryInfo.getSelf(),
Optional.empty(),
Optional.empty()),
new QueryStatistics(
ofMillis(0),
ofMillis(0),
ofMillis(queryInfo.getQueryStats().getQueuedTime().toMillis()),
Optional.empty(),
Optional.empty(),
Optional.empty(),
Optional.empty(),
Optional.empty(),
0,
0,
0,
0,
0,
0,
0,
0,
0,
0,
0,
0,
0,
0,
0,
ImmutableList.of(),
0,
true,
ImmutableList.of(),
ImmutableList.of(),
Optional.empty()),
createQueryContext(queryInfo.getSession(), queryInfo.getResourceGroupId(), queryInfo.getQueryType()),
new QueryIOMetadata(ImmutableList.of(), Optional.empty()),
createQueryFailureInfo(failure, Optional.empty()),
ImmutableList.of(),
ofEpochMilli(queryInfo.getQueryStats().getCreateTime().getMillis()),
ofEpochMilli(queryInfo.getQueryStats().getEndTime().getMillis()),
ofEpochMilli(queryInfo.getQueryStats().getEndTime().getMillis())));
logQueryTimeline(queryInfo);
}
public void queryCompletedEvent(QueryInfo queryInfo)
{
QueryStats queryStats = queryInfo.getQueryStats();
eventListenerManager.queryCompleted(
new QueryCompletedEvent(
createQueryMetadata(queryInfo),
createQueryStatistics(queryInfo),
createQueryContext(queryInfo.getSession(), queryInfo.getResourceGroupId(), queryInfo.getQueryType()),
getQueryIOMetadata(queryInfo),
createQueryFailureInfo(queryInfo.getFailureInfo(), queryInfo.getOutputStage()),
queryInfo.getWarnings(),
ofEpochMilli(queryStats.getCreateTime().getMillis()),
ofEpochMilli(queryStats.getExecutionStartTime().getMillis()),
ofEpochMilli(queryStats.getEndTime() != null ? queryStats.getEndTime().getMillis() : 0)));
logQueryTimeline(queryInfo);
}
private QueryMetadata createQueryMetadata(QueryInfo queryInfo)
{
return new QueryMetadata(
queryInfo.getQueryId().toString(),
queryInfo.getSession().getTransactionId().map(TransactionId::toString),
queryInfo.getQuery(),
Optional.ofNullable(queryInfo.getUpdateType()),
queryInfo.getPreparedQuery(),
queryInfo.getState().toString(),
queryInfo.getReferencedTables(),
queryInfo.getRoutines(),
queryInfo.getSelf(),
createTextQueryPlan(queryInfo),
queryInfo.getOutputStage().flatMap(stage -> stageInfoCodec.toJsonWithLengthLimit(stage, maxJsonLimit)));
}
private QueryStatistics createQueryStatistics(QueryInfo queryInfo)
{
ImmutableList.Builder operatorSummaries = ImmutableList.builder();
for (OperatorStats summary : queryInfo.getQueryStats().getOperatorSummaries()) {
operatorSummaries.add(operatorStatsCodec.toJson(summary));
}
Optional planNodeStatsAndCosts = queryInfo.getOutputStage().map(StatsAndCosts::create);
Optional serializedPlanNodeStatsAndCosts = planNodeStatsAndCosts.map(statsAndCostsCodec::toJson);
QueryStats queryStats = queryInfo.getQueryStats();
return new QueryStatistics(
ofMillis(queryStats.getTotalCpuTime().toMillis()),
ofMillis(queryStats.getElapsedTime().toMillis()),
ofMillis(queryStats.getQueuedTime().toMillis()),
Optional.of(ofMillis(queryStats.getTotalScheduledTime().toMillis())),
Optional.of(ofMillis(queryStats.getResourceWaitingTime().toMillis())),
Optional.of(ofMillis(queryStats.getAnalysisTime().toMillis())),
Optional.of(ofMillis(queryStats.getPlanningTime().toMillis())),
Optional.of(ofMillis(queryStats.getExecutionTime().toMillis())),
queryStats.getPeakUserMemoryReservation().toBytes(),
queryStats.getPeakNonRevocableMemoryReservation().toBytes(),
queryStats.getPeakTaskUserMemory().toBytes(),
queryStats.getPeakTaskTotalMemory().toBytes(),
queryStats.getPhysicalInputDataSize().toBytes(),
queryStats.getPhysicalInputPositions(),
queryStats.getInternalNetworkInputDataSize().toBytes(),
queryStats.getInternalNetworkInputPositions(),
queryStats.getRawInputDataSize().toBytes(),
queryStats.getRawInputPositions(),
queryStats.getOutputDataSize().toBytes(),
queryStats.getOutputPositions(),
queryStats.getLogicalWrittenDataSize().toBytes(),
queryStats.getWrittenPositions(),
queryStats.getCumulativeUserMemory(),
queryStats.getStageGcStatistics(),
queryStats.getCompletedDrivers(),
queryInfo.isCompleteInfo(),
getCpuDistributions(queryInfo),
operatorSummaries.build(),
serializedPlanNodeStatsAndCosts);
}
private QueryContext createQueryContext(SessionRepresentation session, Optional resourceGroup, Optional queryType)
{
return new QueryContext(
session.getUser(),
session.getPrincipal(),
session.getGroups(),
session.getTraceToken(),
session.getRemoteUserAddress(),
session.getUserAgent(),
session.getClientInfo(),
session.getClientTags(),
session.getClientCapabilities(),
session.getSource(),
session.getCatalog(),
session.getSchema(),
resourceGroup,
mergeSessionAndCatalogProperties(session),
session.getResourceEstimates(),
serverAddress,
serverVersion,
environment,
queryType);
}
private Optional createTextQueryPlan(QueryInfo queryInfo)
{
try {
if (queryInfo.getOutputStage().isPresent()) {
return Optional.of(textDistributedPlan(
queryInfo.getOutputStage().get(),
new ValuePrinter(metadata, queryInfo.getSession().toSession(sessionPropertyManager)),
false));
}
}
catch (Exception e) {
// Sometimes it is expected to fail. For example if generated plan is too long.
// Don't fail to create event if the plan cannot be created.
log.warn(e, "Error creating explain plan for query %s", queryInfo.getQueryId());
}
return Optional.empty();
}
private static QueryIOMetadata getQueryIOMetadata(QueryInfo queryInfo)
{
Multimap planNodeStats = extractPlanNodeStats(queryInfo);
ImmutableList.Builder inputs = ImmutableList.builder();
for (Input input : queryInfo.getInputs()) {
// Note: input table can be mapped to multiple operators
Collection inputTableOperatorStats = planNodeStats.get(new FragmentNode(input.getFragmentId(), input.getPlanNodeId()));
OptionalLong physicalInputBytes = OptionalLong.empty();
OptionalLong physicalInputPositions = OptionalLong.empty();
if (!inputTableOperatorStats.isEmpty()) {
physicalInputBytes = OptionalLong.of(inputTableOperatorStats.stream()
.map(OperatorStats::getPhysicalInputDataSize)
.mapToLong(DataSize::toBytes)
.sum());
physicalInputPositions = OptionalLong.of(inputTableOperatorStats.stream()
.mapToLong(OperatorStats::getPhysicalInputPositions)
.sum());
}
inputs.add(new QueryInputMetadata(
input.getCatalogName(),
input.getSchema(),
input.getTable(),
input.getColumns().stream()
.map(Column::getName).collect(Collectors.toList()),
input.getConnectorInfo(),
physicalInputBytes,
physicalInputPositions));
}
Optional output = Optional.empty();
if (queryInfo.getOutput().isPresent()) {
Optional tableFinishInfo = queryInfo.getQueryStats().getOperatorSummaries().stream()
.map(OperatorStats::getInfo)
.filter(TableFinishInfo.class::isInstance)
.map(TableFinishInfo.class::cast)
.findFirst();
output = Optional.of(
new QueryOutputMetadata(
queryInfo.getOutput().get().getCatalogName(),
queryInfo.getOutput().get().getSchema(),
queryInfo.getOutput().get().getTable(),
tableFinishInfo.map(TableFinishInfo::getConnectorOutputMetadata),
tableFinishInfo.map(TableFinishInfo::isJsonLengthLimitExceeded)));
}
return new QueryIOMetadata(inputs.build(), output);
}
private static Multimap extractPlanNodeStats(QueryInfo queryInfo)
{
// Note: A plan may map a table scan to multiple operators.
ImmutableMultimap.Builder planNodeStats = ImmutableMultimap.builder();
getAllStages(queryInfo.getOutputStage())
.forEach(stageInfo -> extractPlanNodeStats(stageInfo, planNodeStats));
return planNodeStats.build();
}
private static void extractPlanNodeStats(StageInfo stageInfo, ImmutableMultimap.Builder planNodeStats)
{
PlanFragment fragment = stageInfo.getPlan();
if (fragment == null) {
return;
}
// Note: a plan node may be mapped to multiple operators
Map> allOperatorStats = Multimaps.index(stageInfo.getStageStats().getOperatorSummaries(), OperatorStats::getPlanNodeId).asMap();
// Sometimes a plan node is merged with other nodes into a single operator, and in that case,
// use the stats of the nearest parent node with stats.
fragment.getRoot().accept(
new PlanVisitor>()
{
@Override
protected Void visitPlan(PlanNode node, Collection parentStats)
{
Collection operatorStats = allOperatorStats.getOrDefault(node.getId(), parentStats);
planNodeStats.putAll(new FragmentNode(fragment.getId(), node.getId()), operatorStats);
for (PlanNode child : node.getSources()) {
child.accept(this, operatorStats);
}
return null;
}
},
ImmutableList.of());
}
private Optional createQueryFailureInfo(ExecutionFailureInfo failureInfo, Optional outputStage)
{
if (failureInfo == null) {
return Optional.empty();
}
Optional failedTask = outputStage.flatMap(QueryMonitor::findFailedTask);
return Optional.of(new QueryFailureInfo(
failureInfo.getErrorCode(),
Optional.ofNullable(failureInfo.getType()),
Optional.ofNullable(failureInfo.getMessage()),
failedTask.map(task -> task.getTaskStatus().getTaskId().toString()),
failedTask.map(task -> task.getTaskStatus().getSelf().getHost()),
executionFailureInfoCodec.toJson(failureInfo)));
}
private static Optional findFailedTask(StageInfo stageInfo)
{
for (StageInfo subStage : stageInfo.getSubStages()) {
Optional task = findFailedTask(subStage);
if (task.isPresent()) {
return task;
}
}
return stageInfo.getTasks().stream()
.filter(taskInfo -> taskInfo.getTaskStatus().getState() == TaskState.FAILED)
.findFirst();
}
private static Map mergeSessionAndCatalogProperties(SessionRepresentation session)
{
Map mergedProperties = new LinkedHashMap<>(session.getSystemProperties());
// Either processed or unprocessed catalog properties, but not both. Instead of trying to enforces this while
// firing events, allow both to be set and if there is a duplicate favor the processed properties.
for (Map.Entry> catalogEntry : session.getUnprocessedCatalogProperties().entrySet()) {
for (Map.Entry entry : catalogEntry.getValue().entrySet()) {
mergedProperties.put(catalogEntry.getKey() + "." + entry.getKey(), entry.getValue());
}
}
for (Map.Entry> catalogEntry : session.getCatalogProperties().entrySet()) {
for (Map.Entry entry : catalogEntry.getValue().entrySet()) {
mergedProperties.put(catalogEntry.getKey().getCatalogName() + "." + entry.getKey(), entry.getValue());
}
}
return ImmutableMap.copyOf(mergedProperties);
}
private static void logQueryTimeline(QueryInfo queryInfo)
{
try {
QueryStats queryStats = queryInfo.getQueryStats();
DateTime queryStartTime = queryStats.getCreateTime();
DateTime queryEndTime = queryStats.getEndTime();
// query didn't finish cleanly
if (queryStartTime == null || queryEndTime == null) {
return;
}
// planning duration -- start to end of planning
long planning = queryStats.getPlanningTime().toMillis();
// Time spent waiting for required no. of worker nodes to be present
long waiting = queryStats.getResourceWaitingTime().toMillis();
List stages = getAllStages(queryInfo.getOutputStage());
// long lastSchedulingCompletion = 0;
long firstTaskStartTime = queryEndTime.getMillis();
long lastTaskStartTime = queryStartTime.getMillis() + planning;
long lastTaskEndTime = queryStartTime.getMillis() + planning;
for (StageInfo stage : stages) {
// only consider leaf stages
if (!stage.getSubStages().isEmpty()) {
continue;
}
for (TaskInfo taskInfo : stage.getTasks()) {
TaskStats taskStats = taskInfo.getStats();
DateTime firstStartTime = taskStats.getFirstStartTime();
if (firstStartTime != null) {
firstTaskStartTime = Math.min(firstStartTime.getMillis(), firstTaskStartTime);
}
DateTime lastStartTime = taskStats.getLastStartTime();
if (lastStartTime != null) {
lastTaskStartTime = max(lastStartTime.getMillis(), lastTaskStartTime);
}
DateTime endTime = taskStats.getEndTime();
if (endTime != null) {
lastTaskEndTime = max(endTime.getMillis(), lastTaskEndTime);
}
}
}
long elapsed = max(queryEndTime.getMillis() - queryStartTime.getMillis(), 0);
long scheduling = max(firstTaskStartTime - queryStartTime.getMillis() - planning, 0);
long running = max(lastTaskEndTime - firstTaskStartTime, 0);
long finishing = max(queryEndTime.getMillis() - lastTaskEndTime, 0);
logQueryTimeline(
queryInfo.getQueryId(),
queryInfo.getSession().getTransactionId().map(TransactionId::toString).orElse(""),
elapsed,
planning,
waiting,
scheduling,
running,
finishing,
queryStartTime,
queryEndTime);
}
catch (Exception e) {
log.error(e, "Error logging query timeline");
}
}
private static void logQueryTimeline(BasicQueryInfo queryInfo)
{
DateTime queryStartTime = queryInfo.getQueryStats().getCreateTime();
DateTime queryEndTime = queryInfo.getQueryStats().getEndTime();
// query didn't finish cleanly
if (queryStartTime == null || queryEndTime == null) {
return;
}
long elapsed = max(queryEndTime.getMillis() - queryStartTime.getMillis(), 0);
logQueryTimeline(
queryInfo.getQueryId(),
queryInfo.getSession().getTransactionId().map(TransactionId::toString).orElse(""),
elapsed,
elapsed,
0,
0,
0,
0,
queryStartTime,
queryEndTime);
}
private static void logQueryTimeline(
QueryId queryId,
String transactionId,
long elapsedMillis,
long planningMillis,
long waitingMillis,
long schedulingMillis,
long runningMillis,
long finishingMillis,
DateTime queryStartTime,
DateTime queryEndTime)
{
log.info("TIMELINE: Query %s :: Transaction:[%s] :: elapsed %sms :: planning %sms :: waiting %sms :: scheduling %sms :: running %sms :: finishing %sms :: begin %s :: end %s",
queryId,
transactionId,
elapsedMillis,
planningMillis,
waitingMillis,
schedulingMillis,
runningMillis,
finishingMillis,
queryStartTime,
queryEndTime);
}
private static List getCpuDistributions(QueryInfo queryInfo)
{
if (queryInfo.getOutputStage().isEmpty()) {
return ImmutableList.of();
}
ImmutableList.Builder builder = ImmutableList.builder();
populateDistribution(queryInfo.getOutputStage().get(), builder);
return builder.build();
}
private static void populateDistribution(StageInfo stageInfo, ImmutableList.Builder distributions)
{
distributions.add(computeCpuDistribution(stageInfo));
for (StageInfo subStage : stageInfo.getSubStages()) {
populateDistribution(subStage, distributions);
}
}
private static StageCpuDistribution computeCpuDistribution(StageInfo stageInfo)
{
Distribution cpuDistribution = new Distribution();
for (TaskInfo taskInfo : stageInfo.getTasks()) {
cpuDistribution.add(taskInfo.getStats().getTotalCpuTime().toMillis());
}
DistributionSnapshot snapshot = cpuDistribution.snapshot();
return new StageCpuDistribution(
stageInfo.getStageId().getId(),
stageInfo.getTasks().size(),
(long) snapshot.getP25(),
(long) snapshot.getP50(),
(long) snapshot.getP75(),
(long) snapshot.getP90(),
(long) snapshot.getP95(),
(long) snapshot.getP99(),
(long) snapshot.getMin(),
(long) snapshot.getMax(),
(long) snapshot.getTotal(),
snapshot.getTotal() / snapshot.getCount());
}
private static class FragmentNode
{
private final PlanFragmentId fragmentId;
private final PlanNodeId nodeId;
public FragmentNode(PlanFragmentId fragmentId, PlanNodeId nodeId)
{
this.fragmentId = requireNonNull(fragmentId, "fragmentId is null");
this.nodeId = requireNonNull(nodeId, "nodeId is null");
}
@Override
public boolean equals(Object o)
{
if (this == o) {
return true;
}
if (o == null || getClass() != o.getClass()) {
return false;
}
FragmentNode that = (FragmentNode) o;
return fragmentId.equals(that.fragmentId) &&
nodeId.equals(that.nodeId);
}
@Override
public int hashCode()
{
return Objects.hash(fragmentId, nodeId);
}
@Override
public String toString()
{
return fragmentId + ":" + nodeId;
}
}
}
© 2015 - 2025 Weber Informatics LLC | Privacy Policy