HADOOP-5533. Recovery duration shown on the jobtracker webpage is inaccurate. Contributed by Amar Kamat.

git-svn-id: https://svn.apache.org/repos/asf/hadoop/core/trunk@765887 13f79535-47bb-0310-9956-ffa450edef68

CHANGES.txt

@@ -1261,6 +1261,9 @@ Release 0.20.0 - Unreleased
     HADOOP-5655. TestMRServerPorts fails on java.net.BindException. (Devaraj
     Das via hairong)
 
+    HADOOP-5533. Recovery duration shown on the jobtracker webpage is 
+    inaccurate. (Amar Kamat via sharad)
+
 Release 0.19.2 - Unreleased
 
   BUG FIXES

src/mapred/org/apache/hadoop/mapred/JobTracker.java

@@ -1199,13 +1199,15 @@ public class JobTracker implements MRConstants, InterTrackerProtocol,
     }
 
     public void recover() {
+      long recoveryProcessStartTime = System.currentTimeMillis();
       if (!shouldRecover()) {
         // clean up jobs structure
         jobsToRecover.clear();
         return;
       }
 
-      LOG.info("Restart count of the jobtracker : " + restartCount);
+      LOG.info("Starting the recovery process with restart count : " 
+               + restartCount);
 
       // I. Init the jobs and cache the recovered job history filenames
       Map<JobID, Path> jobHistoryFilenameMap = new HashMap<JobID, Path>();
@@ -1261,6 +1263,11 @@ public class JobTracker implements MRConstants, InterTrackerProtocol,
         }
       }
 
+      LOG.info("Took a total of " 
+               + StringUtils.formatTime(System.currentTimeMillis() 
+                                        - recoveryProcessStartTime) 
+               + " for recovering filenames of all the jobs from history.");
+
       long recoveryStartTime = System.currentTimeMillis();
 
       // II. Recover each job
@@ -1318,14 +1325,21 @@ public class JobTracker implements MRConstants, InterTrackerProtocol,
         }
       }
 
-      recoveryDuration = System.currentTimeMillis() - recoveryStartTime;
+      long recoveryProcessEndTime = System.currentTimeMillis();
+      LOG.info("Took a total of " 
+               + StringUtils.formatTime(recoveryProcessEndTime
+                                        - recoveryStartTime) 
+               + " for parsing and recovering all the jobs from history.");
+
+      recoveryDuration = recoveryProcessEndTime - recoveryProcessStartTime;
+      LOG.info("Took a total of " + StringUtils.formatTime(recoveryDuration) 
+               + " for the whole recovery process.");
       hasRecovered = true;
 
       // III. Finalize the recovery
       synchronized (trackerExpiryQueue) {
         // Make sure that the tracker statuses in the expiry-tracker queue
         // are updated
-        long now = System.currentTimeMillis();
         int size = trackerExpiryQueue.size();
         for (int i = 0; i < size ; ++i) {
           // Get the first status
@@ -1335,14 +1349,14 @@ public class JobTracker implements MRConstants, InterTrackerProtocol,
           trackerExpiryQueue.remove(status);
 
           // Set the new time
-          status.setLastSeen(now);
+          status.setLastSeen(recoveryProcessEndTime);
 
           // Add back to get the sorted list
           trackerExpiryQueue.add(status);
         }
       }
 
-      LOG.info("Restoration complete");
+      LOG.info("Restoration done. Recovery complete!");
     }
     
     int totalEventsRecovered() {