hbase-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From mbau...@apache.org
Subject svn commit: r1384679 - in /hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver: SplitLogWorker.java wal/HLogSplitter.java
Date Fri, 14 Sep 2012 08:08:31 GMT
Author: mbautin
Date: Fri Sep 14 08:08:31 2012
New Revision: 1384679

URL: http://svn.apache.org/viewvc?rev=1384679&view=rev
Log:
[0.89-fb] add debug message to account for split log timing

Summary: Instrumenting split log methods to find out the bottleneck

Test Plan:
trivial change. deploy to dev cluster to see logs.
  will deploy to dark launch and collect the stats.

Reviewers: kannan, kranganathan, avf, pkhemani

Reviewed By: kranganathan

CC: hbase-eng@

Differential Revision: https://phabricator.fb.com/D561619

Modified:
    hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/SplitLogWorker.java
    hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLogSplitter.java

Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/SplitLogWorker.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/SplitLogWorker.java?rev=1384679&r1=1384678&r2=1384679&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/SplitLogWorker.java
(original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/SplitLogWorker.java
Fri Sep 14 08:08:31 2012
@@ -115,9 +115,17 @@ public class SplitLogWorker implements R
       public Status exec(String filename, CancelableProgressable p) {
         Path rootdir;
         FileSystem fs;
+        StringBuilder timingInfo = new StringBuilder();
+        long t0, t1;
+        t0 = System.currentTimeMillis();
         try {
           rootdir = FSUtils.getRootDir(conf);
           fs = rootdir.getFileSystem(conf);
+
+          t1  = System.currentTimeMillis();
+          timingInfo.append("getFileSystem took " + (t1-t0) + " ms. ");
+          t0 = t1;
+
         } catch (IOException e) {
           LOG.warn("could not find root dir or fs", e);
           return Status.RESIGNED;
@@ -129,6 +137,11 @@ public class SplitLogWorker implements R
           FileStatus st;
           try {
           st = fs.getFileStatus(new Path(filename));
+
+          t1  = System.currentTimeMillis();
+          timingInfo.append("getFileStatus took " + (t1-t0) + " ms. ");
+          t0 = t1;
+
           } catch (FileNotFoundException ex) {
             LOG.warn("nothing to do, file doesn't exist - " + filename);
             return Status.DONE;
@@ -141,6 +154,11 @@ public class SplitLogWorker implements R
               workerName, filename);
           if (HLogSplitter.splitLogFileToTemp(rootdir, tmpname,
               st, fs, conf, p, logCloseThreadPool, masterRef.get()) == false) {
+
+            t1  = System.currentTimeMillis();
+            timingInfo.append("splitLogFileToTemp took " + (t1-t0) + " ms. ");
+            t0 = t1;
+
             return Status.PREEMPTED;
           }
         } catch (InterruptedIOException iioe) {
@@ -158,6 +176,9 @@ public class SplitLogWorker implements R
               e);
           return Status.ERR;
         }
+        finally {
+          LOG.debug("LogSplit timing info " + timingInfo.toString());
+        }
         return Status.DONE;
       }
     });

Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLogSplitter.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLogSplitter.java?rev=1384679&r1=1384678&r2=1384679&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLogSplitter.java
(original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLogSplitter.java
Fri Sep 14 08:08:31 2012
@@ -97,7 +97,7 @@ public class HLogSplitter {
 
   private MonitoredTask status;
 
-
+  
   /**
    * Create a new HLogSplitter using the given {@link Configuration} and the
    * <code>hbase.hlog.splitter.impl</code> property to derived the instance
@@ -185,6 +185,9 @@ public class HLogSplitter {
     synchronizedMap(new TreeMap<byte[], Object>(Bytes.BYTES_COMPARATOR));
     boolean isCorrupted = false;
 
+    long t0, t1;
+    StringBuilder timingInfo = new StringBuilder();
+
     Preconditions.checkState(status == null);
     status = TaskMonitor.get().createStatus(
         "Splitting log file " + logfile.getPath() +
@@ -207,7 +210,14 @@ public class HLogSplitter {
     status.setStatus("Opening log file");
     Reader in = null;
     try {
+      t0 = System.currentTimeMillis();
+
       in = getReader(fs, logfile, conf, skipErrors);
+
+      t1  = System.currentTimeMillis();
+      timingInfo.append("getReader took " + (t1-t0) + " ms. ");
+      t0 = t1;
+
     } catch (CorruptedLogFileException e) {
       LOG.warn("Could not get reader, corrupted log file " + logPath, e);
       ZKSplitLog.markCorrupted(rootDir, tmpname, fs);
@@ -237,8 +247,16 @@ public class HLogSplitter {
           lastFlushedSequenceId = lastFlushedSequenceIds.get(region);
           if (lastFlushedSequenceId == null) {
             try {
+
+              t0  = System.currentTimeMillis();
+
               lastFlushedSequenceId = master.getLastFlushedSequenceId(region);
               lastFlushedSequenceIds.put(region, lastFlushedSequenceId);
+
+              t1  = System.currentTimeMillis();
+              timingInfo.append("getLastFlushedSeqId took " + (t1-t0) + " ms. ");
+              t0 = t1;
+
             } catch (ConnectException e) {
               lastFlushedSequenceId = -1l;
               LOG.warn("Unable to connect to the master to check " +
@@ -256,7 +274,14 @@ public class HLogSplitter {
         }
         WriterAndPath wap = (WriterAndPath)o;
         if (wap == null) {
+          t0  = System.currentTimeMillis();
+
           wap = createWAP(region, entry, rootDir, tmpname, fs, conf);
+
+          t1  = System.currentTimeMillis();
+          timingInfo.append("createWAP took " + (t1-t0) + " ms. ");
+          t0 = t1;
+
           if (wap == null) {
             // ignore edits from this region. It doesn't exist anymore.
             // It was probably already split.
@@ -271,8 +296,8 @@ public class HLogSplitter {
         if (editsCount % interval == 0) {
           status.setStatus("Split " + (editsCount - editsSkipped) +
               " edits, skipped " + editsSkipped + " edits.");
-          long t1 = EnvironmentEdgeManager.currentTimeMillis();
-          if ((t1 - last_report_at) > period) {
+          long t2 = EnvironmentEdgeManager.currentTimeMillis();
+          if ((t2 - last_report_at) > period) {
             last_report_at = t;
             if (reporter != null && reporter.progress() == false) {
               status.setStatus("Failed: reporter.progress asked us to terminate");
@@ -290,11 +315,14 @@ public class HLogSplitter {
       e = RemoteExceptionHandler.checkIOException(e);
       throw e;
     } finally {
+
+      t0  = System.currentTimeMillis();
+
       int n = 0;
       List<Future<Void>> closeResults = new ArrayList<Future<Void>>();
       for (Object o : logWriters.values()) {
-        long t1 = EnvironmentEdgeManager.currentTimeMillis();
-        if ((t1 - last_report_at) > period) {
+        long t2 = EnvironmentEdgeManager.currentTimeMillis();
+        if ((t2 - last_report_at) > period) {
           last_report_at = t;
           if ((progress_failed == false) && (reporter != null) &&
               (reporter.progress() == false)) {
@@ -342,16 +370,27 @@ public class HLogSplitter {
         LOG.error("Interrupted while closing a log writer", ie);
         throw new InterruptedIOException("Interrupted while closing " + ie);
       }
+
+      t1  = System.currentTimeMillis();
+      timingInfo.append("closing logWriters took " + (t1-t0) + " ms. ");
+      t0 = t1;
+
       try {
         in.close();
       } catch (IOException ioe) {
         LOG.warn("Failed to close log reader " + logfile.getPath(), ioe);
       }
-      String msg = "processed " + editsCount + " edits across " + n +
-          " regions" + " threw away edits for " + (logWriters.size() - n) +
-          " regions" + " log file = " + logPath + " is corrupted = " +
+
+      t1  = System.currentTimeMillis();
+      timingInfo.append("closing inputLog took " + (t1-t0) + " ms. ");
+      t0 = t1;
+
+      String msg = "processed " + editsCount + " edits across " + n + 
+          " regions" + " threw away edits for " + (logWriters.size() - n) + 
+          " regions" + " log file = " + logPath + " is corrupted = " + 
           isCorrupted + " progress interrupted? = " + progress_failed;
       LOG.info(msg);
+      LOG.debug(timingInfo);
       status.markComplete(msg);
     }
     if (progress_failed) {



Mime
View raw message