This is an automated email from the ASF dual-hosted git repository. jackietien pushed a commit to branch revert-1845-addMoreTracing in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit dbfbc17e63e492206d2fc18ca186cc300f89ed7b Author: Jackie Tien <[email protected]> AuthorDate: Mon Oct 26 13:15:35 2020 +0800 Revert "[IOTDB-955] Add more tracing log" --- .../System Tools/Performance Tracing Tool.md | 18 +++---- .../System Tools/Performance Tracing Tool.md | 16 +++--- .../org/apache/iotdb/db/conf/IoTDBDescriptor.java | 3 ++ .../db/query/control/QueryResourceManager.java | 5 +- .../iotdb/db/query/control/TracingManager.java | 63 ++++++---------------- .../iotdb/db/query/reader/series/SeriesReader.java | 1 - .../org/apache/iotdb/db/service/TSServiceImpl.java | 6 +-- 7 files changed, 40 insertions(+), 72 deletions(-) diff --git a/docs/UserGuide/System Tools/Performance Tracing Tool.md b/docs/UserGuide/System Tools/Performance Tracing Tool.md index ed7f882..2bf4a00 100644 --- a/docs/UserGuide/System Tools/Performance Tracing Tool.md +++ b/docs/UserGuide/System Tools/Performance Tracing Tool.md @@ -30,18 +30,17 @@ Turn off Tracing： `IoTDB> TRACING OFF` -Since the cost of an IoTDB query mainly depends on the number of time series queried, the number of tsfile files accessed, the total number of chunks to be scanned, and the average size of each chunk (the number of data points contained in the chunk). Therefore, the current performance analysis includes the following contents: +Since the cost of an IoTDB query mainly depends on the number of time series queried, the number of tsfile files accessed, the total number of chunks to be scanned and the average size of each chunk (the number of data points contained in the chunk). Therefore, the current performance analysis includes the following contents: - Start time - Query statement - Number of series paths +- Number of tsfiles - Number of sequence files -- Statistics of each sequence file -- Number of unSequence files -- Statistics of each unSequence file +- Number of unsequence files - Number of chunks - Average size of chunks -- Total cost time +- End time ## Example @@ -51,13 +50,12 @@ For example, execute `select * from root`, the contents of the tracing log file Query Id: 2 - Start time: 2020-06-28 10:53:54.727 Query Id: 2 - Query Statement: select * from root Query Id: 2 - Number of series paths: 3 -Query Id: 2 - Number of sequence files: 1 -Query Id: 2 - SeqFile_1603336100446-1-0.tsfile root.sg.d1[1, 10000] -Query Id: 2 - Number of unsequence files: 1 -Query Id: 2 - UnSeqFile_1603354798303-2-0.tsfile root.sg.d1[9, 1000] +Query Id: 2 - Number of tsfiles: 2 +Query Id: 2 - Number of sequence files: 2 +Query Id: 2 - Number of unsequence files: 0 Query Id: 2 - Number of chunks: 3 Query Id: 2 - Average size of chunks: 4113 -Query Id: 2 - Total cost time: 11ms +Query Id: 2 - End time: 2020-06-28 10:54:44.059 ``` In order to avoid disordered output information caused by multiple queries being executed at the same time, the Query ID is added before each output information. Users can use `grep "Query ID: 2" tracing.txt` to extract all tracing information of one query. diff --git a/docs/zh/UserGuide/System Tools/Performance Tracing Tool.md b/docs/zh/UserGuide/System Tools/Performance Tracing Tool.md index 257960c..05fb5f6 100644 --- a/docs/zh/UserGuide/System Tools/Performance Tracing Tool.md +++ b/docs/zh/UserGuide/System Tools/Performance Tracing Tool.md @@ -35,13 +35,12 @@ IoTDB 支持使用 `TRACING` 语句来启用/禁用对查询语句的性能追 - Start time - Query statement - Number of series paths +- Number of tsfiles - Number of sequence files -- Statistics of each sequence file -- Number of unSequence files -- Statistics of each unSequence file +- Number of unsequence files - Number of chunks - Average size of chunks -- Total cost time +- End time ## Example @@ -51,13 +50,12 @@ IoTDB 支持使用 `TRACING` 语句来启用/禁用对查询语句的性能追 Query Id: 2 - Start time: 2020-06-28 10:53:54.727 Query Id: 2 - Query Statement: select * from root Query Id: 2 - Number of series paths: 3 -Query Id: 2 - Number of sequence files: 1 -Query Id: 2 - SeqFile_1603336100446-1-0.tsfile root.sg.d1[1, 10000] -Query Id: 2 - Number of unsequence files: 1 -Query Id: 2 - UnSeqFile_1603354798303-2-0.tsfile root.sg.d1[9, 1000] +Query Id: 2 - Number of tsfiles: 2 +Query Id: 2 - Number of sequence files: 2 +Query Id: 2 - Number of unsequence files: 0 Query Id: 2 - Number of chunks: 3 Query Id: 2 - Average size of chunks: 4113 -Query Id: 2 - Total cost time: 11ms +Query Id: 2 - End time: 2020-06-28 10:54:44.059 ``` 为了避免多个查询同时执行导致输出信息乱序，在每条输出信息前均增加了该次查询的 Query Id，用户可以使用 `grep "Query Id: 2" tracing.txt` 来提取某次查询的所有追踪信息。 diff --git a/server/src/main/java/org/apache/iotdb/db/conf/IoTDBDescriptor.java b/server/src/main/java/org/apache/iotdb/db/conf/IoTDBDescriptor.java index eb216d4..4fe9ecb 100644 --- a/server/src/main/java/org/apache/iotdb/db/conf/IoTDBDescriptor.java +++ b/server/src/main/java/org/apache/iotdb/db/conf/IoTDBDescriptor.java @@ -231,6 +231,9 @@ public class IoTDBDescriptor { conf.setSyncDir( FilePathUtils.regularizePath(conf.getSystemDir()) + IoTDBConstant.SYNC_FOLDER_NAME); + conf.setTracingDir(FilePathUtils + .regularizePath(conf.getSystemDir() + IoTDBConstant.TRACING_FOLDER_NAME)); + conf.setQueryDir( FilePathUtils.regularizePath(conf.getSystemDir()) + IoTDBConstant.QUERY_FOLDER_NAME); diff --git a/server/src/main/java/org/apache/iotdb/db/query/control/QueryResourceManager.java b/server/src/main/java/org/apache/iotdb/db/query/control/QueryResourceManager.java index 7c4a7f3..7d14885 100644 --- a/server/src/main/java/org/apache/iotdb/db/query/control/QueryResourceManager.java +++ b/server/src/main/java/org/apache/iotdb/db/query/control/QueryResourceManager.java @@ -169,8 +169,9 @@ public class QueryResourceManager { if (config.isEnablePerformanceTracing()) { boolean isprinted = false; if (seqFileNumMap.get(queryId) != null && unseqFileNumMap.get(queryId) != null) { - TracingManager.getInstance().writeTsFileInfo(queryId, seqFileNumMap.remove(queryId), - unseqFileNumMap.remove(queryId)); + TracingManager.getInstance() + .writeTsFileInfo(queryId, seqFileNumMap.remove(queryId).size(), + unseqFileNumMap.remove(queryId).size()); isprinted = true; } if (chunkNumMap.get(queryId) != null && chunkSizeMap.get(queryId) != null) { diff --git a/server/src/main/java/org/apache/iotdb/db/query/control/TracingManager.java b/server/src/main/java/org/apache/iotdb/db/query/control/TracingManager.java index ffbac49..cd23d0b 100644 --- a/server/src/main/java/org/apache/iotdb/db/query/control/TracingManager.java +++ b/server/src/main/java/org/apache/iotdb/db/query/control/TracingManager.java @@ -23,14 +23,9 @@ import java.io.File; import java.io.FileWriter; import java.io.IOException; import java.text.SimpleDateFormat; -import java.util.Iterator; -import java.util.Map; -import java.util.Set; -import java.util.concurrent.ConcurrentHashMap; import org.apache.iotdb.db.conf.IoTDBConstant; import org.apache.iotdb.db.conf.IoTDBDescriptor; import org.apache.iotdb.db.engine.fileSystem.SystemFileFactory; -import org.apache.iotdb.db.engine.storagegroup.TsFileResource; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -40,7 +35,6 @@ public class TracingManager { private static final String QUERY_ID = "Query Id: "; private static final String DATE_FORMAT = "yyyy-MM-dd HH:mm:ss.SSS"; private BufferedWriter writer; - private Map<Long, Long> queryStartTime = new ConcurrentHashMap<>(); public TracingManager(String dirName, String logFileName) { File tracingDir = SystemFileFactory.INSTANCE.getFile(dirName); @@ -66,14 +60,13 @@ public class TracingManager { return TracingManagerHelper.INSTANCE; } - public void writeQueryInfo(long queryId, String statement, long startTime, int pathsNum) - throws IOException { - queryStartTime.put(queryId, startTime); + public void writeQueryInfo(long queryId, String statement, int pathsNum) throws IOException { StringBuilder builder = new StringBuilder(); builder.append(QUERY_ID).append(queryId) .append(" - Query Statement: ").append(statement) .append("\n" + QUERY_ID).append(queryId) - .append(" - Start time: ").append(new SimpleDateFormat(DATE_FORMAT).format(startTime)) + .append(" - Start time: ") + .append(new SimpleDateFormat(DATE_FORMAT).format(System.currentTimeMillis())) .append("\n" + QUERY_ID).append(queryId) .append(" - Number of series paths: ").append(pathsNum) .append("\n"); @@ -81,13 +74,13 @@ public class TracingManager { } // for align by device query - public void writeQueryInfo(long queryId, String statement, long startTime) throws IOException { - queryStartTime.put(queryId, startTime); + public void writeQueryInfo(long queryId, String statement) throws IOException { StringBuilder builder = new StringBuilder(); builder.append(QUERY_ID).append(queryId) .append(" - Query Statement: ").append(statement) .append("\n" + QUERY_ID).append(queryId) - .append(" - Start time: ").append(new SimpleDateFormat(DATE_FORMAT).format(startTime)) + .append(" - Start time: ") + .append(new SimpleDateFormat(DATE_FORMAT).format(System.currentTimeMillis())) .append("\n"); writer.write(builder.toString()); } @@ -99,43 +92,19 @@ public class TracingManager { writer.write(builder.toString()); } - public void writeTsFileInfo(long queryId, Set<TsFileResource> seqFileResources, - Set<TsFileResource> unSeqFileResources) throws IOException { + public void writeTsFileInfo(long queryId, int seqFileNum, int unseqFileNum) throws IOException { // to avoid the disorder info of multi query // add query id as prefix of each info StringBuilder builder = new StringBuilder(QUERY_ID).append(queryId) - .append(" - Number of sequence files: ").append(seqFileResources.size()); - for (TsFileResource seqFileResource : seqFileResources) { - builder.append("\n" + QUERY_ID).append(queryId) - .append(" - SeqFile_").append(seqFileResource.getTsFile().getName()); - printTsFileStatistics(builder, seqFileResource); - } - - builder.append("\n" + QUERY_ID).append(queryId) - .append(" - Number of unSequence files: ").append(unSeqFileResources.size()); - for (TsFileResource unSeqFileResource : unSeqFileResources) { - builder.append("\n" + QUERY_ID).append(queryId) - .append(" - UnSeqFile_").append(unSeqFileResource.getTsFile().getName()); - printTsFileStatistics(builder, unSeqFileResource); - } - builder.append("\n"); + .append(" - Number of tsfiles: ").append(seqFileNum + unseqFileNum) + .append("\n" + QUERY_ID).append(queryId) + .append(" - Number of sequence files: ").append(seqFileNum) + .append("\n" + QUERY_ID).append(queryId) + .append(" - Number of unsequence files: ").append(unseqFileNum) + .append("\n"); writer.write(builder.toString()); } - // print startTime and endTime of each device, format e.g.: device1[1, 10000] - private void printTsFileStatistics(StringBuilder builder, TsFileResource tsFileResource) { - Iterator<String> deviceIter = tsFileResource.getDeviceToIndexMap().keySet().iterator(); - while (deviceIter.hasNext()) { - String device = deviceIter.next(); - builder.append(" ").append(device) - .append("[").append(tsFileResource.getStartTime(device)) - .append(", ").append(tsFileResource.getEndTime(device)).append("]"); - if (deviceIter.hasNext()) { - builder.append(", "); - } - } - } - public void writeChunksInfo(long queryId, long totalChunkNum, long totalChunkSize) throws IOException { StringBuilder builder = new StringBuilder(QUERY_ID).append(queryId) @@ -147,10 +116,10 @@ public class TracingManager { } public void writeEndTime(long queryId) throws IOException { - long endTime = System.currentTimeMillis(); StringBuilder builder = new StringBuilder(QUERY_ID).append(queryId) - .append(" - Total cost time: ").append(endTime - queryStartTime.remove(queryId)) - .append("ms\n"); + .append(" - End time: ") + .append(new SimpleDateFormat(DATE_FORMAT).format(System.currentTimeMillis())) + .append("\n"); writer.write(builder.toString()); writer.flush(); } diff --git a/server/src/main/java/org/apache/iotdb/db/query/reader/series/SeriesReader.java b/server/src/main/java/org/apache/iotdb/db/query/reader/series/SeriesReader.java index 952367b..5b9b96a 100644 --- a/server/src/main/java/org/apache/iotdb/db/query/reader/series/SeriesReader.java +++ b/server/src/main/java/org/apache/iotdb/db/query/reader/series/SeriesReader.java @@ -302,7 +302,6 @@ public class SeriesReader { List<ChunkMetadata> chunkMetadataList = FileLoaderUtils .loadChunkMetadataList(timeSeriesMetadata); chunkMetadataList.forEach(chunkMetadata -> chunkMetadata.setSeq(timeSeriesMetadata.isSeq())); - // try to calculate the total number of chunk and time-value points in chunk if (IoTDBDescriptor.getInstance().getConfig().isEnablePerformanceTracing()) { QueryResourceManager queryResourceManager = QueryResourceManager.getInstance(); diff --git a/server/src/main/java/org/apache/iotdb/db/service/TSServiceImpl.java b/server/src/main/java/org/apache/iotdb/db/service/TSServiceImpl.java index 2b66fd3..76ad37d 100644 --- a/server/src/main/java/org/apache/iotdb/db/service/TSServiceImpl.java +++ b/server/src/main/java/org/apache/iotdb/db/service/TSServiceImpl.java @@ -649,9 +649,9 @@ public class TSServiceImpl implements TSIService.Iface, ServerContext { queryId = generateQueryId(true, fetchSize, deduplicatedPathNum); if (plan instanceof QueryPlan && config.isEnablePerformanceTracing()) { if (!(plan instanceof AlignByDevicePlan)) { - TracingManager.getInstance().writeQueryInfo(queryId, statement, startTime, plan.getPaths().size()); + TracingManager.getInstance().writeQueryInfo(queryId, statement, plan.getPaths().size()); } else { - TracingManager.getInstance().writeQueryInfo(queryId, statement, startTime); + TracingManager.getInstance().writeQueryInfo(queryId, statement); } } // put it into the corresponding Set @@ -659,7 +659,7 @@ public class TSServiceImpl implements TSIService.Iface, ServerContext { statementId2QueryId.computeIfAbsent(statementId, k -> new HashSet<>()).add(queryId); if (plan instanceof AuthorPlan) { - plan.setLoginUserName(username); + ((AuthorPlan) plan).setLoginUserName(username); } // create and cache dataset QueryDataSet newDataSet = createQueryDataSet(queryId, plan);
