SOLR-6403: TransactionLog replay status logging.

git-svn-id: https://svn.apache.org/repos/asf/lucene/dev/trunk@1620166 13f79535-47bb-0310-9956-ffa450edef68

solr/CHANGES.txt

@@ -112,6 +112,11 @@ Apache ZooKeeper 3.4.6
 Detailed Change List
 ----------------------
 
+New Features
+----------------------
+
+* SOLR-6403: TransactionLog replay status logging. (Mark Miller)
+
 Bug Fixes
 ----------------------
 

solr/core/src/java/org/apache/solr/update/HdfsTransactionLog.java

@@ -422,6 +422,16 @@ public class HdfsTransactionLog extends TransactionLog {
       }
     }
     
+    @Override
+    public long currentPos() {
+      return fis.position();
+    }
+    
+    @Override
+    public long currentSize() {
+      return sz;
+    }
+
   }
 
   public class HDFSReverseReader extends ReverseReader {

solr/core/src/java/org/apache/solr/update/TransactionLog.java

@@ -647,6 +647,18 @@ public class TransactionLog {
       }
     }
 
+    // returns best effort current position
+    // for info purposes
+    public long currentPos() {
+      return fis.position();
+    }
+    
+    // returns best effort current size
+    // for info purposes
+    public long currentSize() throws IOException {
+      return channel.size();
+    }
+
   }
 
   public abstract class ReverseReader {

solr/core/src/java/org/apache/solr/update/UpdateLog.java

@@ -24,6 +24,7 @@ import java.io.File;
 import java.io.FileNotFoundException;
 import java.io.FilenameFilter;
 import java.io.IOException;
+import java.text.DecimalFormat;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collection;
@@ -68,6 +69,7 @@ import org.slf4j.LoggerFactory;
 
 /** @lucene.experimental */
 public class UpdateLog implements PluginInfoInitialized {
+  private static final long STATUS_TIME = TimeUnit.NANOSECONDS.convert(60, TimeUnit.SECONDS);
   public static String LOG_FILENAME_PATTERN = "%s.%019d";
   public static String TLOG_NAME="tlog";
 
@@ -1243,7 +1245,7 @@ public class UpdateLog implements PluginInfoInitialized {
     public void doReplay(TransactionLog translog) {
       try {
         loglog.warn("Starting log replay " + translog + " active="+activeLog + " starting pos=" + recoveryInfo.positionOfStart);
-
+        long lastStatusTime = System.nanoTime();
         tlogReader = translog.getReader(recoveryInfo.positionOfStart);
 
         // NOTE: we don't currently handle a core reload during recovery.  This would cause the core
@@ -1254,12 +1256,27 @@ public class UpdateLog implements PluginInfoInitialized {
 
         long commitVersion = 0;
         int operationAndFlags = 0;
+        long nextCount = 0;
 
         for(;;) {
           Object o = null;
           if (cancelApplyBufferUpdate) break;
           try {
             if (testing_logReplayHook != null) testing_logReplayHook.run();
+            if (nextCount++ % 1000 == 0) {
+              long now = System.nanoTime();
+              if (now - lastStatusTime > STATUS_TIME) {
+                lastStatusTime = now;
+                long cpos = tlogReader.currentPos();
+                long csize = tlogReader.currentSize();
+                loglog.info(
+                        "log replay status {} active={} starting pos={} current pos={} current size={} % read={}",
+                        translog, activeLog, recoveryInfo.positionOfStart, cpos, csize,
+                        new DecimalFormat("###").format(cpos / (double) csize * 100));
+                
+              }
+            }
+            
             o = null;
             o = tlogReader.next();
             if (o == null && activeLog) {