HBASE-26190 High rate logging of BucketAllocatorException: Allocation too big

Reduce the frequency of allocation failed traces by printing them
preiodically (once per minute). Record the allocation failures in the
Bucket Cache Stats and let the stat thread dump cumulative allocation
failures alongside other traces it dumps.

Also, this change adds trace for the Table name, Column Family and
HFileName for the most recent allocation failure in last 1 minute.

Author: KulwantSingh011

hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java

@@ -2029,7 +2029,7 @@ static private byte[] getDummyHeaderForVersion(boolean usesHBaseChecksum) {
    * @return This HFileBlocks fileContext which will a derivative of the
    *   fileContext for the file from which this block's data was originally read.
    */
-  HFileContext getHFileContext() {
+  public HFileContext getHFileContext() {
     return this.fileContext;
   }
 

hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCache.java

@@ -67,9 +67,11 @@
 import org.apache.hadoop.hbase.io.hfile.Cacheable;
 import org.apache.hadoop.hbase.io.hfile.CachedBlock;
 import org.apache.hadoop.hbase.io.hfile.HFileBlock;
+import org.apache.hadoop.hbase.io.hfile.HFileContext;
 import org.apache.hadoop.hbase.nio.ByteBuff;
 import org.apache.hadoop.hbase.nio.RefCnt;
 import org.apache.hadoop.hbase.protobuf.ProtobufMagic;
+import org.apache.hadoop.hbase.util.Bytes;
 import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
 import org.apache.hadoop.hbase.util.IdReadWriteLock;
 import org.apache.hadoop.hbase.util.IdReadWriteLockStrongRef;
@@ -249,6 +251,10 @@ public class BucketCache implements BlockCache, HeapSize {
    * */
   private String algorithm;
 
+  /* Tracing failed Bucket Cache allocations. */
+  private long allocFailLogPrevTs; // time of previous log event for allocation failure.
+  private static final int ALLOCATION_FAIL_LOG_TIME_PERIOD = 60000; // Default 1 minute.
+
   public BucketCache(String ioEngineName, long capacity, int blockSize, int[] bucketSizes,
       int writerThreadNum, int writerQLen, String persistencePath) throws IOException {
     this(ioEngineName, capacity, blockSize, bucketSizes, writerThreadNum, writerQLen,
@@ -291,6 +297,8 @@ public BucketCache(String ioEngineName, long capacity, int blockSize, int[] buck
     this.blockSize = blockSize;
     this.ioErrorsTolerationDuration = ioErrorsTolerationDuration;
 
+    this.allocFailLogPrevTs = 0;
+
     bucketAllocator = new BucketAllocator(capacity, bucketSizes);
     for (int i = 0; i < writerThreads.length; ++i) {
       writerQueues.add(new ArrayBlockingQueue<>(writerQLen));
@@ -728,7 +736,8 @@ public void logStats() {
           (StringUtils.formatPercent(cacheStats.getHitCachingRatio(), 2)+ ", ")) +
         "evictions=" + cacheStats.getEvictionCount() + ", " +
         "evicted=" + cacheStats.getEvictedCount() + ", " +
-        "evictedPerRun=" + cacheStats.evictedPerEviction());
+        "evictedPerRun=" + cacheStats.evictedPerEviction() + ", " +
+        "allocationFailCount=" + cacheStats.getAllocationFailCount());
     cacheStats.reset();
   }
 
@@ -1036,7 +1045,29 @@ void doDrain(final List<RAMQueueEntry> entries) throws InterruptedException {
         }
         index++;
       } catch (BucketAllocatorException fle) {
-        LOG.warn("Failed allocation for " + (re == null ? "" : re.getKey()) + "; " + fle);
+        long currTs = System.currentTimeMillis(); // Current time since Epoch in milliseconds.
+        cacheStats.allocationFailed(); // Record the warning.
+        if (allocFailLogPrevTs == 0 || (currTs - allocFailLogPrevTs) > ALLOCATION_FAIL_LOG_TIME_PERIOD) {
+          String failHFileName    = "";
+          String failColumnFamily = "";
+          String failTableName    = "";
+          if (re != null) {
+            Cacheable failData = re.getData();
+            if (failData instanceof HFileBlock) {
+              HFileBlock    failBlock       = (HFileBlock) failData;
+              HFileContext  failFileContext = failBlock.getHFileContext();
+              failHFileName                 = failFileContext.getHFileName();
+              failColumnFamily              = Bytes.toString(failFileContext.getColumnFamily());
+              failTableName                 = Bytes.toString(failFileContext.getTableName());
+            }
+          }
+          LOG.warn("Most recent failed allocation in " + ALLOCATION_FAIL_LOG_TIME_PERIOD +
+              " milliseconds; Key: " + (re == null ? "" : re.getKey()) +
+              ", TableName = " + failTableName + ", ColumnFamily = " + failColumnFamily +
+              ", HFileName : " + failHFileName
+              , fle);
+          allocFailLogPrevTs = currTs;
+        }
         // Presume can't add. Too big? Move index on. Entry will be cleared from ramCache below.
         bucketEntries[index] = null;
         index++;

hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/bucket/BucketCacheStats.java

@@ -35,14 +35,20 @@ public class BucketCacheStats extends CacheStats {
   private static final long NANO_TIME = TimeUnit.MILLISECONDS.toNanos(1);
   private long lastLogTime = EnvironmentEdgeManager.currentTime();
 
+  /* Tracing failed Bucket Cache allocations. */
+  private LongAdder allocationFailCount = new LongAdder();
+
   BucketCacheStats() {
     super("BucketCache");
+
+    allocationFailCount.reset();
   }
 
   @Override
   public String toString() {
     return super.toString() + ", ioHitsPerSecond=" + getIOHitsPerSecond() +
-      ", ioTimePerHit=" + getIOTimePerHit();
+      ", ioTimePerHit=" + getIOTimePerHit() + ", allocationFailCount=" +
+      getAllocationFailCount();
   }
 
   public void ioHit(long time) {
@@ -66,5 +72,14 @@ public double getIOTimePerHit() {
   public void reset() {
     ioHitCount.reset();
     ioHitTime.reset();
+    allocationFailCount.reset();
+  }
+
+  public long getAllocationFailCount() {
+    return allocationFailCount.sum();
+  }
+
+  public void allocationFailed () {
+    allocationFailCount.increment();
   }
 }