HBASE-27888 Record readBlock message in log when it takes too long time

Author: chaijunjie0101

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.
   }

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>

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