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 2021/07/17 01:46:02 UTC
[iotdb] branch autoai updated (9be4412 -> 6b4fd0f)
This is an automated email from the ASF dual-hosted git repository.
qiaojialin pushed a change to branch autoai
in repository https://gitbox.apache.org/repos/asf/iotdb.git.
from 9be4412 thrift out of sequence & clientpool queue -> stack & add some logs (#3586)
new b0264a9 add insertTablet writeLog timing
new 6b4fd0f add log in ExclusiveWriteLogNode
The 2 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
Summary of changes:
.../cluster/server/member/MetaGroupMember.java | 4 +-
.../db/engine/storagegroup/TsFileProcessor.java | 5 ++
.../db/writelog/node/ExclusiveWriteLogNode.java | 64 ++++++++++++++++++----
3 files changed, 59 insertions(+), 14 deletions(-)
[iotdb] 01/02: add insertTablet writeLog timing
Posted by qi...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
qiaojialin pushed a commit to branch autoai
in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit b0264a9ebe0cd011e3809662c751abb6248edef3
Author: qiaojialin <64...@qq.com>
AuthorDate: Fri Jul 16 23:46:56 2021 +0800
add insertTablet writeLog timing
---
.../org/apache/iotdb/db/engine/storagegroup/TsFileProcessor.java | 5 +++++
1 file changed, 5 insertions(+)
diff --git a/server/src/main/java/org/apache/iotdb/db/engine/storagegroup/TsFileProcessor.java b/server/src/main/java/org/apache/iotdb/db/engine/storagegroup/TsFileProcessor.java
index ddec381..4675ecd 100644
--- a/server/src/main/java/org/apache/iotdb/db/engine/storagegroup/TsFileProcessor.java
+++ b/server/src/main/java/org/apache/iotdb/db/engine/storagegroup/TsFileProcessor.java
@@ -253,11 +253,16 @@ public class TsFileProcessor {
}
try {
workMemTable.insertTablet(insertTabletPlan, start, end);
+ long startTime = System.currentTimeMillis();
if (IoTDBDescriptor.getInstance().getConfig().isEnableWal()) {
insertTabletPlan.setStart(start);
insertTabletPlan.setEnd(end);
getLogNode().write(insertTabletPlan);
}
+ long elapsed = System.currentTimeMillis() - startTime;
+ if (elapsed > 5000) {
+ logger.error("write wal slowly : cost {}ms", elapsed);
+ }
} catch (Exception e) {
for (int i = start; i < end; i++) {
results[i] = RpcUtils.getStatus(TSStatusCode.INTERNAL_SERVER_ERROR, e.getMessage());
[iotdb] 02/02: add log in ExclusiveWriteLogNode
Posted by qi...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
qiaojialin pushed a commit to branch autoai
in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit 6b4fd0f08dc089a5277fae16503d658ceb702f39
Author: qiaojialin <64...@qq.com>
AuthorDate: Sat Jul 17 09:44:35 2021 +0800
add log in ExclusiveWriteLogNode
---
.../cluster/server/member/MetaGroupMember.java | 4 +-
.../db/writelog/node/ExclusiveWriteLogNode.java | 64 ++++++++++++++++++----
2 files changed, 54 insertions(+), 14 deletions(-)
diff --git a/cluster/src/main/java/org/apache/iotdb/cluster/server/member/MetaGroupMember.java b/cluster/src/main/java/org/apache/iotdb/cluster/server/member/MetaGroupMember.java
index c978208..1cc4ad9 100644
--- a/cluster/src/main/java/org/apache/iotdb/cluster/server/member/MetaGroupMember.java
+++ b/cluster/src/main/java/org/apache/iotdb/cluster/server/member/MetaGroupMember.java
@@ -535,9 +535,9 @@ public class MetaGroupMember extends RaftMember {
private void generateNodeReport() {
try {
- if (logger.isInfoEnabled()) {
+ if (logger.isDebugEnabled()) {
NodeReport report = genNodeReport();
- logger.info(report.toString());
+ logger.debug(report.toString());
}
} catch (Exception e) {
logger.error("{} exception occurred when generating node report", name, e);
diff --git a/server/src/main/java/org/apache/iotdb/db/writelog/node/ExclusiveWriteLogNode.java b/server/src/main/java/org/apache/iotdb/db/writelog/node/ExclusiveWriteLogNode.java
index c947963..3d55e12 100644
--- a/server/src/main/java/org/apache/iotdb/db/writelog/node/ExclusiveWriteLogNode.java
+++ b/server/src/main/java/org/apache/iotdb/db/writelog/node/ExclusiveWriteLogNode.java
@@ -59,12 +59,12 @@ public class ExclusiveWriteLogNode implements WriteLogNode, Comparable<Exclusive
private IoTDBConfig config = IoTDBDescriptor.getInstance().getConfig();
- private ByteBuffer logBufferWorking;
- private ByteBuffer logBufferIdle;
- private ByteBuffer logBufferFlushing;
+ private volatile ByteBuffer logBufferWorking;
+ private volatile ByteBuffer logBufferIdle;
+ private volatile ByteBuffer logBufferFlushing;
// used for the convenience of deletion
- private ByteBuffer[] bufferArray;
+ private volatile ByteBuffer[] bufferArray;
private final Object switchBufferCondition = new Object();
private ReentrantLock lock = new ReentrantLock();
@@ -77,7 +77,7 @@ public class ExclusiveWriteLogNode implements WriteLogNode, Comparable<Exclusive
private int bufferedLogNum = 0;
- private boolean deleted;
+ private boolean deleted = false;
/**
* constructor of ExclusiveWriteLogNode.
@@ -105,7 +105,12 @@ public class ExclusiveWriteLogNode implements WriteLogNode, Comparable<Exclusive
if (deleted) {
throw new IOException("WAL node deleted");
}
+ long start = System.currentTimeMillis();
lock.lock();
+ long elapse = System.currentTimeMillis() - start;
+ if (elapse > 5000) {
+ logger.warn("[wal] ExclusiveWriteLogNode lock got cost: {}ms", elapse);
+ }
try {
putLog(plan);
if (bufferedLogNum >= config.getFlushWalThreshold()) {
@@ -151,7 +156,7 @@ public class ExclusiveWriteLogNode implements WriteLogNode, Comparable<Exclusive
}
logger.debug("Log node {} closed successfully", identifier);
} catch (IOException e) {
- logger.error("Cannot close log node {} because:", identifier, e);
+ logger.warn("Cannot close log node {} because:", identifier, e);
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
logger.warn("Waiting for current buffer being flushed interrupted");
@@ -232,28 +237,33 @@ public class ExclusiveWriteLogNode implements WriteLogNode, Comparable<Exclusive
FileUtils.forceDelete(logFile);
logger.info("Log node {} cleaned old file", identifier);
} catch (IOException e) {
- logger.error("Old log file {} of {} cannot be deleted", logFile.getName(), identifier, e);
+ logger.warn("Old log file {} of {} cannot be deleted", logFile.getName(), identifier, e);
}
}
}
private void forceWal() {
+ logger.warn("[wal] {} forceWal try to start", this.hashCode());
lock.lock();
+ logger.warn("[wal] {} forceWal start", this.hashCode());
try {
try {
if (currentFileWriter != null) {
currentFileWriter.force();
}
} catch (IOException e) {
- logger.error("Log node {} force failed.", identifier, e);
+ logger.warn("Log node {} force failed.", identifier, e);
}
} finally {
lock.unlock();
+ logger.warn("[wal] {} forceWal end", this.hashCode());
}
}
private void sync() {
+ logger.warn("[wal] {} sync try to start", this.hashCode());
lock.lock();
+ logger.warn("[wal] {} sync start", this.hashCode());
try {
if (bufferedLogNum == 0) {
return;
@@ -272,18 +282,26 @@ public class ExclusiveWriteLogNode implements WriteLogNode, Comparable<Exclusive
logger.warn("can not found file {}", identifier, e);
} finally {
lock.unlock();
+ logger.warn("[wal] {} sync end", this.hashCode());
}
}
private void flushBuffer(ILogWriter writer) {
+ logger.warn("[wal] {} flushBuffer start", this.hashCode());
+ long start = System.currentTimeMillis();
try {
writer.write(logBufferFlushing);
} catch (ClosedChannelException e) {
// ignore
} catch (IOException e) {
- logger.error("Log node {} sync failed, change system mode to read-only", identifier, e);
+ logger.warn("Log node {} sync failed, change system mode to read-only", identifier, e);
IoTDBDescriptor.getInstance().getConfig().setReadOnly(true);
return;
+ } finally {
+ long elapse = System.currentTimeMillis() - start;
+ if (elapse > 5000) {
+ logger.warn("[wal] flushBuffer cost: {}ms", elapse);
+ }
}
logBufferFlushing.clear();
@@ -292,40 +310,62 @@ public class ExclusiveWriteLogNode implements WriteLogNode, Comparable<Exclusive
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
+ logger.warn("[wal] {} flushBuffer end", this.hashCode());
}
private void switchBufferWorkingToFlushing() throws InterruptedException {
+ logger.warn("[wal] {} switchBufferWorkingToFlushing start", this.hashCode());
+ long start = System.currentTimeMillis();
synchronized (switchBufferCondition) {
while (logBufferFlushing != null && !deleted) {
- switchBufferCondition.wait();
+ switchBufferCondition.wait(100);
}
logBufferFlushing = logBufferWorking;
logBufferWorking = null;
switchBufferCondition.notifyAll();
}
+ long elapse = System.currentTimeMillis() - start;
+ if (elapse > 5000) {
+ logger.warn("[wal] switch Working -> Flushing cost: {}ms", elapse);
+ }
+ logger.warn("[wal] {} switchBufferWorkingToFlushing end", this.hashCode());
}
private void switchBufferIdleToWorking() throws InterruptedException {
+ logger.warn("[wal] {} switchBufferIdleToWorking start", this.hashCode());
+ long start = System.currentTimeMillis();
synchronized (switchBufferCondition) {
while (logBufferIdle == null && !deleted) {
- switchBufferCondition.wait();
+ switchBufferCondition.wait(100);
}
logBufferWorking = logBufferIdle;
logBufferIdle = null;
switchBufferCondition.notifyAll();
}
+ long elapse = System.currentTimeMillis() - start;
+ if (elapse > 5000) {
+ logger.warn("[wal] switch Idle -> Working cost: {}ms", elapse);
+ }
+ logger.warn("[wal] {} switchBufferIdleToWorking end", this.hashCode());
}
private void switchBufferFlushingToIdle() throws InterruptedException {
+ logger.warn("[wal] {} switchBufferFlushingToIdle start", this.hashCode());
+ long start = System.currentTimeMillis();
synchronized (switchBufferCondition) {
while (logBufferIdle != null && !deleted) {
- switchBufferCondition.wait();
+ switchBufferCondition.wait(100);
}
logBufferIdle = logBufferFlushing;
logBufferIdle.clear();
logBufferFlushing = null;
switchBufferCondition.notifyAll();
}
+ long elapse = System.currentTimeMillis() - start;
+ if (elapse > 5000) {
+ logger.warn("[wal] switch Flushing -> Idle cost: {}ms", elapse);
+ }
+ logger.warn("[wal] {} switchBufferFlushingToIdle end", this.hashCode());
}
private ILogWriter getCurrentFileWriter() throws FileNotFoundException {