svn commit: r1463658 - in /hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver: HRegion.java MemStore.java

[li...@apache.org]

Author: liyin
Date: Tue Apr  2 18:18:54 2013
New Revision: 1463658

URL: http://svn.apache.org/r1463658
Log:
[0.89-fb] [HBASE-8228] Enable finer profiling for a memstore snapshot. -- TEMPORARY DIFF

Author: aaiyer

Summary:
more instrumentation

We do not intend to have this diff around for a while. Will be
reverted after getting the info we need to track the outliers.

Test Plan: push to titan025 and get the data to understand this.

Reviewers: liyintang, rshroff, adela

Reviewed By: rshroff

CC: hbase-eng@

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

Task ID: 2237950

Modified:
    hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java
    hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/MemStore.java

Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java?rev=1463658&r1=1463657&r2=1463658&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java Tue Apr  2 18:18:54 2013
@@ -1383,6 +1383,7 @@ public class HRegion implements HeapSize
     status.setStatus("Obtaining lock to block concurrent updates");
     long t0, t1;
     long t01 = 0, t02 = 0, t03 = 0, t04 = 0, t05 = 0;
+    StringBuilder sb = new StringBuilder();
     this.updatesLock.writeLock().lock();
     t0 = EnvironmentEdgeManager.currentTimeMillis();
     status.setStatus("Preparing to flush by snapshotting stores");
@@ -1391,35 +1392,40 @@ public class HRegion implements HeapSize
     List<StoreFlusher> storeFlushers = new ArrayList<StoreFlusher>(
         stores.size());
     t01 = EnvironmentEdgeManager.currentTimeMillis();
+    sb.append("setStatus : " + (t01-t0) + ", ");
     try {
       sequenceId = (wal == null)? myseqid :
         wal.startCacheFlush(this.regionInfo.getRegionName());
       t02 = EnvironmentEdgeManager.currentTimeMillis();
+      sb.append("startCacheFlush : " + (t02-t01) + ", ");
       completeSequenceId = this.getCompleteCacheFlushSequenceId(sequenceId);
       t03 = EnvironmentEdgeManager.currentTimeMillis();
+      sb.append("getCompleteCacheFlushSeqId : " + (t03-t02) + ", ");
+      long tmp0, tmp1;
       for (Store s : stores.values()) {
+        tmp0 = EnvironmentEdgeManager.currentTimeMillis();
         storeFlushers.add(s.getStoreFlusher(completeSequenceId));
+        tmp1 = EnvironmentEdgeManager.currentTimeMillis();
+        sb.append("getFlusher : " + s.getColumnFamilyName() + " : " + (tmp1-tmp0));
       }
       t04 = EnvironmentEdgeManager.currentTimeMillis();
+      sb.append(" all getStoreFlusher : " + (t04-t03) + ", ");
 
       // prepare flush (take a snapshot)
       for (StoreFlusher flusher : storeFlushers) {
+        tmp0 = EnvironmentEdgeManager.currentTimeMillis();
         flusher.prepare();
+        tmp1 = EnvironmentEdgeManager.currentTimeMillis();
+        sb.append("prepare : " + flusher.toString() + " : " + (tmp1-tmp0));
       }
       t05 = EnvironmentEdgeManager.currentTimeMillis();
+      sb.append(" all prepare() : " + (t05-t04) + " ms. ");
     } finally {
       this.updatesLock.writeLock().unlock();
       t1 = EnvironmentEdgeManager.currentTimeMillis();
       LOG.debug("Finished snapshotting. Held region-wide updates lock for "
         + (t1-t0) + " ms."
-        + " parts: "
-        + (t01-t0) +  " ms. "
-        + (t02-t01) +  " ms. "
-        + (t03-t02) +  " ms. "
-        + (t04-t03) +  " ms. "
-        + (t05-t04) +  " ms. "
-        + (t1-t05) +  " ms. "
-        );
+        + sb.toString());
     }
 
     status.setStatus("Flushing stores");

Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/MemStore.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/MemStore.java?rev=1463658&r1=1463657&r2=1463658&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/MemStore.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/MemStore.java Tue Apr  2 18:18:54 2013
@@ -40,6 +40,7 @@ import org.apache.hadoop.hbase.io.HeapSi
 import org.apache.hadoop.hbase.util.Bytes;
 import org.apache.hadoop.hbase.util.ClassSize;
 import org.apache.hadoop.hbase.util.CollectionBackedScanner;
+import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
 
 /**
  * The MemStore holds in-memory modifications to the Store.  Modifications
@@ -124,7 +125,10 @@ public class MemStore implements HeapSiz
    * To get the snapshot made by this method, use {@link #getSnapshot()}
    */
   void snapshot() {
+    long t0 = 0, t1 = 0, t2 = 0;
+    t0 = EnvironmentEdgeManager.currentTimeMillis();
     this.lock.writeLock().lock();
+    t1 = EnvironmentEdgeManager.currentTimeMillis();
     try {
       // If snapshot currently has entries, then flusher failed or didn't call
       // cleanup.  Log a warning.
@@ -145,6 +149,9 @@ public class MemStore implements HeapSiz
       }
     } finally {
       this.lock.writeLock().unlock();
+      t2 = EnvironmentEdgeManager.currentTimeMillis();
+      LOG.debug("Snapshotting " + this.toString() + " took "
+          + (t2-t1) + " ms. To grab the writeLock : " + (t1 - t0));
     }
   }