Add debug
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/thrift/impl/ClientRPCServiceImpl.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/thrift/impl/ClientRPCServiceImpl.java
index 09e21e1..f03a0e5 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/thrift/impl/ClientRPCServiceImpl.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/protocol/thrift/impl/ClientRPCServiceImpl.java
@@ -309,6 +309,7 @@
ExecutionResult result;
if (clientSession.getSqlDialect() == IClientSession.SqlDialect.TREE) {
Statement s = StatementGenerator.createStatement(statement, clientSession.getZoneId());
+ LOGGER.info("parse cost {}", (System.nanoTime() - startTime));
if (s == null) {
return RpcUtils.getTSExecuteStatementResp(
@@ -343,6 +344,7 @@
} else {
org.apache.iotdb.db.queryengine.plan.relational.sql.ast.Statement s =
relationSqlParser.createStatement(statement, clientSession.getZoneId());
+ LOGGER.info("parse cost {}", (System.nanoTime() - startTime));
if (s instanceof Use) {
useDatabase = true;
@@ -372,6 +374,8 @@
req.getTimeout());
}
+ LOGGER.info("plan cost {}", (System.nanoTime() - startTime));
+
if (result.status.code != TSStatusCode.SUCCESS_STATUS.getStatusCode()
&& result.status.code != TSStatusCode.REDIRECTION_RECOMMEND.getStatusCode()) {
finished = true;
@@ -435,6 +439,7 @@
if (quota != null) {
quota.close();
}
+ LOGGER.info("query cost: {}", currentOperationCost);
}
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/driver/Driver.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/driver/Driver.java
index 356a632..dd4813d 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/driver/Driver.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/driver/Driver.java
@@ -428,6 +428,7 @@
value[1] += operatorContext.getNextCalledCount();
}
for (Map.Entry<String, long[]> entry : operatorType2TotalCost.entrySet()) {
+ LOGGER.info("driver cost {}: {}", entry.getKey(), entry.getValue());
QUERY_METRICS.recordOperatorExecutionCost(entry.getKey(), entry.getValue()[0]);
QUERY_METRICS.recordOperatorExecutionCount(entry.getKey(), entry.getValue()[1]);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/operator/source/SeriesScanUtil.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/operator/source/SeriesScanUtil.java
index 15fe071..c46f1e9 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/operator/source/SeriesScanUtil.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/operator/source/SeriesScanUtil.java
@@ -49,6 +49,7 @@
import org.apache.tsfile.read.reader.IPageReader;
import org.apache.tsfile.read.reader.IPointReader;
import org.apache.tsfile.read.reader.page.AlignedPageReader;
+import org.apache.tsfile.read.reader.page.TablePageReader;
import org.apache.tsfile.read.reader.series.PaginationController;
import org.apache.tsfile.utils.Accountable;
import org.apache.tsfile.utils.RamUsageEstimator;
@@ -1228,7 +1229,10 @@
this.version = new MergeReaderPriority(fileTimestamp, version, offset, isSeq);
this.data = data;
this.isSeq = isSeq;
- this.isAligned = data instanceof AlignedPageReader || data instanceof MemAlignedPageReader;
+ this.isAligned =
+ data instanceof AlignedPageReader
+ || data instanceof MemAlignedPageReader
+ || data instanceof TablePageReader;
this.isMem = data instanceof MemPageReader || data instanceof MemAlignedPageReader;
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/metric/SeriesScanCostMetricSet.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/metric/SeriesScanCostMetricSet.java
index ab6fb12..ebaa7c0 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/metric/SeriesScanCostMetricSet.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/metric/SeriesScanCostMetricSet.java
@@ -1107,28 +1107,28 @@
/////////////////////////////////////////////////////////////////////////////////////////////////
private static final String READ_CHUNK = "read_chunk";
private static final String ALL = "all";
- public static final String READ_CHUNK_ALL = READ_CHUNK + "_" + ALL;
+ public static final String READ_CHUNK_CACHE = READ_CHUNK + "_" + CACHE;
public static final String READ_CHUNK_FILE = READ_CHUNK + "_" + FILE;
- private Timer readChunkAllTimer = DoNothingMetricManager.DO_NOTHING_TIMER;
+ private Timer readChunkCacheTimer = DoNothingMetricManager.DO_NOTHING_TIMER;
private Timer readChunkFileTimer = DoNothingMetricManager.DO_NOTHING_TIMER;
private void bindReadChunk(AbstractMetricService metricService) {
- readChunkAllTimer =
+ readChunkCacheTimer =
metricService.getOrCreateTimer(
Metric.SERIES_SCAN_COST.toString(),
MetricLevel.IMPORTANT,
Tag.STAGE.toString(),
- READ_CHUNK,
+ READ_CHUNK_CACHE,
Tag.TYPE.toString(),
NULL,
Tag.FROM.toString(),
- ALL);
+ CACHE);
readChunkFileTimer =
metricService.getOrCreateTimer(
Metric.SERIES_SCAN_COST.toString(),
MetricLevel.IMPORTANT,
Tag.STAGE.toString(),
- READ_CHUNK,
+ READ_CHUNK_FILE,
Tag.TYPE.toString(),
NULL,
Tag.FROM.toString(),
@@ -1136,16 +1136,16 @@
}
private void unbindReadChunk(AbstractMetricService metricService) {
- readChunkAllTimer = DoNothingMetricManager.DO_NOTHING_TIMER;
+ readChunkCacheTimer = DoNothingMetricManager.DO_NOTHING_TIMER;
readChunkFileTimer = DoNothingMetricManager.DO_NOTHING_TIMER;
- Arrays.asList(ALL, FILE)
+ Arrays.asList(CACHE, FILE)
.forEach(
from ->
metricService.remove(
MetricType.TIMER,
Metric.SERIES_SCAN_COST.toString(),
Tag.STAGE.toString(),
- READ_CHUNK,
+ READ_CHUNK + "_" + from,
Tag.TYPE.toString(),
NULL,
Tag.FROM.toString(),
@@ -1571,8 +1571,8 @@
case READ_TIMESERIES_METADATA_FILE:
readTimeseriesMetadataFileTimer.updateNanos(cost);
break;
- case READ_CHUNK_ALL:
- readChunkAllTimer.updateNanos(cost);
+ case READ_CHUNK_CACHE:
+ readChunkCacheTimer.updateNanos(cost);
break;
case READ_CHUNK_FILE:
readChunkFileTimer.updateNanos(cost);
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/AnalyzeVisitor.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/AnalyzeVisitor.java
index b855603..ff13095 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/AnalyzeVisitor.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/AnalyzeVisitor.java
@@ -538,6 +538,7 @@
logger.debug("[EndFetchSchema]");
long schemaFetchCost = System.nanoTime() - startTime;
context.setFetchSchemaCost(schemaFetchCost);
+ logger.info("device fetch cost: {}", schemaFetchCost);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TREE_TYPE, SCHEMA_FETCHER, schemaFetchCost);
}
@@ -2227,6 +2228,7 @@
}
} finally {
long partitionFetchCost = System.nanoTime() - startTime;
+ logger.info("data partition cost: {}", partitionFetchCost);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TREE_TYPE, PARTITION_FETCHER, partitionFetchCost);
context.setFetchPartitionCost(partitionFetchCost);
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/Analyzer.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/Analyzer.java
index 238620b..ea844d1 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/Analyzer.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/analyze/Analyzer.java
@@ -25,11 +25,16 @@
import org.apache.iotdb.db.queryengine.plan.analyze.schema.ISchemaFetcher;
import org.apache.iotdb.db.queryengine.plan.statement.Statement;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
import static org.apache.iotdb.db.queryengine.metric.QueryPlanCostMetricSet.ANALYZER;
import static org.apache.iotdb.db.queryengine.metric.QueryPlanCostMetricSet.TREE_TYPE;
/** Analyze the statement and generate Analysis. */
public class Analyzer {
+ private static final Logger LOGGER = LoggerFactory.getLogger(Analyzer.class);
+
private final MPPQueryContext context;
private final IPartitionFetcher partitionFetcher;
@@ -52,6 +57,7 @@
}
if (statement.isQuery()) {
+ LOGGER.info("analyze cost: {}", System.nanoTime() - startTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TREE_TYPE, ANALYZER, System.nanoTime() - startTime);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/execution/QueryExecution.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/execution/QueryExecution.java
index 4ecddf1..65dc6af 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/execution/QueryExecution.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/execution/QueryExecution.java
@@ -303,6 +303,7 @@
if (analysis.isQuery()) {
long distributionPlanCost = System.nanoTime() - startTime;
+ LOGGER.info("distribution plan cost: {}", distributionPlanCost);
context.setDistributionPlanCost(distributionPlanCost);
QUERY_PLAN_COST_METRIC_SET.recordPlanCost(
TREE_TYPE, DISTRIBUTION_PLANNER, distributionPlanCost);
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/planner/LogicalPlanner.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/planner/LogicalPlanner.java
index 1a05c5f..503beb6 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/planner/LogicalPlanner.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/planner/LogicalPlanner.java
@@ -27,6 +27,9 @@
import org.apache.iotdb.db.queryengine.plan.planner.plan.LogicalQueryPlan;
import org.apache.iotdb.db.queryengine.plan.planner.plan.node.PlanNode;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
import java.util.Arrays;
import java.util.List;
@@ -36,6 +39,8 @@
/** Generate a logical plan for the statement. */
public class LogicalPlanner {
+ private static final Logger LOGGER = LoggerFactory.getLogger(LogicalPlanner.class);
+
private final MPPQueryContext context;
private final List<PlanOptimizer> optimizers =
Arrays.asList(new PredicatePushDown(), new AggregationPushDown());
@@ -54,12 +59,14 @@
long planFinishTime = System.nanoTime();
context.setLogicalPlanCost(planFinishTime - startTime);
+ LOGGER.info("logical plan cost: {}", planFinishTime - startTime);
for (PlanOptimizer optimizer : optimizers) {
rootNode = optimizer.optimize(rootNode, analysis, context);
}
context.setLogicalOptimizationCost(System.nanoTime() - planFinishTime);
+ LOGGER.info("optimize cost: {}", System.nanoTime() - planFinishTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TREE_TYPE, LOGICAL_PLANNER, System.nanoTime() - planFinishTime);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/analyzer/Analyzer.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/analyzer/Analyzer.java
index 8d25c7a..22a4306 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/analyzer/Analyzer.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/analyzer/Analyzer.java
@@ -31,6 +31,9 @@
import org.apache.iotdb.db.queryengine.plan.relational.sql.ast.Statement;
import org.apache.iotdb.db.queryengine.plan.relational.sql.ast.WrappedInsertStatement;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
import java.util.List;
import java.util.Map;
@@ -40,6 +43,8 @@
public class Analyzer {
+ private static final Logger LOGGER = LoggerFactory.getLogger(Analyzer.class);
+
private final StatementAnalyzerFactory statementAnalyzerFactory;
private final MPPQueryContext context;
@@ -92,6 +97,7 @@
analyzer.analyze(statement);
if (statement instanceof Query) {
+ LOGGER.info("analyze cost: {}", System.nanoTime() - startTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TABLE_TYPE, ANALYZER, System.nanoTime() - startTime);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/TableLogicalPlanner.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/TableLogicalPlanner.java
index 2692690..6d5e2b5 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/TableLogicalPlanner.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/TableLogicalPlanner.java
@@ -64,6 +64,8 @@
import com.google.common.collect.ImmutableMap;
import org.apache.tsfile.read.common.type.LongType;
import org.apache.tsfile.read.common.type.TypeFactory;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
import java.util.ArrayList;
import java.util.List;
@@ -79,6 +81,8 @@
import static org.apache.iotdb.db.queryengine.plan.relational.type.InternalTypeManager.getTSDataType;
public class TableLogicalPlanner {
+ private static final Logger LOGGER = LoggerFactory.getLogger(TableLogicalPlanner.class);
+
private final MPPQueryContext queryContext;
private final SessionInfo sessionInfo;
private final SymbolAllocator symbolAllocator;
@@ -124,6 +128,7 @@
PlanNode planNode = planStatement(analysis, statement);
if (statement instanceof Query) {
+ LOGGER.info("logical plan cost: {}", System.nanoTime() - startTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TABLE_TYPE, LOGICAL_PLANNER, System.nanoTime() - startTime);
startTime = System.nanoTime();
@@ -142,6 +147,7 @@
warningCollector,
PlanOptimizersStatsCollector.createPlanOptimizersStatsCollector()));
}
+ LOGGER.info("optimize cost: {}", System.nanoTime() - startTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TABLE_TYPE, LOGICAL_PLAN_OPTIMIZE, System.nanoTime() - startTime);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/distribute/TableDistributedPlanner.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/distribute/TableDistributedPlanner.java
index a485f38..c3d5e06 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/distribute/TableDistributedPlanner.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/distribute/TableDistributedPlanner.java
@@ -19,6 +19,7 @@
import org.apache.iotdb.db.queryengine.execution.exchange.sink.DownStreamChannelLocation;
import org.apache.iotdb.db.queryengine.metric.QueryPlanCostMetricSet;
import org.apache.iotdb.db.queryengine.plan.analyze.QueryType;
+import org.apache.iotdb.db.queryengine.plan.execution.QueryExecution;
import org.apache.iotdb.db.queryengine.plan.planner.distribution.WriteFragmentParallelPlanner;
import org.apache.iotdb.db.queryengine.plan.planner.plan.DistributedQueryPlan;
import org.apache.iotdb.db.queryengine.plan.planner.plan.FragmentInstance;
@@ -38,6 +39,8 @@
import org.apache.iotdb.db.queryengine.plan.relational.planner.optimizations.PlanOptimizer;
import org.apache.iotdb.db.queryengine.plan.relational.sql.ast.Query;
import org.apache.iotdb.db.queryengine.plan.relational.type.InternalTypeManager;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
import java.util.Collections;
import java.util.HashMap;
@@ -51,6 +54,7 @@
import static org.apache.iotdb.db.queryengine.metric.QueryPlanCostMetricSet.TABLE_TYPE;
public class TableDistributedPlanner {
+ private static final Logger LOGGER = LoggerFactory.getLogger(TableDistributedPlanner.class);
private final Analysis analysis;
private final SymbolAllocator symbolAllocator;
@@ -104,6 +108,7 @@
DistributedQueryPlan resultDistributedPlan = generateDistributedPlan(outputNodeWithExchange);
if (analysis.getStatement() instanceof Query) {
+ LOGGER.info("distribution plan cost: {}", System.nanoTime() - startTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TABLE_TYPE, DISTRIBUTION_PLANNER, System.nanoTime() - startTime);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/optimizations/PushPredicateIntoTableScan.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/optimizations/PushPredicateIntoTableScan.java
index f9d2d5e..ad8081b 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/optimizations/PushPredicateIntoTableScan.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/relational/planner/optimizations/PushPredicateIntoTableScan.java
@@ -61,6 +61,8 @@
import com.google.common.collect.ImmutableSet;
import org.apache.tsfile.read.filter.basic.Filter;
import org.apache.tsfile.utils.Pair;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
import javax.annotation.Nullable;
@@ -120,6 +122,7 @@
* to be adapted.
*/
public class PushPredicateIntoTableScan implements PlanOptimizer {
+ private static final Logger LOGGER = LoggerFactory.getLogger(PushPredicateIntoTableScan.class);
private static final IoTDBConfig CONFIG = IoTDBDescriptor.getInstance().getConfig();
@@ -439,6 +442,7 @@
attributeColumns,
queryContext);
tableScanNode.setDeviceEntries(deviceEntries);
+ LOGGER.info("device fetch cost: {}", System.nanoTime() - startTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TABLE_TYPE, SCHEMA_FETCHER, System.nanoTime() - startTime);
@@ -477,7 +481,7 @@
} else {
analysis.upsertDataPartition(dataPartition);
}
-
+ LOGGER.info("data partition cost: {}", System.nanoTime() - startTime);
QueryPlanCostMetricSet.getInstance()
.recordPlanCost(TABLE_TYPE, PARTITION_FETCHER, System.nanoTime() - startTime);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/scheduler/ClusterScheduler.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/scheduler/ClusterScheduler.java
index 448f082..ec9f635 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/scheduler/ClusterScheduler.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/plan/scheduler/ClusterScheduler.java
@@ -136,6 +136,7 @@
stateMachine.transitionToFailed(e);
return;
} finally {
+ logger.info("dispatch cost: {}", System.nanoTime() - startTime);
QUERY_EXECUTION_METRICS.recordExecutionCost(WAIT_FOR_DISPATCH, System.nanoTime() - startTime);
}
diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/buffer/ChunkCache.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/buffer/ChunkCache.java
index 5914272..a604409 100644
--- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/buffer/ChunkCache.java
+++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/buffer/ChunkCache.java
@@ -47,7 +47,7 @@
import java.util.function.Function;
import java.util.function.LongConsumer;
-import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.READ_CHUNK_ALL;
+import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.READ_CHUNK_CACHE;
import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.READ_CHUNK_FILE;
/**
@@ -162,11 +162,13 @@
} finally {
if (chunkLoader.isCacheMiss()) {
cacheMissAdder.accept(1);
+ SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost(
+ READ_CHUNK_FILE, System.nanoTime() - startTime);
} else {
cacheHitAdder.accept(1);
+ SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost(
+ READ_CHUNK_CACHE, System.nanoTime() - startTime);
}
- SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost(
- READ_CHUNK_ALL, System.nanoTime() - startTime);
}
}
