HBASE-25847 More DEBUG and TRACE level logging in CatalogJanitor and HbckChore (#3230)

Signed-off-by: Bharath Vissapragada <bharathv@apache.org>
Signed-off-by: Michael Stack <stack@apache.org>

hbase-server/src/main/java/org/apache/hadoop/hbase/master/HbckChore.java

@@ -223,7 +223,7 @@ public class HbckChore extends ScheduledChore {
           .isTableState(regionInfo.getTable(), TableState.State.DISABLED)) {
         disabledTableRegions.add(regionInfo.getRegionNameAsString());
       }
-      if (regionInfo.isSplitParent()) {
+      if (regionState.isSplit()) {
         splitParentRegions.add(regionInfo.getRegionNameAsString());
       }
       HbckRegionInfo.MetaEntry metaEntry =
@@ -231,7 +231,30 @@ public class HbckChore extends ScheduledChore {
               regionState.getStamp());
       regionInfoMap.put(regionInfo.getEncodedName(), new HbckRegionInfo(metaEntry));
     }
-    LOG.info("Loaded {} regions from in-memory state of AssignmentManager", regionStates.size());
+    LOG.info("Loaded {} regions ({} disabled, {} split parents) from in-memory state",
+      regionStates.size(), disabledTableRegions.size(), splitParentRegions.size());
+    if (LOG.isDebugEnabled()) {
+      Map<RegionState.State,Integer> stateCountMap = new HashMap<>();
+      for (RegionState regionState : regionStates) {
+        stateCountMap.compute(regionState.getState(), (k, v) -> (v == null) ? 1 : v + 1);
+      }
+      StringBuffer sb = new StringBuffer();
+      sb.append("Regions by state: ");
+      stateCountMap.entrySet().forEach(e -> {
+          sb.append(e.getKey());
+          sb.append('=');
+          sb.append(e.getValue());
+          sb.append(' ');
+        }
+      );
+      LOG.debug(sb.toString());
+    }
+    if (LOG.isTraceEnabled()) {
+      for (RegionState regionState : regionStates) {
+        LOG.trace("{}: {}, serverName=", regionState.getRegion(), regionState.getState(),
+          regionState.getServerName());
+      }
+    }
   }
 
   private void loadRegionsFromRSReport() {
@@ -307,7 +330,7 @@ public class HbckChore extends ScheduledChore {
       }
       numRegions += regionDirs.size();
     }
-    LOG.info("Loaded {} tables {} regions from filesyetem and found {} orphan regions",
+    LOG.info("Loaded {} tables {} regions from filesystem and found {} orphan regions",
         tableDirs.size(), numRegions, orphanRegionsOnFS.size());
   }
 

hbase-server/src/main/java/org/apache/hadoop/hbase/master/janitor/CatalogJanitor.java

