This is an automated email from the ASF dual-hosted git repository. caogaofei pushed a commit to branch beyyes/time_recording in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit 03df0117fcad999c08144cadddebd5007b2935ed Author: Beyyes <[email protected]> AuthorDate: Fri Dec 1 16:23:15 2023 +0800 fix, tmp --- .../db/queryengine/execution/driver/Driver.java | 8 ++--- .../fragment/FragmentInstanceContext.java | 23 ++++++++++--- .../execution/fragment/QueryContext.java | 16 ++++++--- .../execution/operator/source/SeriesScanUtil.java | 27 +++++++++++---- .../iotdb/db/storageengine/buffer/ChunkCache.java | 4 +-- .../read/reader/chunk/DiskAlignedChunkLoader.java | 26 ++++++++++---- .../metadata/DiskAlignedChunkMetadataLoader.java | 2 +- .../metadata/MemAlignedChunkMetadataLoader.java | 2 +- .../org/apache/iotdb/db/utils/FileLoaderUtils.java | 40 +++++++++++----------- 9 files changed, 98 insertions(+), 50 deletions(-) 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 da8ab1d24e8..8ad1fa3f398 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 @@ -433,10 +433,10 @@ public abstract class Driver implements IDriver { Thread.currentThread().interrupt(); } } - LOGGER.warn( - "~~~~~ closeAndDestroyOperators of driver, allExecuteTime: {}ms, root operator: {}", - allExecuteTime / 1000000, - root.getClass()); + // LOGGER.warn( + // "~~~~~ closeAndDestroyOperators of driver, allExecuteTime: {}ms, root operator: {}", + // allExecuteTime / 1000000, + // root.getClass()); return inFlightException; } diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/FragmentInstanceContext.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/FragmentInstanceContext.java index 0dc79dd5c48..dfdc881034b 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/FragmentInstanceContext.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/FragmentInstanceContext.java @@ -452,18 +452,31 @@ public class FragmentInstanceContext extends QueryContext { releaseTime.set(endTime); durationTime.set(endTime - executionStartTime.get()); LOGGER.warn( - " ===== FragmentInstanceContext released, id: {}, " + " ========== \r\n " + + "FragmentInstanceContext released, id: {}, " + "releaseTime: {}, " + "startTime: {}, " - + "durationTime: {}ms, " - + "loadTimeseriesMetadataDiskCount: {}, " - + "loadTimeseriesMetadataDiskTime: {}", + + "durationTime: {}ms, \r\n" + + "loadTimeseriesMetadataCount: [Disk: {}, Mem: {}], \r\n" + + "loadTimeseriesMetadataTime: [Disk: {}, Mem: {}]ns, \r\n" + + "constructChunkReaderDisk - Count: {}, Time:{}ns, constructChunkReaderDiskDeserializationTime: {}ns\r\n" + + "buildTsBlockFromPageReaderCount: [Disk: {}, Mem: {}], \r\n" + + "buildTsBlockFromPageReaderTime: [Disk: {}, Mem: {}]ns", id, releaseTime.get(), executionStartTime.get(), durationTime.get(), loadTimeSeriesMetadataDiskCount, - loadTimeSeriesMetadataDiskCount); + loadTimeSeriesMetadataMemCount, + loadTimeSeriesMetadataDiskTime, + loadTimeSeriesMetadataMemTime, + constructChunkReaderDiskCount, + constructChunkReaderDiskTime, + constructChunkReaderDiskDeserializationTime, + buildTsBlockFromPageReaderDiskCount, + buildTsBlockFromPageReaderMemCount, + buildTsBlockFromPageReaderDiskTime, + buildTsBlockFromPageReaderMemTime); dataRegion = null; globalTimeFilter = null; diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/QueryContext.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/QueryContext.java index 2e2babe80ea..242a68f4060 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/QueryContext.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/queryengine/execution/fragment/QueryContext.java @@ -37,13 +37,21 @@ import java.util.HashSet; import java.util.List; import java.util.Map; import java.util.Set; +import java.util.concurrent.atomic.AtomicLong; /** QueryContext contains the shared information with in a query. */ public class QueryContext { - public int loadTimeSeriesMetadataDiskCount = 0; - public long loadTimeSeriesMetadataDiskTime = 0; - public int loadTimeSeriesMetadataMemCount = 0; - public long loadTimeSeriesMetadataMemTime = 0; + public AtomicLong loadTimeSeriesMetadataDiskCount = new AtomicLong(0); + public AtomicLong loadTimeSeriesMetadataDiskTime = new AtomicLong(0); + public AtomicLong loadTimeSeriesMetadataMemCount = new AtomicLong(0); + public AtomicLong loadTimeSeriesMetadataMemTime = new AtomicLong(0); + public AtomicLong constructChunkReaderDiskCount = new AtomicLong(0); + public AtomicLong constructChunkReaderDiskTime = new AtomicLong(0); + public AtomicLong constructChunkReaderDiskDeserializationTime = new AtomicLong(0); + public AtomicLong buildTsBlockFromPageReaderDiskCount = new AtomicLong(0); + public AtomicLong buildTsBlockFromPageReaderDiskTime = new AtomicLong(0); + public AtomicLong buildTsBlockFromPageReaderMemCount = new AtomicLong(0); + public AtomicLong buildTsBlockFromPageReaderMemTime = new AtomicLong(0); /** * The key is the path of a ModificationFile and the value is all Modifications in this file. We 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 77f1c100f4d..155f0665833 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 @@ -547,7 +547,8 @@ public class SeriesScanUtil { chunkMetaData.getVersion(), chunkMetaData.getOffsetOfChunkHeader(), iPageReader, - true)); + true, + context)); } } else { for (int i = pageReaderList.size() - 1; i >= 0; i--) { @@ -556,7 +557,8 @@ public class SeriesScanUtil { chunkMetaData.getVersion(), chunkMetaData.getOffsetOfChunkHeader(), pageReaderList.get(i), - true)); + true, + context)); } } } else { @@ -567,7 +569,8 @@ public class SeriesScanUtil { chunkMetaData.getVersion(), chunkMetaData.getOffsetOfChunkHeader(), pageReader, - false))); + false, + context))); } } @@ -1130,7 +1133,7 @@ public class SeriesScanUtil { } protected static class VersionPageReader { - + private final QueryContext queryContext; private final PriorityMergeReader.MergeReaderPriority version; private final IPageReader data; @@ -1138,12 +1141,14 @@ public class SeriesScanUtil { private final boolean isAligned; private final boolean isMem; - VersionPageReader(long version, long offset, IPageReader data, boolean isSeq) { + VersionPageReader( + long version, long offset, IPageReader data, boolean isSeq, QueryContext queryContext) { this.version = new PriorityMergeReader.MergeReaderPriority(version, offset); this.data = data; this.isSeq = isSeq; this.isAligned = data instanceof IAlignedPageReader; this.isMem = data instanceof MemPageReader || data instanceof MemAlignedPageReader; + this.queryContext = queryContext; } @SuppressWarnings("squid:S3740") @@ -1176,6 +1181,16 @@ public class SeriesScanUtil { } return tsBlock; } finally { + long time = System.nanoTime() - startTime; + if (isAligned) { + if (isMem) { + queryContext.buildTsBlockFromPageReaderMemCount.getAndAdd(1); + queryContext.buildTsBlockFromPageReaderMemTime.getAndAdd(time); + } else { + queryContext.buildTsBlockFromPageReaderDiskCount.getAndAdd(1); + queryContext.buildTsBlockFromPageReaderDiskTime.getAndAdd(time); + } + } SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost( isAligned ? (isMem @@ -1184,7 +1199,7 @@ public class SeriesScanUtil { : (isMem ? BUILD_TSBLOCK_FROM_PAGE_READER_NONALIGNED_MEM : BUILD_TSBLOCK_FROM_PAGE_READER_NONALIGNED_DISK), - System.nanoTime() - startTime); + time); } } 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 84d6f4f728b..758282c0667 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 @@ -131,8 +131,8 @@ public class ChunkCache { return new Chunk( chunk.getHeader(), chunk.getData().duplicate(), timeRangeList, chunkStatistic); } finally { - SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost( - READ_CHUNK_ALL, System.nanoTime() - startTime); + long time = System.nanoTime() - startTime; + SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost(READ_CHUNK_ALL, time); } } diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/DiskAlignedChunkLoader.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/DiskAlignedChunkLoader.java index c6c59578c67..c3612b49993 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/DiskAlignedChunkLoader.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/DiskAlignedChunkLoader.java @@ -19,6 +19,7 @@ package org.apache.iotdb.db.storageengine.dataregion.read.reader.chunk; +import org.apache.iotdb.db.queryengine.execution.fragment.QueryContext; import org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet; import org.apache.iotdb.db.storageengine.buffer.ChunkCache; import org.apache.iotdb.db.storageengine.dataregion.tsfile.TsFileResource; @@ -31,6 +32,9 @@ import org.apache.iotdb.tsfile.read.filter.basic.Filter; import org.apache.iotdb.tsfile.read.reader.IChunkReader; import org.apache.iotdb.tsfile.read.reader.chunk.AlignedChunkReader; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + import java.io.IOException; import java.util.ArrayList; import java.util.List; @@ -39,7 +43,8 @@ import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.CON import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.INIT_CHUNK_READER_ALIGNED_DISK; public class DiskAlignedChunkLoader implements IChunkLoader { - + private static final Logger LOGGER = LoggerFactory.getLogger(DiskAlignedChunkLoader.class); + private QueryContext context; private final boolean debug; // only used for limit and offset push down optimizer, if we select all columns from aligned @@ -53,8 +58,10 @@ public class DiskAlignedChunkLoader implements IChunkLoader { private static final SeriesScanCostMetricSet SERIES_SCAN_COST_METRIC_SET = SeriesScanCostMetricSet.getInstance(); - public DiskAlignedChunkLoader(boolean debug, boolean queryAllSensors, TsFileResource resource) { - this.debug = debug; + public DiskAlignedChunkLoader( + QueryContext context, boolean queryAllSensors, TsFileResource resource) { + this.context = context; + this.debug = context.isDebug(); this.queryAllSensors = queryAllSensors; this.resource = resource; } @@ -107,13 +114,18 @@ public class DiskAlignedChunkLoader implements IChunkLoader { long t2 = System.nanoTime(); IChunkReader chunkReader = new AlignedChunkReader(timeChunk, valueChunkList, timeFilter, queryAllSensors); - SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost( - INIT_CHUNK_READER_ALIGNED_DISK, System.nanoTime() - t2); + long time = System.nanoTime() - t2; + LOGGER.warn("~~~~~ construct chunk reader deserialization time: {}", time); + context.constructChunkReaderDiskDeserializationTime.getAndAdd(time); + SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost(INIT_CHUNK_READER_ALIGNED_DISK, time); return chunkReader; } finally { - SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost( - CONSTRUCT_CHUNK_READER_ALIGNED_DISK, System.nanoTime() - t1); + long time = System.nanoTime() - t1; + context.constructChunkReaderDiskCount.getAndAdd(1); + context.constructChunkReaderDiskTime.getAndAdd(time); + + SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost(CONSTRUCT_CHUNK_READER_ALIGNED_DISK, time); } } } diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/DiskAlignedChunkMetadataLoader.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/DiskAlignedChunkMetadataLoader.java index 0520200a9e8..d53a3e6d077 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/DiskAlignedChunkMetadataLoader.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/DiskAlignedChunkMetadataLoader.java @@ -121,7 +121,7 @@ public class DiskAlignedChunkMetadataLoader implements IChunkMetadataLoader { chunkMetadata.setVersion(resource.getVersion()); chunkMetadata.setClosed(resource.isClosed()); chunkMetadata.setChunkLoader( - new DiskAlignedChunkLoader(context.isDebug(), queryAllSensors, resource)); + new DiskAlignedChunkLoader(context, queryAllSensors, resource)); } }); diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/MemAlignedChunkMetadataLoader.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/MemAlignedChunkMetadataLoader.java index 105e62620d8..4ac6c31c1f9 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/MemAlignedChunkMetadataLoader.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/read/reader/chunk/metadata/MemAlignedChunkMetadataLoader.java @@ -78,7 +78,7 @@ public class MemAlignedChunkMetadataLoader implements IChunkMetadataLoader { chunkMetadata.setVersion(resource.getVersion()); chunkMetadata.setClosed(resource.isClosed()); chunkMetadata.setChunkLoader( - new DiskAlignedChunkLoader(context.isDebug(), queryAllSensors, resource)); + new DiskAlignedChunkLoader(context, queryAllSensors, resource)); } }); diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/utils/FileLoaderUtils.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/utils/FileLoaderUtils.java index 05fa39658a5..39fb06b22d3 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/utils/FileLoaderUtils.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/utils/FileLoaderUtils.java @@ -58,8 +58,6 @@ import java.util.Map; import java.util.Map.Entry; import java.util.Set; -import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.LOAD_TIMESERIES_METADATA_ALIGNED_DISK; -import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.LOAD_TIMESERIES_METADATA_ALIGNED_MEM; import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.LOAD_TIMESERIES_METADATA_NONALIGNED_DISK; import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.LOAD_TIMESERIES_METADATA_NONALIGNED_MEM; import static org.apache.iotdb.db.queryengine.metric.SeriesScanCostMetricSet.TIMESERIES_METADATA_MODIFICATION_ALIGNED; @@ -191,13 +189,6 @@ public class FileLoaderUtils { return timeSeriesMetadata; } finally { long time = System.nanoTime() - t1; - if (loadFromMem) { - context.loadTimeSeriesMetadataMemCount += 1; - context.loadTimeSeriesMetadataMemTime += time; - } else { - context.loadTimeSeriesMetadataDiskCount += 1; - context.loadTimeSeriesMetadataDiskTime += time; - } SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost( loadFromMem ? LOAD_TIMESERIES_METADATA_NONALIGNED_MEM @@ -261,19 +252,28 @@ public class FileLoaderUtils { } return alignedTimeSeriesMetadata; } finally { - long loadAlignedTimeSeriesMetadataTime = System.nanoTime() - t1; - LOGGER.warn( - "!!!!! loadAlignedTimeSeriesMetadataTime, path: {}, type: {}, time: {}ms", - alignedPath.getFullPath(), - loadFromMem - ? LOAD_TIMESERIES_METADATA_ALIGNED_MEM - : LOAD_TIMESERIES_METADATA_ALIGNED_DISK, - loadAlignedTimeSeriesMetadataTime / 1000000); + long costTime = System.nanoTime() - t1; + if (loadFromMem) { + context.loadTimeSeriesMetadataMemCount.getAndAdd(1); + context.loadTimeSeriesMetadataMemTime.getAndAdd(costTime); + // LOGGER.warn( + // "!!!!! loadAlignedTimeSeriesMetadataTime, Mem, path: {}, time: {}ns", + // alignedPath.getFullPath(), + // costTime); + } else { + context.loadTimeSeriesMetadataDiskCount.getAndAdd(1); + context.loadTimeSeriesMetadataDiskTime.getAndAdd(costTime); + // LOGGER.warn( + // "!!!!! loadAlignedTimeSeriesMetadataTime, Disk, path: {}, time: {}ns", + // alignedPath.getFullPath(), + // costTime); + } + SERIES_SCAN_COST_METRIC_SET.recordSeriesScanCost( loadFromMem - ? LOAD_TIMESERIES_METADATA_ALIGNED_MEM - : LOAD_TIMESERIES_METADATA_ALIGNED_DISK, - loadAlignedTimeSeriesMetadataTime); + ? LOAD_TIMESERIES_METADATA_NONALIGNED_MEM + : LOAD_TIMESERIES_METADATA_NONALIGNED_DISK, + costTime); } }
