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/14 10:56:34 UTC
[incubator-iotdb] 01/02: add logs for memtable write
This is an automated email from the ASF dual-hosted git repository.
liurui pushed a commit to branch feature_async_close_tsfile
in repository https://gitbox.apache.org/repos/asf/incubator-iotdb.git
commit 4fa3caa4afef608b0a6f193f0998040bb2be65f1
Author: liuruiyiyang <24...@qq.com>
AuthorDate: Fri Jun 14 18:52:05 2019 +0800
add logs for memtable write
---
.../engine/bufferwrite/BufferWriteProcessor.java | 17 +++++-
.../iotdb/db/engine/memtable/AbstractMemTable.java | 7 ++-
.../monitor/collector/MemTableWriteTimeCost.java | 62 ++++++++++++++++++++++
.../apache/iotdb/db/utils/PrimitiveArrayList.java | 14 +++++
4 files changed, 98 insertions(+), 2 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 f44b417..ded049b 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
@@ -50,6 +50,8 @@ import org.apache.iotdb.db.engine.pool.FlushManager;
import org.apache.iotdb.db.engine.querycontext.ReadOnlyMemChunk;
import org.apache.iotdb.db.engine.version.VersionController;
import org.apache.iotdb.db.exception.BufferWriteProcessorException;
+import org.apache.iotdb.db.monitor.collector.MemTableWriteTimeCost;
+import org.apache.iotdb.db.monitor.collector.MemTableWriteTimeCost.MemTableWriteTimeCostType;
import org.apache.iotdb.db.qp.constant.DatetimeUtils;
import org.apache.iotdb.db.utils.ImmediateFuture;
import org.apache.iotdb.db.utils.MemUtils;
@@ -185,6 +187,7 @@ public class BufferWriteProcessor extends Processor {
* @throws BufferWriteProcessorException if a flushing operation occurs and failed.
*/
public boolean write(TSRecord tsRecord) throws BufferWriteProcessorException {
+ MemTableWriteTimeCost.getInstance().init();
long start1 = System.currentTimeMillis();
long memUsage = MemUtils.getRecordSize(tsRecord);
BasicMemController.UsageLevel level = BasicMemController.getInstance()
@@ -207,7 +210,11 @@ public class BufferWriteProcessor extends Processor {
valueCount++;
start2 = System.currentTimeMillis() - start2;
if (start2 > 1000) {
- LOGGER.info("BufferWriteProcessor.write step2 cost: {}", start2);
+ LOGGER.info("BufferWriteProcessor.write step2 of SAFE cost: {}", start2);
+ Map<MemTableWriteTimeCostType, long[]> map = MemTableWriteTimeCost.getInstance().getTimeCostMaps().get(Thread.currentThread().getName());
+ for(MemTableWriteTimeCostType type: MemTableWriteTimeCostType.values()){
+ LOGGER.info("In BufferWriteProcessor.write step2 of SAFE, {} cost {} ms, execute {} times", type, map.get(type)[1], map.get(type)[0]);
+ }
}
checkMemThreshold4Flush(memUsage);
return true;
@@ -220,6 +227,14 @@ public class BufferWriteProcessor extends Processor {
dataPoint.getValue().toString());
}
valueCount++;
+ start2 = System.currentTimeMillis() - start2;
+ if (start2 > 1000) {
+ LOGGER.info("BufferWriteProcessor.write step2 of WARNING cost: {}", start2);
+ Map<MemTableWriteTimeCostType, long[]> map = MemTableWriteTimeCost.getInstance().getTimeCostMaps().get(Thread.currentThread().getName());
+ for(MemTableWriteTimeCostType type: MemTableWriteTimeCostType.values()){
+ LOGGER.info("In BufferWriteProcessor.write step2 of WARNING, {} cost {} ms, execute {} times", type, map.get(type)[1], map.get(type)[0]);
+ }
+ }
try {
flush();
} catch (IOException e) {
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/AbstractMemTable.java b/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/AbstractMemTable.java
index 1a4f755..d6e2908 100644
--- a/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/AbstractMemTable.java
+++ b/iotdb/src/main/java/org/apache/iotdb/db/engine/memtable/AbstractMemTable.java
@@ -27,9 +27,10 @@ import java.util.Map;
import org.apache.iotdb.db.engine.modification.Deletion;
import org.apache.iotdb.db.engine.modification.Modification;
import org.apache.iotdb.db.engine.querycontext.ReadOnlyMemChunk;
+import org.apache.iotdb.db.monitor.collector.MemTableWriteTimeCost;
+import org.apache.iotdb.db.monitor.collector.MemTableWriteTimeCost.MemTableWriteTimeCostType;
import org.apache.iotdb.db.utils.TimeValuePair;
import org.apache.iotdb.tsfile.file.metadata.enums.TSDataType;
-import org.apache.iotdb.tsfile.utils.Binary;
public abstract class AbstractMemTable implements IMemTable {
@@ -76,8 +77,12 @@ public abstract class AbstractMemTable implements IMemTable {
@Override
public void write(String deviceId, String measurement, TSDataType dataType, long insertTime,
String insertValue) {
+ long start = System.currentTimeMillis();
IWritableMemChunk memSeries = createIfNotExistAndGet(deviceId, measurement, dataType);
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.WRITE_1, start);
+ start = System.currentTimeMillis();
memSeries.write(insertTime, insertValue);
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.WRITE_2, start);
}
@Override
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/monitor/collector/MemTableWriteTimeCost.java b/iotdb/src/main/java/org/apache/iotdb/db/monitor/collector/MemTableWriteTimeCost.java
new file mode 100644
index 0000000..ccf3f57
--- /dev/null
+++ b/iotdb/src/main/java/org/apache/iotdb/db/monitor/collector/MemTableWriteTimeCost.java
@@ -0,0 +1,62 @@
+package org.apache.iotdb.db.monitor.collector;
+
+import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
+
+public class MemTableWriteTimeCost {
+
+ public Map<String, Map<MemTableWriteTimeCostType, long[]>> getTimeCostMaps() {
+ return timeCostMaps;
+ }
+
+ private Map<String, Map<MemTableWriteTimeCostType, long[]>> timeCostMaps = new ConcurrentHashMap<>();
+
+ public static MemTableWriteTimeCost getInstance() {
+ return MemTableWriteTimeCostHolder.INSTANCE;
+ }
+
+ private static class MemTableWriteTimeCostHolder {
+
+ private static final MemTableWriteTimeCost INSTANCE = new MemTableWriteTimeCost();
+ }
+
+ private MemTableWriteTimeCost() {
+
+ }
+
+ public void init() {
+ if (timeCostMaps.get(Thread.currentThread().getName()) == null) {
+ Map<MemTableWriteTimeCostType, long[]> map = new ConcurrentHashMap<>();
+ for (MemTableWriteTimeCostType type : MemTableWriteTimeCostType.values()) {
+ map.put(type, new long[2]);
+ }
+ timeCostMaps.put(Thread.currentThread().getName(), map);
+ } else {
+ timeCostMaps.get(Thread.currentThread().getName()).clear();
+ for (MemTableWriteTimeCostType type : MemTableWriteTimeCostType.values()) {
+ timeCostMaps.get(Thread.currentThread().getName()).put(type, new long[2]);
+ }
+ }
+ }
+
+ public void measure(MemTableWriteTimeCostType type, long start) {
+ long elapse = System.currentTimeMillis() - start;
+ long[] a = new long[2];
+ // long[0] is the count, long[1] is the latency in ms
+ a[0] = timeCostMaps.get(Thread.currentThread().getName()).get(type)[0] + 1;
+ a[1] = timeCostMaps.get(Thread.currentThread().getName()).get(type)[1] + elapse;
+ timeCostMaps.get(Thread.currentThread().getName()).put(type, a);
+ }
+
+ public enum MemTableWriteTimeCostType {
+ EXPAND_ARRAY_1,
+ EXPAND_ARRAY_2,
+ CAPACITY_1,
+ CAPACITY_2,
+ WRITE_1,
+ WRITE_2,
+ PUT_TIMESTAMP_1,
+ PUT_TIMESTAMP_2,
+ }
+}
+
diff --git a/iotdb/src/main/java/org/apache/iotdb/db/utils/PrimitiveArrayList.java b/iotdb/src/main/java/org/apache/iotdb/db/utils/PrimitiveArrayList.java
index a473152..9fa0a7f 100644
--- a/iotdb/src/main/java/org/apache/iotdb/db/utils/PrimitiveArrayList.java
+++ b/iotdb/src/main/java/org/apache/iotdb/db/utils/PrimitiveArrayList.java
@@ -21,6 +21,8 @@ package org.apache.iotdb.db.utils;
import java.lang.reflect.Array;
import java.util.ArrayList;
import java.util.List;
+import org.apache.iotdb.db.monitor.collector.MemTableWriteTimeCost;
+import org.apache.iotdb.db.monitor.collector.MemTableWriteTimeCost.MemTableWriteTimeCostType;
public class PrimitiveArrayList {
@@ -52,6 +54,7 @@ public class PrimitiveArrayList {
private void capacity(int aimSize) {
if (currentArraySize < aimSize) {
if (currentArraySize < MAX_SIZE_OF_ONE_ARRAY) {
+ long start = System.currentTimeMillis();
// expand current Array
int newCapacity = Math.min(MAX_SIZE_OF_ONE_ARRAY, currentArraySize * 2);
values.set(currentIndex,
@@ -59,30 +62,41 @@ public class PrimitiveArrayList {
timestamps.set(currentIndex,
(long[]) expandArray(timestamps.get(currentIndex), currentArraySize, newCapacity));
currentArraySize = newCapacity;
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.CAPACITY_1, start);
} else {
+ long start = System.currentTimeMillis();
// add a new Array to the list
values.add(Array.newInstance(clazz, INITIAL_SIZE));
timestamps.add(new long[INITIAL_SIZE]);
currentIndex++;
currentArraySize = INITIAL_SIZE;
currentArrayIndex = -1;
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.CAPACITY_2, start);
}
}
}
private Object expandArray(Object array, int preLentgh, int aimLength) {
+ long start = System.currentTimeMillis();
Class arrayClass = array.getClass().getComponentType();
Object newArray = Array.newInstance(arrayClass, aimLength);
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.EXPAND_ARRAY_1, start);
+ start = System.currentTimeMillis();
System.arraycopy(array, 0, newArray, 0, preLentgh);
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.EXPAND_ARRAY_2, start);
return newArray;
}
public void putTimestamp(long timestamp, Object value) {
+ long start = System.currentTimeMillis();
capacity(currentArrayIndex + 1 + 1);
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.PUT_TIMESTAMP_1, start);
+ start = System.currentTimeMillis();
currentArrayIndex++;
timestamps.get(currentIndex)[currentArrayIndex] = timestamp;
Array.set(values.get(currentIndex), currentArrayIndex, value);
length++;
+ MemTableWriteTimeCost.getInstance().measure(MemTableWriteTimeCostType.PUT_TIMESTAMP_2, start);
}
public long getTimestamp(int index) {