HBASE-11320 Reenable bucket cache logging

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 {

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 =
+  private final ScheduledExecutorService scheduleThreadPool = Executors.newScheduledThreadPool(1,
-    Executors.newScheduledThreadPool(1,
+    new ThreadFactoryBuilder().setNameFormat("LruBlockCacheStatsExecutor").setDaemon(true).build());
-      new ThreadFactoryBuilder()
-        .setNameFormat("LruStats #%d")
-        .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) + ", " +
+    LruBlockCache.LOG.info("totalSize=" + StringUtils.byteDesc(totalSize) + ", " +
-        "free=" + StringUtils.byteDesc(freeSize) + ", " +
+        "freeSize=" + StringUtils.byteDesc(freeSize) + ", " +
         "max=" + StringUtils.byteDesc(this.maxSize) + ", " +
-        "blocks=" + size() +", " +
         "accesses=" + stats.getRequestCount() + ", " +
         "hits=" + stats.getHitCount() + ", " +
-        "hitRatio=" +
+        "hitRatio=" + (stats.getHitCount() == 0 ?
-          (stats.getHitCount() == 0 ? "0" : (StringUtils.formatPercent(stats.getHitRatio(), 2)+ ", ")) + ", " +
+          "0" : (StringUtils.formatPercent(stats.getHitRatio(), 2)+ ", ")) + ", " +
         "cachingAccesses=" + stats.getRequestCachingCount() + ", " +
         "cachingHits=" + stats.getHitCachingCount() + ", " +
-        "cachingHitsRatio=" +
+        "cachingHitsRatio=" + (stats.getHitCachingCount() == 0 ?
-          (stats.getHitCachingCount() == 0 ? "0,": (StringUtils.formatPercent(stats.getHitCachingRatio(), 2) + ", ")) +
+          "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();
   }

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() {
+  void logStatistics() {
-    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() {
     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();

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 =
+  private final ScheduledExecutorService scheduleThreadPool = Executors.newScheduledThreadPool(1,
-    Executors.newScheduledThreadPool(1,
+    new ThreadFactoryBuilder().setNameFormat("BucketCacheStatsExecutor").setDaemon(true).build());
-      new ThreadFactoryBuilder()
-        .setNameFormat("BucketCache Statistics #%d")
-        .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();
+    long cacheSize = getRealCacheSize();
-    LOG.debug("BucketCache Stats: " +
+    LOG.info("failedBlockAdditions=" + getFailedBlockAdditions() + ", " +
-        "failedBlockAdditions=" + this.failedBlockAdditions.get() + ", " +
+        "totalSize=" + StringUtils.byteDesc(totalSize) + ", " +
-        "total=" + StringUtils.byteDesc(totalSize) + ", " +
+        "freeSize=" + StringUtils.byteDesc(freeSize) + ", " +
-        "free=" + 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);
   }

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<KeyValue> cells) throws IOException {

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);