You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@iotdb.apache.org by li...@apache.org on 2019/06/11 09:00:51 UTC
[incubator-iotdb] 02/02: add log for cost time larger than 1000 ms
This is an automated email from the ASF dual-hosted git repository.
liurui pushed a commit to branch feature_async_close_memtablePool
in repository https://gitbox.apache.org/repos/asf/incubator-iotdb.git
commit de1e2b98fe2abe6305417c2c7b6c26f4acdbf583
Author: liuruiyiyang <24...@qq.com>
AuthorDate: Tue Jun 11 17:00:27 2019 +0800
add log for cost time larger than 1000 ms
---
.../engine/bufferwrite/BufferWriteProcessor.java | 28 +++++++++++-----------
.../iotdb/db/engine/filenode/FileNodeManager.java | 13 ++++++++--
.../db/engine/memtable/MemTableFlushTask.java | 2 +-
3 files changed, 26 insertions(+), 17 deletions(-)
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/engine/bufferwrite/BufferWriteProcessor.java b/iotdb/src/main/java/org/apache/iotdb/db/engine/bufferwrite/BufferWriteProcessor.java
index b331a57..211b9b0 100644
--- a/iotdb/src/main/java/org/apache/iotdb/db/engine/bufferwrite/BufferWriteProcessor.java
+++ b/iotdb/src/main/java/org/apache/iotdb/db/engine/bufferwrite/BufferWriteProcessor.java
@@ -253,7 +253,12 @@ public class BufferWriteProcessor extends Processor {
LOGGER.info("The usage of memory {} in bufferwrite processor {} reaches the threshold {}",
usageMem, processorName, threshold);
try {
+ long start = System.currentTimeMillis();
flush();
+ long elapse = System.currentTimeMillis() - start;
+ if(elapse > 1000) {
+ LOGGER.info("{} check memThreshold for flush cost {} ms", processorName, elapse);
+ }
} catch (IOException e) {
LOGGER.error("Flush bufferwrite error.", e);
throw new BufferWriteProcessorException(e);
@@ -413,17 +418,6 @@ public class BufferWriteProcessor extends Processor {
}
lastFlushTime = System.currentTimeMillis();
// check value count
- // waiting for the end of last flush operation.
- try {
- long startTime = System.currentTimeMillis();
- flushFuture.get();
- long timeCost = System.currentTimeMillis() - startTime;
- if (timeCost > 10) {
- LOGGER.info("BufferWrite Processor {} wait for the previous flushing task for {} ms.", getProcessorName(), timeCost);
- }
- } catch (InterruptedException | ExecutionException e) {
- throw new IOException(e);
- }
if (valueCount > 0) {
// update the lastUpdatetime, prepare for flush
try {
@@ -441,11 +435,14 @@ public class BufferWriteProcessor extends Processor {
}
valueCount = 0;
- synchronized (flushingMemTables) {
- flushingMemTables.add(workMemTable);
- }
+ flushingMemTables.add(workMemTable);
IMemTable tmpMemTableToFlush = workMemTable;
+ long start = System.currentTimeMillis();
workMemTable = MemTablePool.getInstance().getEmptyMemTable();
+ long elapse = System.currentTimeMillis() - start;
+ if (elapse > 1000) {
+ LOGGER.info("{} get memTable from pool cost {} ms", getProcessorName(), elapse);
+ }
flushId++;
long version = versionController.nextVersion();
@@ -457,7 +454,10 @@ public class BufferWriteProcessor extends Processor {
"flush memtable for bufferwrite processor {} synchronously for close task.",
getProcessorName(), FlushManager.getInstance().getWaitingTasksNumber(),
FlushManager.getInstance().getCorePoolSize());
+ start = System.currentTimeMillis();
flushTask("synchronously", tmpMemTableToFlush, version, walTaskId);
+ elapse = System.currentTimeMillis() - start;
+ LOGGER.info("{} flush for close cost {} ms", getProcessorName(), elapse);
flushFuture = new ImmediateFuture<>(true);
} else {
if (LOGGER.isInfoEnabled()) {
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/engine/filenode/FileNodeManager.java b/iotdb/src/main/java/org/apache/iotdb/db/engine/filenode/FileNodeManager.java
index 2b1f8ce..f550cc0 100644
--- a/iotdb/src/main/java/org/apache/iotdb/db/engine/filenode/FileNodeManager.java
+++ b/iotdb/src/main/java/org/apache/iotdb/db/engine/filenode/FileNodeManager.java
@@ -311,8 +311,13 @@ public class FileNodeManager implements IStatistic, IService {
// }
updateStat(isMonitor, tsRecord);
-
+ long start = System.currentTimeMillis();
FileNodeProcessor fileNodeProcessor = getProcessor(deviceId, true);
+ long elapse = System.currentTimeMillis() - start;
+ if(elapse > 1000){
+ LOGGER.info("{} execute [getProcessor(deviceId, true)] cost ,{}, ms", fileNodeProcessor.getProcessorName(), elapse);
+ }
+
int insertType;
try {
@@ -489,8 +494,12 @@ public class FileNodeManager implements IStatistic, IService {
bufferWriteProcessor.getInsertFilePath(), MemUtils.bytesCntToStr(
IoTDBDescriptor.getInstance().getConfig().getBufferwriteFileSizeThreshold()));
}
-
+ long start = System.currentTimeMillis();
fileNodeProcessor.closeBufferWrite();
+ long elapse = System.currentTimeMillis() - start;
+ if (elapse > 1000) {
+ LOGGER.info("{} close triggered by file size threshold cost {} ms", filenodeName, elapse);
+ }
}
}
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTableFlushTask.java b/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTableFlushTask.java
index 27926c0..1d7b56b 100644
--- a/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTableFlushTask.java
+++ b/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTableFlushTask.java
@@ -138,8 +138,8 @@ public class MemTableFlushTask {
ioTime += System.currentTimeMillis() - starTime;
}
}
- flushCallBack.afterFlush(memTable, tsFileIoWriter);
MemTablePool.getInstance().release(memTable);
+ flushCallBack.afterFlush(memTable, tsFileIoWriter);
tsFileIoWriter.getFlushID().getAndIncrement();
LOGGER.info("BufferWrite Processor {}, flushing a memtable into disk: io cost {} ms.",
processName, ioTime);