You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@iotdb.apache.org by qi...@apache.org on 2019/06/12 04:32:39 UTC
[incubator-iotdb] branch feature_async_close_tsfile updated: add
more logs when getting a memtable
This is an automated email from the ASF dual-hosted git repository.
qiaojialin pushed a commit to branch feature_async_close_tsfile
in repository https://gitbox.apache.org/repos/asf/incubator-iotdb.git
The following commit(s) were added to refs/heads/feature_async_close_tsfile by this push:
new 1d35b2f add more logs when getting a memtable
1d35b2f is described below
commit 1d35b2f201e2619a6be6035896b607d5eb182ae5
Author: qiaojialin <64...@qq.com>
AuthorDate: Wed Jun 12 12:32:23 2019 +0800
add more logs when getting a memtable
---
.../db/engine/bufferwrite/BufferWriteProcessor.java | 13 ++++++++-----
.../iotdb/db/engine/filenode/FileNodeManager.java | 14 +++++++++++++-
.../iotdb/db/engine/memtable/MemTableFlushTask.java | 8 ++++++++
.../apache/iotdb/db/engine/memtable/MemTablePool.java | 18 +++++++++++++++---
.../iotdb/db/engine/overflow/io/OverflowProcessor.java | 2 +-
5 files changed, 45 insertions(+), 10 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 c21ad7e..97e53cb 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
@@ -163,7 +163,12 @@ public class BufferWriteProcessor extends Processor {
throw new BufferWriteProcessorException(e);
}
if (workMemTable == null) {
- workMemTable = MemTablePool.getInstance().getEmptyMemTable();
+ long start1 = System.currentTimeMillis();
+ workMemTable = MemTablePool.getInstance().getEmptyMemTable(this);
+ start1 = System.currentTimeMillis() - start1;
+ if (start1 > 1000) {
+ LOGGER.info("BufferWriteProcessor.reopen getEmptyMemtable cost: {}", start1);
+ }
} else {
workMemTable.clear();
}
@@ -373,8 +378,6 @@ public class BufferWriteProcessor extends Processor {
MemTableFlushTask tableFlushTask = new MemTableFlushTask(writer, getProcessorName(), flushId,
this::removeFlushedMemTable);
tableFlushTask.flushMemTable(fileSchema, tmpMemTableToFlush, version);
- // write restore information
- writer.flush();
}
filenodeFlushAction.act();
@@ -452,11 +455,11 @@ public class BufferWriteProcessor extends Processor {
IMemTable tmpMemTableToFlush = workMemTable;
long start = System.currentTimeMillis();
- workMemTable = MemTablePool.getInstance().getEmptyMemTable();
+ workMemTable = MemTablePool.getInstance().getEmptyMemTable(this);
start = System.currentTimeMillis() - start;
if (start > 1000) {
- LOGGER.info("get empty memtable cost: {}", start);
+ LOGGER.info("BufferWriteProcessor.flush getEmptyMemtable cost: {}", start);
}
flushId++;
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 8018204..a6ec145 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
@@ -435,12 +435,12 @@ public class FileNodeManager implements IStatistic, IService {
throws FileNodeManagerException, FileNodeProcessorException {
long start1 = System.currentTimeMillis();
-
// get bufferwrite processor
BufferWriteProcessor bufferWriteProcessor;
String filenodeName = fileNodeProcessor.getProcessorName();
try {
bufferWriteProcessor = fileNodeProcessor.getBufferWriteProcessor(filenodeName, timestamp);
+
} catch (FileNodeProcessorException e) {
LOGGER.error("Get the bufferwrite processor failed, the filenode is {}, insert time is {}",
filenodeName, timestamp);
@@ -448,7 +448,14 @@ public class FileNodeManager implements IStatistic, IService {
updateStatHashMapWhenFail(tsRecord);
}
throw new FileNodeManagerException(e);
+ } finally {
+ long start1_1 = System.currentTimeMillis() - start1;
+ if (start1_1 > 1000) {
+ LOGGER.info("FileNodeManager.insertBufferWrite step-1-1, cost: {}", start1_1);
+ }
}
+
+ long start1_2 = System.currentTimeMillis();
// Add a new interval file to newfilelist
if (bufferWriteProcessor.isNewProcessor()) {
bufferWriteProcessor.setNewProcessor(false);
@@ -464,6 +471,10 @@ public class FileNodeManager implements IStatistic, IService {
throw new FileNodeManagerException(e);
}
}
+ start1_2 = System.currentTimeMillis() - start1_2;
+ if (start1_2 > 1000) {
+ LOGGER.info("FileNodeManager.insertBufferWrite step-1-2, cost: {}", start1_2);
+ }
start1 = System.currentTimeMillis() - start1;
if (start1 > 1000) {
@@ -471,6 +482,7 @@ public class FileNodeManager implements IStatistic, IService {
}
long start2 = System.currentTimeMillis();
+
long start2_1 = start2;
// write wal
try {
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 6e66dfb..02cd45c 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
@@ -17,6 +17,7 @@ package org.apache.iotdb.db.engine.memtable;
import java.io.IOException;
import java.util.List;
import java.util.concurrent.ConcurrentLinkedQueue;
+import org.apache.iotdb.db.engine.bufferwrite.RestorableTsFileIOWriter;
import org.apache.iotdb.db.utils.TimeValuePair;
import org.apache.iotdb.tsfile.common.conf.TSFileConfig;
import org.apache.iotdb.tsfile.file.metadata.enums.TSDataType;
@@ -145,6 +146,13 @@ public class MemTableFlushTask {
MemTablePool.getInstance().release(memTable);
LOGGER.info("Processor {} return back a memtable to MemTablePool", processorName);
flushCallBack.afterFlush(memTable, tsFileIoWriter);
+ if (tsFileIoWriter instanceof RestorableTsFileIOWriter) {
+ try {
+ ((RestorableTsFileIOWriter) tsFileIoWriter).flush();
+ } catch (IOException e) {
+ LOGGER.error("write restore file meet error", e);
+ }
+ }
long newId = tsFileIoWriter.getFlushID().incrementAndGet();
LOGGER.info("BufferWrite Processor {}, flushing a memtable into disk: io cost {}ms, new flushID in tsFileIoWriter: {}.",
processorName, ioTime, newId);
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTablePool.java b/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTablePool.java
index a1615b8..f82bfe5 100644
--- a/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTablePool.java
+++ b/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/MemTablePool.java
@@ -1,6 +1,7 @@
package org.apache.iotdb.db.engine.memtable;
import java.util.Stack;
+import org.apache.iotdb.tsfile.common.constant.SystemConstant;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -18,22 +19,28 @@ public class MemTablePool {
emptyMemTables = new Stack<>();
}
- public IMemTable getEmptyMemTable() {
+ public IMemTable getEmptyMemTable(Object applier) {
synchronized (emptyMemTables) {
if (emptyMemTables.isEmpty() && size < capacity) {
size++;
- LOGGER.info("generated a new memtable, system memtable size: {}, stack size: {}", size, emptyMemTables.size());
+ LOGGER.info("generated a new memtable for {}, system memtable size: {}, stack size: {}",
+ applier, size, emptyMemTables.size());
return new PrimitiveMemTable();
} else if (!emptyMemTables.isEmpty()){
- LOGGER.info("system memtable size: {}, stack size: {}, then get a memtable from stack", size, emptyMemTables.size());
+ LOGGER.info("system memtable size: {}, stack size: {}, then get a memtable from stack for {}",
+ size, emptyMemTables.size(), applier);
return emptyMemTables.pop();
}
}
// wait until some one has released a memtable
+ long waitStartTime = System.currentTimeMillis();
+ long lastPrintIdx = 0;
while (true) {
if(!emptyMemTables.isEmpty()) {
synchronized (emptyMemTables) {
if (!emptyMemTables.isEmpty()){
+ LOGGER.info("system memtable size: {}, stack size: {}, then get a memtable from stack for {}",
+ size, emptyMemTables.size(), applier);
return emptyMemTables.pop();
}
}
@@ -44,6 +51,11 @@ public class MemTablePool {
Thread.currentThread().interrupt();
LOGGER.error("Unexpected interruption", e);
}
+ long waitedTime = System.currentTimeMillis() - waitStartTime;
+ if (waitedTime / 2000 > lastPrintIdx) {
+ lastPrintIdx = waitedTime / 2000;
+ LOGGER.info("{} has waited for a memtable for {}ms", waitedTime);
+ }
}
}
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/engine/overflow/io/OverflowProcessor.java b/iotdb/src/main/java/org/apache/iotdb/db/engine/overflow/io/OverflowProcessor.java
index 1c2ccc4..d8cb8be 100644
--- a/iotdb/src/main/java/org/apache/iotdb/db/engine/overflow/io/OverflowProcessor.java
+++ b/iotdb/src/main/java/org/apache/iotdb/db/engine/overflow/io/OverflowProcessor.java
@@ -587,7 +587,7 @@ public class OverflowProcessor extends Processor {
//add mmd
overflowFlushMemTables.add(workSupport);
IMemTable tmpMemTableToFlush = workSupport;
- workSupport = MemTablePool.getInstance().getEmptyMemTable();
+ workSupport = MemTablePool.getInstance().getEmptyMemTable(this);
flushFuture = FlushManager.getInstance().submit(() -> flushTask("asynchronously",
tmpMemTableToFlush, walTaskId, flushId, this::removeFlushedMemTable));