@@ -74,6 +74,8 @@ import org.slf4j.LoggerFactory;
 @InterfaceAudience.Private
 public class CatalogJanitor extends ScheduledChore {
 
+  public static final int DEFAULT_HBASE_CATALOGJANITOR_INTERVAL = 300 * 1000;
+
   private static final Logger LOG = LoggerFactory.getLogger(CatalogJanitor.class.getName());
 
   private final AtomicBoolean alreadyRunning = new AtomicBoolean(false);
@@ -88,7 +90,8 @@ public class CatalogJanitor extends ScheduledChore {
 
   public CatalogJanitor(final MasterServices services) {
     super("CatalogJanitor-" + services.getServerName().toShortString(), services,
-      services.getConfiguration().getInt("hbase.catalogjanitor.interval", 300000));
+      services.getConfiguration().getInt("hbase.catalogjanitor.interval",
+        DEFAULT_HBASE_CATALOGJANITOR_INTERVAL));
     this.services = services;
   }
 
@@ -158,20 +161,30 @@ public class CatalogJanitor extends ScheduledChore {
     int gcs = 0;
     try {
       if (!alreadyRunning.compareAndSet(false, true)) {
-        LOG.debug("CatalogJanitor already running");
+        if (LOG.isDebugEnabled()) {
+          LOG.debug("CatalogJanitor already running");
+        }
         // -1 indicates previous scan is in progress
         return -1;
       }
       this.lastReport = scanForReport();
       if (!this.lastReport.isEmpty()) {
         LOG.warn(this.lastReport.toString());
+      } else {
+        if (LOG.isDebugEnabled()) {
+          LOG.debug(this.lastReport.toString());
+        }
       }
+
       updateAssignmentManagerMetrics();
 
       Map<RegionInfo, Result> mergedRegions = this.lastReport.mergedRegions;
       for (Map.Entry<RegionInfo, Result> e : mergedRegions.entrySet()) {
         if (this.services.isInMaintenanceMode()) {
           // Stop cleaning if the master is in maintenance mode
+          if (LOG.isDebugEnabled()) {
+            LOG.debug("In maintenence mode, not cleaning");
+          }
           break;
         }
 
@@ -188,6 +201,9 @@ public class CatalogJanitor extends ScheduledChore {
       for (Map.Entry<RegionInfo, Result> e : splitParents.entrySet()) {
         if (this.services.isInMaintenanceMode()) {
           // Stop cleaning if the master is in maintenance mode
+          if (LOG.isDebugEnabled()) {
+            LOG.debug("In maintenence mode, not cleaning");
+          }
           break;
         }
 
@@ -235,6 +251,9 @@ public class CatalogJanitor extends ScheduledChore {
    */
   private boolean cleanMergeRegion(final RegionInfo mergedRegion, List<RegionInfo> parents)
     throws IOException {
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("Cleaning merged region {}", mergedRegion);
+    }
     FileSystem fs = this.services.getMasterFileSystem().getFileSystem();
     Path rootdir = this.services.getMasterFileSystem().getRootDir();
     Path tabledir = CommonFSUtils.getTableDir(rootdir, mergedRegion.getTable());
@@ -247,16 +266,23 @@ public class CatalogJanitor extends ScheduledChore {
       LOG.warn("Merged region does not exist: " + mergedRegion.getEncodedName());
     }
     if (regionFs == null || !regionFs.hasReferences(htd)) {
-      LOG.debug(
+      if (LOG.isDebugEnabled()) {
-        "Deleting parents ({}) from fs; merged child {} no longer holds references", parents
+        LOG.debug(
-          .stream().map(r -> RegionInfo.getShortNameToLog(r)).collect(Collectors.joining(", ")),
+          "Deleting parents ({}) from fs; merged child {} no longer holds references", parents
-        mergedRegion);
+            .stream().map(r -> RegionInfo.getShortNameToLog(r)).collect(Collectors.joining(", ")),
+          mergedRegion);
+      }
       ProcedureExecutor<MasterProcedureEnv> pe = this.services.getMasterProcedureExecutor();
-      pe.submitProcedure(
+      GCMultipleMergedRegionsProcedure mergeRegionProcedure =
-        new GCMultipleMergedRegionsProcedure(pe.getEnvironment(), mergedRegion, parents));
+          new GCMultipleMergedRegionsProcedure(pe.getEnvironment(), mergedRegion, parents);
+      pe.submitProcedure(mergeRegionProcedure);
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Submitted procedure {} for merged region {}", mergeRegionProcedure,
+          mergedRegion);
+      }
+      // TODO: The above scheduled GCMultipleMergedRegionsProcedure does the below.
+      // Do we need this?
       for (RegionInfo ri : parents) {
-        // The above scheduled GCMultipleMergedRegionsProcedure does the below.
-        // Do we need this?
         this.services.getAssignmentManager().getRegionStates().deleteRegion(ri);
         this.services.getServerManager().removeRegion(ri);
       }
@@ -300,9 +326,15 @@ public class CatalogJanitor extends ScheduledChore {
 
   static boolean cleanParent(MasterServices services, RegionInfo parent, Result rowContent)
     throws IOException {
+    if (LOG.isDebugEnabled()) {
+      LOG.debug("Cleaning parent region {}", parent);
+    }
     // Check whether it is a merged region and if it is clean of references.
     if (CatalogFamilyFormat.hasMergeRegions(rowContent.rawCells())) {
       // Wait until clean of merge parent regions first
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Region {} has merge parents, cleaning them first", parent);
+      }
       return false;
     }
     // Run checks on each daughter split.
@@ -314,14 +346,32 @@ public class CatalogJanitor extends ScheduledChore {
         daughters.getFirst() != null ? daughters.getFirst().getShortNameToLog() : "null";
       String daughterB =
         daughters.getSecond() != null ? daughters.getSecond().getShortNameToLog() : "null";
-      LOG.debug("Deleting region " + parent.getShortNameToLog() + " because daughters -- " +
+      if (LOG.isDebugEnabled()) {
-        daughterA + ", " + daughterB + " -- no longer hold references");
+        LOG.debug("Deleting region " + parent.getShortNameToLog() + " because daughters -- " +
+          daughterA + ", " + daughterB + " -- no longer hold references");
+      }
       ProcedureExecutor<MasterProcedureEnv> pe = services.getMasterProcedureExecutor();
-      pe.submitProcedure(new GCRegionProcedure(pe.getEnvironment(), parent));
+      GCRegionProcedure gcRegionProcedure = new GCRegionProcedure(pe.getEnvironment(), parent);
+      pe.submitProcedure(gcRegionProcedure);
+      if (LOG.isDebugEnabled()) {
+        LOG.debug("Submitted procedure {} for split parent {}", gcRegionProcedure, parent);
+      }
       // Remove from in-memory states
+      // TODO: The above scheduled GCRegionProcedure does the below. Do we need this?
       services.getAssignmentManager().getRegionStates().deleteRegion(parent);
       services.getServerManager().removeRegion(parent);
       return true;
+    } else {
+      if (LOG.isDebugEnabled()) {
+        if (!hasNoReferences(a)) {
+          LOG.debug("Deferring removal of region {} because daughter {} still has references",
+            parent, daughters.getFirst());
+        }
+        if (!hasNoReferences(b)) {
+          LOG.debug("Deferring removal of region {} because daughter {} still has references",
+            parent, daughters.getSecond());
+        }
+      }
     }
     return false;
   }