From f305516a14f0ec9d6a74fba58a175f8973e824dd Mon Sep 17 00:00:00 2001
From: chaijunjie0101 <1340011734@qq.com>
Date: Fri, 26 May 2023 20:43:21 +0800
Subject: [PATCH] HBASE-27888 Record readBlock message in log when it takes too
 long time

---
 .../src/main/java/org/apache/hadoop/hbase/HConstants.java | 7 +++++++
 hbase-common/src/main/resources/hbase-default.xml         | 5 +++++
 .../java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java | 8 ++++++++
 3 files changed, 20 insertions(+)

diff --git a/hbase-common/src/main/java/org/apache/hadoop/hbase/HConstants.java b/hbase-common/src/main/java/org/apache/hadoop/hbase/HConstants.java
index 12479979b2ba..5915d6fe6227 100644
--- a/hbase-common/src/main/java/org/apache/hadoop/hbase/HConstants.java
+++ b/hbase-common/src/main/java/org/apache/hadoop/hbase/HConstants.java
@@ -1603,6 +1603,13 @@ public enum OperationStatusCode {
    */
   public final static boolean HBASE_SERVER_USEIP_ENABLED_DEFAULT = false;
 
+  /**
+   * If reading block cost time more than the threshold, a warning will be logged.
+   */
+  public static final String FS_READER_WARN_TIME = "hbase.fs.reader.warn.time";
+
+  public static final long DEFAULT_FS_READER_WARN_TIME = 100L;
+
   private HConstants() {
     // Can't be instantiated with this ctor.
   }
diff --git a/hbase-common/src/main/resources/hbase-default.xml b/hbase-common/src/main/resources/hbase-default.xml
index a4ee0c8b20b6..2a188e1e2411 100644
--- a/hbase-common/src/main/resources/hbase-default.xml
+++ b/hbase-common/src/main/resources/hbase-default.xml
@@ -2062,4 +2062,9 @@ possible configurations would overwhelm and obscure the important.
       hitting the namenode, if the DFSInputStream's block list is incomplete.
     </description>
   </property>
+  <property>
+    <name>hbase.fs.reader.warn.time</name>
+    <value>100</value>
+    <description>Record slow read block in warning log, in milliseconds.</description>
+  </property>
 </configuration>
diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java
index c84836bcd532..7239d18e8b44 100644
--- a/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java
+++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java
@@ -1385,6 +1385,8 @@ static class FSReaderImpl implements FSReader {
 
     private final boolean isPreadAllBytes;
 
+    private final long readWarnTime;
+
     FSReaderImpl(ReaderContext readerContext, HFileContext fileContext, ByteBuffAllocator allocator,
       Configuration conf) throws IOException {
       this.fileSize = readerContext.getFileSize();
@@ -1402,6 +1404,8 @@ static class FSReaderImpl implements FSReader {
       defaultDecodingCtx = new HFileBlockDefaultDecodingContext(conf, fileContext);
       encodedBlockDecodingCtx = defaultDecodingCtx;
       isPreadAllBytes = readerContext.isPreadAllBytes();
+      readWarnTime =
+        conf.getLong(HConstants.FS_READER_WARN_TIME, HConstants.DEFAULT_FS_READER_WARN_TIME);
     }
 
     @Override
@@ -1759,6 +1763,10 @@ protected HFileBlock readBlockDataInternal(FSDataInputStream is, long offset,
           hFileBlock.sanityCheckUncompressed();
         }
         LOG.trace("Read {} in {} ms", hFileBlock, duration);
+        if (!LOG.isTraceEnabled() && duration > this.readWarnTime) {
+          LOG.warn("Read Block Slow: read {} cost {} ms, threshold = {} ms", hFileBlock, duration,
+            this.readWarnTime);
+        }
         span.addEvent("Read block", attributesBuilder.build());
         // Cache next block header if we read it for the next time through here.
         if (nextBlockOnDiskSize != -1) {