From 2f820dde17a21fa519c1ff803c6f564153fa1549 Mon Sep 17 00:00:00 2001
From: Todd Lipcon <todd@apache.org>
Date: Wed, 21 Mar 2012 18:14:09 +0000
Subject: [PATCH] HDFS-309. FSEditLog should log progress during replay.
 Contributed by Sho Shimauchi.

git-svn-id: https://svn.apache.org/repos/asf/hadoop/common/trunk@1303485 13f79535-47bb-0310-9956-ffa450edef68
---
 hadoop-hdfs-project/hadoop-hdfs/CHANGES.txt   |  3 ++
 .../hdfs/server/namenode/FSEditLogLoader.java | 37 +++++++++++++++++++
 .../server/namenode/TestFSEditLogLoader.java  |  1 +
 3 files changed, 41 insertions(+)

diff --git a/hadoop-hdfs-project/hadoop-hdfs/CHANGES.txt b/hadoop-hdfs-project/hadoop-hdfs/CHANGES.txt
index 4c0f825a2e5..f65a8ea9348 100644
--- a/hadoop-hdfs-project/hadoop-hdfs/CHANGES.txt
+++ b/hadoop-hdfs-project/hadoop-hdfs/CHANGES.txt
@@ -55,6 +55,9 @@ Trunk (unreleased changes)
     HDFS-3091. Update the usage limitations of ReplaceDatanodeOnFailure policy in
     the config description for the smaller clusters. (szetszwo via umamahesh)
 
+    HDFS-309. FSEditLog should log progress during replay. (Sho Shimauchi
+    via todd)
+
   OPTIMIZATIONS
 
     HDFS-2834. Add a ByteBuffer-based read API to DFSInputStream.
diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSEditLogLoader.java b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSEditLogLoader.java
index 7c241071504..aa6b70cf4e3 100644
--- a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSEditLogLoader.java
+++ b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSEditLogLoader.java
@@ -25,6 +25,8 @@ import java.io.InputStream;
 import java.util.Arrays;
 import java.util.EnumMap;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 import org.apache.hadoop.classification.InterfaceAudience;
 import org.apache.hadoop.classification.InterfaceStability;
 import org.apache.hadoop.fs.permission.PermissionStatus;
@@ -67,6 +69,8 @@ import com.google.common.base.Joiner;
 @InterfaceAudience.Private
 @InterfaceStability.Evolving
 public class FSEditLogLoader {
+  static final Log LOG = LogFactory.getLog(FSEditLogLoader.class.getName());
+  static long REPLAY_TRANSACTION_LOG_INTERVAL = 1000; // 1sec
   private final FSNamesystem fsNamesys;
 
   public FSEditLogLoader(FSNamesystem fsNamesys) {
@@ -108,6 +112,10 @@ public class FSEditLogLoader {
     EnumMap<FSEditLogOpCodes, Holder<Integer>> opCounts =
       new EnumMap<FSEditLogOpCodes, Holder<Integer>>(FSEditLogOpCodes.class);
 
+    if (LOG.isTraceEnabled()) {
+      LOG.trace("Acquiring write lock to replay edit log");
+    }
+
     fsNamesys.writeLock();
     fsDir.writeLock();
 
@@ -115,6 +123,16 @@ public class FSEditLogLoader {
     Arrays.fill(recentOpcodeOffsets, -1);
 
     long txId = expectedStartingTxId - 1;
+    long lastTxId = in.getLastTxId();
+    long numTxns = (lastTxId - expectedStartingTxId) + 1;
+
+    long lastLogTime = now();
+
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("edit log length: " + in.length() + ", start txid: "
+          + expectedStartingTxId + ", last txid: " + lastTxId);
+    }
+
     try {
       try {
         while (true) {
@@ -151,6 +169,15 @@ public class FSEditLogLoader {
             FSImage.LOG.error(errorMessage);
             throw new IOException(errorMessage, t);
           }
+
+          // log progress
+          if (now() - lastLogTime > REPLAY_TRANSACTION_LOG_INTERVAL) {
+            int percent = Math.round((float) txId / numTxns * 100);
+            LOG.info("replaying edit log: " + txId + "/" + numTxns
+                + " transactions completed. (" + percent + "%)");
+            lastLogTime = now();
+          }
+
           numEdits++;
         }
       } catch (IOException ex) {
@@ -162,6 +189,11 @@ public class FSEditLogLoader {
     } finally {
       fsDir.writeUnlock();
       fsNamesys.writeUnlock();
+
+      if (LOG.isTraceEnabled()) {
+        LOG.trace("replaying edit log finished");
+      }
+
       if (FSImage.LOG.isDebugEnabled()) {
         dumpOpCounts(opCounts);
       }
@@ -172,6 +204,11 @@ public class FSEditLogLoader {
   @SuppressWarnings("deprecation")
   private void applyEditLogOp(FSEditLogOp op, FSDirectory fsDir,
       int logVersion) throws IOException {
+
+    if (LOG.isTraceEnabled()) {
+      LOG.trace("replaying edit log: " + op);
+    }
+
     switch (op.opCode) {
     case OP_ADD: {
       AddCloseOp addCloseOp = (AddCloseOp)op;
diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSEditLogLoader.java b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSEditLogLoader.java
index fd1733a584a..98605e1f4e1 100644
--- a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSEditLogLoader.java
+++ b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSEditLogLoader.java
@@ -52,6 +52,7 @@ public class TestFSEditLogLoader {
   
   static {
     ((Log4JLogger)FSImage.LOG).getLogger().setLevel(Level.ALL);
+    ((Log4JLogger)FSEditLogLoader.LOG).getLogger().setLevel(Level.ALL);
   }
   
   private static final File TEST_DIR = new File(