From 2ab3b325caefbc649b0cea911728a4776294a76a Mon Sep 17 00:00:00 2001 From: Michael Stack Date: Tue, 10 Jun 2014 14:27:04 -0700 Subject: [PATCH] HBASE-11320 Reenable bucket cache logging --- .../hadoop/hbase/io/hfile/BlockCacheUtil.java | 2 +- .../hadoop/hbase/io/hfile/LruBlockCache.java | 31 +++++++-------- .../io/hfile/bucket/BucketAllocator.java | 21 ++-------- .../hbase/io/hfile/bucket/BucketCache.java | 38 ++++++++++--------- .../hadoop/hbase/regionserver/HRegion.java | 2 +- .../MultiVersionConsistencyControl.java | 2 +- 6 files changed, 41 insertions(+), 55 deletions(-) diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/BlockCacheUtil.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/BlockCacheUtil.java index e4131d67825..d146084be07 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/BlockCacheUtil.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/BlockCacheUtil.java @@ -229,7 +229,7 @@ public class BlockCacheUtil { /** * Use one of these to keep a running account of cached blocks by file. Throw it away when done. * This is different than metrics in that it is stats on current state of a cache. - * @see getLoadedCachedBlocksByFile + * See getLoadedCachedBlocksByFile */ @JsonIgnoreProperties({"cachedBlockStatsByFile"}) public static class CachedBlocksByFile { diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/LruBlockCache.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/LruBlockCache.java index b6b8ad47032..9c5408fbca2 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/LruBlockCache.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/LruBlockCache.java @@ -140,12 +140,8 @@ public class LruBlockCache implements ResizableBlockCache, HeapSize { private final EvictionThread evictionThread; /** Statistics thread schedule pool (for heavy debugging, could remove) */ - private final ScheduledExecutorService scheduleThreadPool = - Executors.newScheduledThreadPool(1, - new ThreadFactoryBuilder() - .setNameFormat("LruStats #%d") - .setDaemon(true) - .build()); + private final ScheduledExecutorService scheduleThreadPool = Executors.newScheduledThreadPool(1, + new ThreadFactoryBuilder().setNameFormat("LruBlockCacheStatsExecutor").setDaemon(true).build()); /** Current size of cache */ private final AtomicLong size; @@ -286,6 +282,8 @@ public class LruBlockCache implements ResizableBlockCache, HeapSize { } else { this.evictionThread = null; } + // TODO: Add means of turning this off. Bit obnoxious running thread just to make a log + // every five minutes. this.scheduleThreadPool.scheduleAtFixedRate(new StatisticsThread(this), statThreadPeriod, statThreadPeriod, TimeUnit.SECONDS); } @@ -732,13 +730,14 @@ public class LruBlockCache implements ResizableBlockCache, HeapSize { * Statistics thread. Periodically prints the cache statistics to the log. */ static class StatisticsThread extends Thread { - LruBlockCache lru; + private final LruBlockCache lru; public StatisticsThread(LruBlockCache lru) { - super("LruBlockCache.StatisticsThread"); + super("LruBlockCacheStats"); setDaemon(true); this.lru = lru; } + @Override public void run() { lru.logStats(); @@ -746,22 +745,20 @@ public class LruBlockCache implements ResizableBlockCache, HeapSize { } public void logStats() { - if (!LOG.isDebugEnabled()) return; // Log size long totalSize = heapSize(); long freeSize = maxSize - totalSize; - LruBlockCache.LOG.debug("Total=" + StringUtils.byteDesc(totalSize) + ", " + - "free=" + StringUtils.byteDesc(freeSize) + ", " + + LruBlockCache.LOG.info("totalSize=" + StringUtils.byteDesc(totalSize) + ", " + + "freeSize=" + StringUtils.byteDesc(freeSize) + ", " + "max=" + StringUtils.byteDesc(this.maxSize) + ", " + - "blocks=" + size() +", " + "accesses=" + stats.getRequestCount() + ", " + "hits=" + stats.getHitCount() + ", " + - "hitRatio=" + - (stats.getHitCount() == 0 ? "0" : (StringUtils.formatPercent(stats.getHitRatio(), 2)+ ", ")) + ", " + + "hitRatio=" + (stats.getHitCount() == 0 ? + "0" : (StringUtils.formatPercent(stats.getHitRatio(), 2)+ ", ")) + ", " + "cachingAccesses=" + stats.getRequestCachingCount() + ", " + "cachingHits=" + stats.getHitCachingCount() + ", " + - "cachingHitsRatio=" + - (stats.getHitCachingCount() == 0 ? "0,": (StringUtils.formatPercent(stats.getHitCachingRatio(), 2) + ", ")) + + "cachingHitsRatio=" + (stats.getHitCachingCount() == 0 ? + "0,": (StringUtils.formatPercent(stats.getHitCachingRatio(), 2) + ", ")) + "evictions=" + stats.getEvictionCount() + ", " + "evicted=" + stats.getEvictedCount() + ", " + "evictedPerRun=" + stats.evictedPerEviction()); @@ -782,7 +779,7 @@ public class LruBlockCache implements ResizableBlockCache, HeapSize { (5 * Bytes.SIZEOF_FLOAT) + Bytes.SIZEOF_BOOLEAN + ClassSize.OBJECT); - // HeapSize implementation + @Override public long heapSize() { return getCurrentSize(); } diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketAllocator.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketAllocator.java index 08cfa341429..36fad56d82f 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketAllocator.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketAllocator.java @@ -27,6 +27,7 @@ import java.util.concurrent.atomic.AtomicLong; import com.google.common.base.Objects; import com.google.common.base.Preconditions; + import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; import org.apache.hadoop.classification.InterfaceAudience; @@ -512,21 +513,7 @@ public final class BucketAllocator { return this.buckets; } - public void dumpToLog() { - logStatistics(); - StringBuilder sb = new StringBuilder(); - for (Bucket b : buckets) { - sb.append("Bucket:").append(b.baseOffset).append('\n'); - sb.append(" Size index: " + b.sizeIndex() + "; Free:" + b.freeCount - + "; used:" + b.usedCount + "; freelist\n"); - for (int i = 0; i < b.freeCount(); ++i) - sb.append(b.freeList[i]).append(','); - sb.append('\n'); - } - LOG.info(sb); - } - - public void logStatistics() { + void logStatistics() { IndexStatistics total = new IndexStatistics(); IndexStatistics[] stats = getIndexStatistics(total); LOG.info("Bucket allocator statistics follow:\n"); @@ -538,7 +525,7 @@ public final class BucketAllocator { } } - public IndexStatistics[] getIndexStatistics(IndexStatistics grandTotal) { + IndexStatistics[] getIndexStatistics(IndexStatistics grandTotal) { IndexStatistics[] stats = getIndexStatistics(); long totalfree = 0, totalused = 0; for (IndexStatistics stat : stats) { @@ -549,7 +536,7 @@ public final class BucketAllocator { return stats; } - public IndexStatistics[] getIndexStatistics() { + IndexStatistics[] getIndexStatistics() { IndexStatistics[] stats = new IndexStatistics[bucketSizes.length]; for (int i = 0; i < stats.length; ++i) stats[i] = bucketSizeInfos[i].statistics(); diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java index e77bfc2b3c5..c01c38f1409 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java @@ -103,7 +103,7 @@ public class BucketCache implements BlockCache, HeapSize { private static final float DEFAULT_MIN_FACTOR = 0.85f; /** Statistics thread */ - private static final int statThreadPeriod = 3 * 60; + private static final int statThreadPeriod = 5 * 60; final static int DEFAULT_WRITER_THREADS = 3; final static int DEFAULT_WRITER_QUEUE_ITEMS = 64; @@ -188,12 +188,8 @@ public class BucketCache implements BlockCache, HeapSize { }); /** Statistics thread schedule pool (for heavy debugging, could remove) */ - private final ScheduledExecutorService scheduleThreadPool = - Executors.newScheduledThreadPool(1, - new ThreadFactoryBuilder() - .setNameFormat("BucketCache Statistics #%d") - .setDaemon(true) - .build()); + private final ScheduledExecutorService scheduleThreadPool = Executors.newScheduledThreadPool(1, + new ThreadFactoryBuilder().setNameFormat("BucketCacheStatsExecutor").setDaemon(true).build()); // Allocate or free space for the block private BucketAllocator bucketAllocator; @@ -252,6 +248,8 @@ public class BucketCache implements BlockCache, HeapSize { writerThreads[i].start(); } // Run the statistics thread periodically to print the cache statistics log + // TODO: Add means of turning this off. Bit obnoxious running thread just to make a log + // every five minutes. this.scheduleThreadPool.scheduleAtFixedRate(new StatisticsThread(this), statThreadPeriod, statThreadPeriod, TimeUnit.SECONDS); LOG.info("Started bucket cache; ioengine=" + ioEngineName + @@ -445,16 +443,15 @@ public class BucketCache implements BlockCache, HeapSize { /* * Statistics thread. Periodically output cache statistics to the log. */ - // TODO: Fix. We run a thread to log at DEBUG. If no DEBUG level, we still run the thread! - // A thread just to log is OTT. FIX. private static class StatisticsThread extends Thread { - BucketCache bucketCache; + private final BucketCache bucketCache; public StatisticsThread(BucketCache bucketCache) { - super("BucketCache.StatisticsThread"); + super("BucketCacheStatsThread"); setDaemon(true); this.bucketCache = bucketCache; } + @Override public void run() { bucketCache.logStats(); @@ -462,16 +459,13 @@ public class BucketCache implements BlockCache, HeapSize { } public void logStats() { - if (!LOG.isDebugEnabled()) return; - // Log size long totalSize = bucketAllocator.getTotalSize(); long usedSize = bucketAllocator.getUsedSize(); long freeSize = totalSize - usedSize; - long cacheSize = this.realCacheSize.get(); - LOG.debug("BucketCache Stats: " + - "failedBlockAdditions=" + this.failedBlockAdditions.get() + ", " + - "total=" + StringUtils.byteDesc(totalSize) + ", " + - "free=" + StringUtils.byteDesc(freeSize) + ", " + + long cacheSize = getRealCacheSize(); + LOG.info("failedBlockAdditions=" + getFailedBlockAdditions() + ", " + + "totalSize=" + StringUtils.byteDesc(totalSize) + ", " + + "freeSize=" + StringUtils.byteDesc(freeSize) + ", " + "usedSize=" + StringUtils.byteDesc(usedSize) +", " + "cacheSize=" + StringUtils.byteDesc(cacheSize) +", " + "accesses=" + cacheStats.getRequestCount() + ", " + @@ -490,6 +484,14 @@ public class BucketCache implements BlockCache, HeapSize { cacheStats.reset(); } + public long getFailedBlockAdditions() { + return this.failedBlockAdditions.get(); + } + + public long getRealCacheSize() { + return this.realCacheSize.get(); + } + private long acceptableSize() { return (long) Math.floor(bucketAllocator.getTotalSize() * DEFAULT_ACCEPT_FACTOR); } diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java index dedaf41e254..eeecb459e77 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java @@ -6179,7 +6179,7 @@ public class HRegion implements HeapSize { // , Writable{ * @param wal * @param cells list of KeyValues inserted into memstore. Those KeyValues are passed in order to * be updated with right mvcc values(their log sequence nu - * @return + * @return Return the key used appending with no sync and no append. * @throws IOException */ private HLogKey appendNoSyncNoAppend(final HLog wal, List cells) throws IOException { diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/MultiVersionConsistencyControl.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/MultiVersionConsistencyControl.java index 43433135b66..2e508f58e82 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/MultiVersionConsistencyControl.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/MultiVersionConsistencyControl.java @@ -62,7 +62,7 @@ public class MultiVersionConsistencyControl { /** * * @param initVal The value we used initially and expected it'll be reset later - * @return + * @return WriteEntry instance. */ WriteEntry beginMemstoreInsert() { return beginMemstoreInsertWithSeqNum(NO_WRITE_NUMBER);