Author: liyin Date: Thu Apr 4 20:49:23 2013 New Revision: 1464741 URL: http://svn.apache.org/r1464741 Log: [0.89-fb] [HBASE-8228] More Logging -- TEMPORY DIFF
Author: aaiyer Summary: temporary diff to gather more data about snapshots Test Plan: gather data from tsh025 Reviewers: rshroff, liyintang, adela Reviewed By: rshroff CC: hbase-eng@ Differential Revision: https://phabricator.fb.com/D762007 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/wal/HLog.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=1464741&r1=1464740&r2=1464741&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 Thu Apr 4 20:49:23 2013 @@ -1400,7 +1400,7 @@ public class HRegion implements HeapSize sb.append("startCacheFlush : " + (t02-t01) + ", "); completeSequenceId = this.getCompleteCacheFlushSequenceId(sequenceId); t03 = EnvironmentEdgeManager.currentTimeMillis(); - sb.append("getCompleteCacheFlushSeqId : " + (t03-t02) + ", "); + sb.append("getCompleteCacheFlushSeqId : " + (t03-t02) + ", ["); long tmp0, tmp1; for (Store s : stores.values()) { tmp0 = EnvironmentEdgeManager.currentTimeMillis(); @@ -1409,7 +1409,7 @@ public class HRegion implements HeapSize sb.append("getFlusher : " + s.getColumnFamilyName() + " : " + (tmp1-tmp0)); } t04 = EnvironmentEdgeManager.currentTimeMillis(); - sb.append(" all getStoreFlusher : " + (t04-t03) + ", "); + sb.append("] all getStoreFlusher : " + (t04-t03) + ", ["); // prepare flush (take a snapshot) for (StoreFlusher flusher : storeFlushers) { @@ -1419,7 +1419,7 @@ public class HRegion implements HeapSize sb.append("prepare : " + flusher.toString() + " : " + (tmp1-tmp0)); } t05 = EnvironmentEdgeManager.currentTimeMillis(); - sb.append(" all prepare() : " + (t05-t04) + " ms. "); + sb.append("] all prepare() : " + (t05-t04) + " ms. "); } finally { this.updatesLock.writeLock().unlock(); t1 = EnvironmentEdgeManager.currentTimeMillis(); Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLog.java URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLog.java?rev=1464741&r1=1464740&r2=1464741&view=diff ============================================================================== --- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLog.java (original) +++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/wal/HLog.java Thu Apr 4 20:49:23 2013 @@ -605,7 +605,9 @@ public class HLog implements Syncable { int oldNumEntries; long t0 = 0; long t1 = 0; + long startWLock, endWLock; this.cacheFlushLock.writeLock().lock(); + startWLock = EnvironmentEdgeManager.currentTimeMillis(); try { synchronized (updateLock) { t0 = EnvironmentEdgeManager.currentTimeMillis(); @@ -634,6 +636,10 @@ public class HLog implements Syncable { } } finally { this.cacheFlushLock.writeLock().unlock(); + endWLock = EnvironmentEdgeManager.currentTimeMillis(); + LOG.debug("While rolling held cacheFlushLock.writeLock() for " + + (endWLock - startWLock) + " ms. From " + + startWLock + " to " + endWLock); } Path oldFile = null; @@ -1355,7 +1361,10 @@ public class HLog implements Syncable { * @see #abortCacheFlush() */ public long startCacheFlush(final byte [] regionName) { + long startRLock, endRLock, obSeqT; + startRLock = EnvironmentEdgeManager.currentTimeMillis(); this.cacheFlushLock.readLock().lock(); + endRLock = EnvironmentEdgeManager.currentTimeMillis(); if (this.firstSeqWrittenInSnapshotMemstore.containsKey(regionName)) { LOG.warn("Requested a startCacheFlush while firstSeqWrittenInSnapshotMemstore still" + " contains " + Bytes.toString(regionName) + " . Did the previous flush fail?" @@ -1366,7 +1375,13 @@ public class HLog implements Syncable { this.firstSeqWrittenInSnapshotMemstore.put(regionName, seq); } } - return obtainSeqNum(); + long num = obtainSeqNum(); + obSeqT = EnvironmentEdgeManager.currentTimeMillis(); + LOG.debug("Trying to get cacheFlushLock.readLock for startCacheFlush took " + + (obSeqT - startRLock) + " ms. startRLock = " + + startRLock + " endRLock = " + + endRLock + " obSeqT = " + obSeqT); + return num; } /**
