This is an automated email from the ASF dual-hosted git repository. spricoder pushed a commit to branch optimize/log-simplify in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit 59c7da76699e114c614931a089b76caaa08d04f0 Author: spricoder <[email protected]> AuthorDate: Fri Dec 29 14:11:57 2023 +0800 Optimize log according to real scenarios --- .../consensus/iot/IoTConsensusServerImpl.java | 2 +- .../event/common/heartbeat/PipeHeartbeatEvent.java | 4 +- .../pipe/resource/wal/PipeWALResourceManager.java | 4 +- .../db/storageengine/dataregion/DataRegion.java | 2 - .../dataregion/flush/CompressionRatio.java | 4 +- .../dataregion/flush/MemTableFlushTask.java | 38 +++++++++------- .../dataregion/memtable/TsFileProcessor.java | 53 ++++++++-------------- .../iotdb/tsfile/write/writer/TsFileIOWriter.java | 2 +- 8 files changed, 50 insertions(+), 59 deletions(-) diff --git a/iotdb-core/consensus/src/main/java/org/apache/iotdb/consensus/iot/IoTConsensusServerImpl.java b/iotdb-core/consensus/src/main/java/org/apache/iotdb/consensus/iot/IoTConsensusServerImpl.java index 4e43306d7c5..800754ddba6 100644 --- a/iotdb-core/consensus/src/main/java/org/apache/iotdb/consensus/iot/IoTConsensusServerImpl.java +++ b/iotdb-core/consensus/src/main/java/org/apache/iotdb/consensus/iot/IoTConsensusServerImpl.java @@ -206,7 +206,7 @@ public class IoTConsensusServerImpl { writeToStateMachineStartTime - getStateMachineLockTime); IndexedConsensusRequest indexedConsensusRequest = buildIndexedConsensusRequestForLocalRequest(request); - if (indexedConsensusRequest.getSearchIndex() % 10000 == 0) { + if (indexedConsensusRequest.getSearchIndex() % 100000 == 0) { logger.info( "DataRegion[{}]: index after build: safeIndex:{}, searchIndex: {}", thisNode.getGroupId(), diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/event/common/heartbeat/PipeHeartbeatEvent.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/event/common/heartbeat/PipeHeartbeatEvent.java index e9e6bb9d6c5..3e9f3b29d4b 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/event/common/heartbeat/PipeHeartbeatEvent.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/event/common/heartbeat/PipeHeartbeatEvent.java @@ -94,8 +94,8 @@ public class PipeHeartbeatEvent extends EnrichedEvent { public boolean internallyDecreaseResourceReferenceCount(String holderMessage) { // PipeName == null indicates that the event is the raw event at disruptor, // not the event copied and passed to the extractor - if (shouldPrintMessage && pipeName != null && LOGGER.isInfoEnabled()) { - LOGGER.info(this.toString()); + if (shouldPrintMessage && pipeName != null && LOGGER.isDebugEnabled()) { + LOGGER.debug(this.toString()); } return true; } diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/resource/wal/PipeWALResourceManager.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/resource/wal/PipeWALResourceManager.java index 592b86bdae7..0c34edda8a3 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/resource/wal/PipeWALResourceManager.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/pipe/resource/wal/PipeWALResourceManager.java @@ -70,8 +70,8 @@ public abstract class PipeWALResourceManager { try { if (entry.getValue().invalidateIfPossible()) { iterator.remove(); - } else { - LOGGER.info( + } else if (LOGGER.isDebugEnabled()) { + LOGGER.debug( "WAL (memtableId {}) is still referenced {} times", entry.getKey(), entry.getValue().getReferenceCount()); diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/DataRegion.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/DataRegion.java index acac85f500e..84adee4591d 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/DataRegion.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/DataRegion.java @@ -1415,7 +1415,6 @@ public class DataRegion implements IDataRegionForQuery { if (!workUnsequenceTsFileProcessors.containsKey(tsFileProcessor.getTimeRangeId())) { timePartitionIdVersionControllerMap.remove(tsFileProcessor.getTimeRangeId()); } - logger.info("close a sequence tsfile processor {}", databaseName + "-" + dataRegionId); } else { closingUnSequenceTsFileProcessor.add(tsFileProcessor); future = tsFileProcessor.asyncClose(); @@ -2330,7 +2329,6 @@ public class DataRegion implements IDataRegionForQuery { tsFileProcessor.isSequence(), tsFileResource.getTsFile().getName()); } - logger.info("signal closing database condition in {}", databaseName + "-" + dataRegionId); } protected int executeCompaction() { diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/CompressionRatio.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/CompressionRatio.java index 32e1cf80416..dfc37ba428e 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/CompressionRatio.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/CompressionRatio.java @@ -95,8 +95,8 @@ public class CompressionRatio { String.format( Locale.ENGLISH, RATIO_FILE_PATH_FORMAT, totalMemorySize.get(), totalDiskSize)); persist(oldFile, newFile); - if (LOGGER.isInfoEnabled()) { - LOGGER.info("Compression ratio is {}", (double) totalMemorySize.get() / totalDiskSize); + if (LOGGER.isDebugEnabled()) { + LOGGER.debug("Compression ratio is {}", (double) totalMemorySize.get() / totalDiskSize); } } diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/MemTableFlushTask.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/MemTableFlushTask.java index 1cf48033c63..454702e72f3 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/MemTableFlushTask.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/flush/MemTableFlushTask.java @@ -110,12 +110,14 @@ public class MemTableFlushTask { memTable.getSeriesNumber() == 0 ? 0 : memTable.getTotalPointsNum() / memTable.getSeriesNumber(); - LOGGER.info( - "The memTable size of SG {} is {}, the avg series points num in chunk is {}, total timeseries number is {}", - storageGroup, - memTable.memSize(), - avgSeriesPointsNum, - memTable.getSeriesNumber()); + if (LOGGER.isDebugEnabled()) { + LOGGER.debug( + "The memTable size of SG {} is {}, the avg series points num in chunk is {}, total timeseries number is {}", + storageGroup, + memTable.memSize(), + avgSeriesPointsNum, + memTable.getSeriesNumber()); + } WRITING_METRICS.recordFlushingMemTableStatus( storageGroup, memTable.memSize(), @@ -214,11 +216,13 @@ public class MemTableFlushTask { Tag.NAME.toString(), "flush"); - LOGGER.info( - "Database {} memtable {} flushing a memtable has finished! Time consumption: {}ms", - storageGroup, - memTable, - System.currentTimeMillis() - start); + if (LOGGER.isDebugEnabled()) { + LOGGER.debug( + "Database {} memtable {} flushing a memtable has finished! Time consumption: {}ms", + storageGroup, + memTable, + System.currentTimeMillis() - start); + } } /** encoding task (second task of pipeline) */ @@ -285,11 +289,13 @@ public class MemTableFlushTask { recordFlushPointsMetric(); - LOGGER.info( - "Database {}, flushing memtable {} into disk: Encoding data cost " + "{} ms.", - storageGroup, - writer.getFile().getName(), - memSerializeTime); + if (LOGGER.isDebugEnabled()) { + LOGGER.debug( + "Database {}, flushing memtable {} into disk: Encoding data cost " + "{} ms.", + storageGroup, + writer.getFile().getName(), + memSerializeTime); + } WRITING_METRICS.recordFlushCost(WritingMetrics.FLUSH_STAGE_ENCODING, memSerializeTime); } }; diff --git a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/memtable/TsFileProcessor.java b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/memtable/TsFileProcessor.java index 16119d9bd02..1f11f696abb 100644 --- a/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/memtable/TsFileProcessor.java +++ b/iotdb-core/datanode/src/main/java/org/apache/iotdb/db/storageengine/dataregion/memtable/TsFileProcessor.java @@ -792,10 +792,12 @@ public class TsFileProcessor { return false; } if (workMemTable.shouldFlush()) { - logger.info( - "The memtable size {} of tsfile {} reaches the mem control threshold", - workMemTable.memSize(), - tsFileResource.getTsFile().getAbsolutePath()); + if (logger.isDebugEnabled()) { + logger.debug( + "The memtable size {} of tsfile {} reaches the mem control threshold", + workMemTable.memSize(), + tsFileResource.getTsFile().getAbsolutePath()); + } return true; } if (!enableMemControl && workMemTable.memSize() >= getMemtableSizeThresholdBasedOnSeriesNum()) { @@ -824,14 +826,6 @@ public class TsFileProcessor { public boolean shouldClose() { long fileSize = tsFileResource.getTsFileSize(); long fileSizeThreshold = sequence ? config.getSeqTsFileSize() : config.getUnSeqTsFileSize(); - - if (fileSize >= fileSizeThreshold) { - logger.info( - "{} fileSize {} >= fileSizeThreshold {}", - tsFileResource.getTsFilePath(), - fileSize, - fileSizeThreshold); - } return fileSize >= fileSizeThreshold; } @@ -926,7 +920,6 @@ public class TsFileProcessor { // When invoke closing TsFile after insert data to memTable, we shouldn't flush until invoke // flushing memTable in System module. Future<?> future = addAMemtableIntoFlushingList(tmpMemTable); - logger.info("Memtable {} has been added to flushing list", tmpMemTable); shouldClose = true; return future; } catch (Exception e) { @@ -1353,12 +1346,14 @@ public class TsFileProcessor { private void updateCompressionRatio() { try { double compressionRatio = ((double) totalMemTableSize) / writer.getPos(); - logger.info( - "The compression ratio of tsfile {} is {}, totalMemTableSize: {}, the file size: {}", - writer.getFile().getAbsolutePath(), - compressionRatio, - totalMemTableSize, - writer.getPos()); + if (logger.isDebugEnabled()) { + logger.debug( + "The compression ratio of tsfile {} is {}, totalMemTableSize: {}, the file size: {}", + writer.getFile().getAbsolutePath(), + compressionRatio, + totalMemTableSize, + writer.getPos()); + } String dataRegionId = dataRegionInfo.getDataRegion().getDataRegionId(); WritingMetrics.getInstance() .recordTsFileCompressionRatioOfFlushingMemTable(dataRegionId, compressionRatio); @@ -1374,12 +1369,14 @@ public class TsFileProcessor { /** end file and write some meta */ private void endFile() throws IOException, TsFileProcessorException { - logger.info("Start to end file {}", tsFileResource); - long closeStartTime = System.currentTimeMillis(); + if (logger.isDebugEnabled()) { + logger.debug("Start to end file {}", tsFileResource); + } writer.endFile(); tsFileResource.serialize(); - logger.info("Ended file {}", tsFileResource); - + if (logger.isDebugEnabled()) { + logger.debug("Ended file {}", tsFileResource); + } // remove this processor from Closing list in StorageGroupProcessor, // mark the TsFileResource closed, no need writer anymore for (CloseFileListener closeFileListener : closeFileListeners) { @@ -1390,16 +1387,6 @@ public class TsFileProcessor { tsFileProcessorInfo.clear(); dataRegionInfo.closeTsFileProcessorAndReportToSystem(this); } - if (logger.isInfoEnabled()) { - long closeEndTime = System.currentTimeMillis(); - logger.info( - "Database {} close the file {}, TsFile size is {}, " - + "time consumption of flushing metadata is {}ms", - storageGroupName, - tsFileResource.getTsFile().getAbsoluteFile(), - writer.getFile().length(), - closeEndTime - closeStartTime); - } writer = null; } diff --git a/iotdb-core/tsfile/src/main/java/org/apache/iotdb/tsfile/write/writer/TsFileIOWriter.java b/iotdb-core/tsfile/src/main/java/org/apache/iotdb/tsfile/write/writer/TsFileIOWriter.java index e1d54fcf790..12b79a9fc80 100644 --- a/iotdb-core/tsfile/src/main/java/org/apache/iotdb/tsfile/write/writer/TsFileIOWriter.java +++ b/iotdb-core/tsfile/src/main/java/org/apache/iotdb/tsfile/write/writer/TsFileIOWriter.java @@ -349,7 +349,7 @@ public class TsFileIOWriter implements AutoCloseable { } canWrite = false; long cost = System.currentTimeMillis() - startTime; - logger.info("Time for flushing metadata is {} ms", cost); + logger.debug("Time for flushing metadata is {} ms", cost); } private void checkInMemoryPathCount() {
