You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@iotdb.apache.org by hx...@apache.org on 2020/06/26 15:33:57 UTC

[incubator-iotdb] branch master updated: [IOTDB-726] fix the lineNumber of mlog/snapshot is incorrect after restarting the server (#1416)

This is an automated email from the ASF dual-hosted git repository.

hxd pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-iotdb.git


The following commit(s) were added to refs/heads/master by this push:
     new 6c76ec3  [IOTDB-726] fix the lineNumber of mlog/snapshot is incorrect after restarting the server  (#1416)
6c76ec3 is described below

commit 6c76ec3104a1d7330a72de767058b0f191926ffe
Author: Xiangdong Huang <hu...@tsinghua.edu.cn>
AuthorDate: Fri Jun 26 23:33:47 2020 +0800

    [IOTDB-726] fix the lineNumber of mlog/snapshot is incorrect after restarting the server  (#1416)
    
    * fix error that the line number error after restart the server while mlog.txt exists but snapshot file does not exist
    
    * add debug log for testing time cost of deserialize from snapshot and mlog
---
 .../org/apache/iotdb/db/metadata/MLogWriter.java   | 10 ++-
 .../org/apache/iotdb/db/metadata/MManager.java     | 96 ++++++++++++++++------
 .../java/org/apache/iotdb/db/service/IoTDB.java    |  5 +-
 3 files changed, 84 insertions(+), 27 deletions(-)

diff --git a/server/src/main/java/org/apache/iotdb/db/metadata/MLogWriter.java b/server/src/main/java/org/apache/iotdb/db/metadata/MLogWriter.java
index 0b9ab3e..18115d3 100644
--- a/server/src/main/java/org/apache/iotdb/db/metadata/MLogWriter.java
+++ b/server/src/main/java/org/apache/iotdb/db/metadata/MLogWriter.java
@@ -169,4 +169,12 @@ public class MLogWriter {
   int getLineNumber() {
     return lineNumber;
   }
-}
\ No newline at end of file
+
+  /**
+   * only used for initialize a mlog file writer.
+   * @param number
+   */
+  void setLineNumber(int number) {
+    lineNumber = number;
+  }
+}
diff --git a/server/src/main/java/org/apache/iotdb/db/metadata/MManager.java b/server/src/main/java/org/apache/iotdb/db/metadata/MManager.java
index 16847ca..79f60c1 100644
--- a/server/src/main/java/org/apache/iotdb/db/metadata/MManager.java
+++ b/server/src/main/java/org/apache/iotdb/db/metadata/MManager.java
@@ -205,7 +205,7 @@ public class MManager {
       tagLogFile = new TagLogFile(config.getSchemaDir(), MetadataConstant.TAG_LOG);
 
       isRecovering = true;
-      initFromLog(logFile);
+      int lineNumber = initFromLog(logFile);
 
       if (config.isEnableParameterAdapter()) {
         List<String> storageGroups = mtree.getAllStorageGroupNames();
@@ -218,6 +218,7 @@ public class MManager {
       }
 
       logWriter = new MLogWriter(config.getSchemaDir(), MetadataConstant.METADATA_LOG);
+      logWriter.setLineNumber(lineNumber);
       isRecovering = false;
     } catch (IOException | MetadataException e) {
       mtree = new MTree();
@@ -226,7 +227,14 @@ public class MManager {
     initialized = true;
   }
 
-  private void initFromLog(File logFile) throws IOException {
+  /**
+   *
+   * @param logFile
+   * @return line number of the logFile
+   * @throws IOException
+   */
+  @SuppressWarnings("squid:S3776")
+  private int initFromLog(File logFile) throws IOException {
     File tmpFile = SystemFileFactory.INSTANCE.getFile(mtreeSnapshotTmpPath);
     if (tmpFile.exists()) {
       logger.warn("Creating MTree snapshot not successful before crashing...");
@@ -234,29 +242,46 @@ public class MManager {
     }
 
     File mtreeSnapshot = SystemFileFactory.INSTANCE.getFile(mtreeSnapshotPath);
+    long time = System.currentTimeMillis();
     if (!mtreeSnapshot.exists()) {
       mtree = new MTree();
     } else {
       mtree = MTree.deserializeFrom(mtreeSnapshot);
+      lastSnapshotLogLineNumber = mtree.getSnapshotLineNumber();
     }
+    logger.debug("spend {} ms to deserialize mtree from snapshot", System.currentTimeMillis() - time);
+
+    time = System.currentTimeMillis();
     // init the metadata from the operation log
     if (logFile.exists()) {
+      int idx = 0;
       try (FileReader fr = new FileReader(logFile);
           BufferedReader br = new BufferedReader(fr)) {
         String cmd;
-        int idx = 0;
         while (idx < mtree.getSnapshotLineNumber()) {
           cmd = br.readLine();
+          if (cmd == null) {
+            throw new IOException(String
+                .format("mtree snapshot file has %d lines but the mlog.txt has only %d lines.",
+                    mtree.getSnapshotLineNumber(), idx));
+          }
           idx++;
         }
         while ((cmd = br.readLine()) != null) {
           try {
             operation(cmd);
+            idx++;
           } catch (Exception e) {
             logger.error("Can not operate cmd {}", cmd, e);
           }
         }
       }
+      logger.debug("spend {} ms to deserialize mtree from mlog.txt", System.currentTimeMillis() - time);
+      return idx;
+    } else if (mtreeSnapshot.exists()) {
+      throw new IOException("mtree snapshot file exists but mlog.txt does not exist.");
+    } else {
+      return 0;
     }
   }
 
@@ -1773,31 +1798,52 @@ public class MManager {
   }
 
   private void checkMTreeModified() {
-    if (System.currentTimeMillis() - logFile.lastModified() < mtreeSnapshotThresholdTime) {
-      logger.info("MTree snapshot is not created because of active modification");
-    } else if (logWriter.getLineNumber() - lastSnapshotLogLineNumber < mtreeSnapshotInterval) {
-      logger.info(
-          "MTree snapshot need not be created. Current mlog line number: {}, last snapshot line number: {}",
-          logWriter.getLineNumber(), lastSnapshotLogLineNumber);
+    if (logWriter == null || logFile == null) {
+      //the logWriter is not initialized now, we skip the check once.
+      return;
+    }
+    if (System.currentTimeMillis() - logFile.lastModified() >= mtreeSnapshotThresholdTime
+        && logWriter.getLineNumber() > lastSnapshotLogLineNumber) {
+      logger.info("Start creating MTree snapshot, because {} ms elaspse.", System.currentTimeMillis() - logFile.lastModified());
+      createSnapshot();
+    } else if (logWriter.getLineNumber() - lastSnapshotLogLineNumber >= mtreeSnapshotInterval) {
+      logger.info("Start creating MTree snapshot, because of {} new lines are added.", logWriter.getLineNumber() - lastSnapshotLogLineNumber);
+      createSnapshot();
     } else {
-      lock.readLock().lock();
-      logger.info("Start creating MTree snapshot. This may take a while...");
-      try {
-        mtree.serializeTo(mtreeSnapshotTmpPath, logWriter.getLineNumber());
-        lastSnapshotLogLineNumber = logWriter.getLineNumber();
-        File tmpFile = SystemFileFactory.INSTANCE.getFile(mtreeSnapshotTmpPath);
-        File snapshotFile = SystemFileFactory.INSTANCE.getFile(mtreeSnapshotPath);
-        if (snapshotFile.exists()) {
-          Files.delete(snapshotFile.toPath());
-        }
-        if (tmpFile.renameTo(snapshotFile)) {
-          logger.info("Finish creating MTree snapshot to {}.", mtreeSnapshotPath);
+      if (logger.isDebugEnabled()) {
+        logger.debug(
+            "MTree snapshot need not be created. Current mlog line number: {}, last snapshot line number: {}, time difference from last modification: {}ms",
+            logWriter.getLineNumber(), lastSnapshotLogLineNumber,
+            System.currentTimeMillis() - logFile.lastModified());
+      }
+    }
+  }
+
+  private void createSnapshot() {
+    lock.readLock().lock();
+    long time = System.currentTimeMillis();
+    try {
+      mtree.serializeTo(mtreeSnapshotTmpPath, logWriter.getLineNumber());
+      lastSnapshotLogLineNumber = logWriter.getLineNumber();
+      File tmpFile = SystemFileFactory.INSTANCE.getFile(mtreeSnapshotTmpPath);
+      File snapshotFile = SystemFileFactory.INSTANCE.getFile(mtreeSnapshotPath);
+      if (snapshotFile.exists()) {
+        Files.delete(snapshotFile.toPath());
+      }
+      if (tmpFile.renameTo(snapshotFile)) {
+        logger.info("Finish creating MTree snapshot to {}, spend {}ms.", mtreeSnapshotPath, System.currentTimeMillis() - time);
+      }
+    } catch (IOException e) {
+      logger.warn("Failed to create MTree snapshot to {}", mtreeSnapshotPath, e);
+      if (SystemFileFactory.INSTANCE.getFile(mtreeSnapshotTmpPath).exists()) {
+        try {
+          Files.delete(SystemFileFactory.INSTANCE.getFile(mtreeSnapshotTmpPath).toPath());
+        } catch (IOException e1) {
+          logger.warn("delete file {} failed: {}", mtreeSnapshotTmpPath, e1.getMessage());
         }
-      } catch (IOException e) {
-        logger.warn("Failed to create MTree snapshot to {}", mtreeSnapshotPath, e);
-      } finally {
-        lock.readLock().unlock();
       }
+    } finally {
+      lock.readLock().unlock();
     }
   }
 }
diff --git a/server/src/main/java/org/apache/iotdb/db/service/IoTDB.java b/server/src/main/java/org/apache/iotdb/db/service/IoTDB.java
index eedf20d..dc3ffa6 100644
--- a/server/src/main/java/org/apache/iotdb/db/service/IoTDB.java
+++ b/server/src/main/java/org/apache/iotdb/db/service/IoTDB.java
@@ -89,7 +89,7 @@ public class IoTDB implements IoTDBMBean {
 
     Runtime.getRuntime().addShutdownHook(new IoTDBShutdownHook());
     setUncaughtExceptionHandler();
-
+    logger.info("recover the schema...");
     initMManager();
     registerManager.register(JMXService.getInstance());
     registerManager.register(FlushManager.getInstance());
@@ -131,7 +131,10 @@ public class IoTDB implements IoTDBMBean {
   }
 
   private void initMManager() {
+    long time = System.currentTimeMillis();
     MManager.getInstance().init();
+    long end = System.currentTimeMillis() - time;
+    logger.info("spend {}ms to recover schema.", end);
     IoTDBConfigDynamicAdapter.getInstance().setInitialized(true);
     logger.info(
         "After initializing, max memTable num is {}, tsFile threshold is {}, memtableSize is {}",