From c32b6c8eff468450500a4cf28d9dc421048e506e Mon Sep 17 00:00:00 2001 From: Andrew Purtell Date: Wed, 5 May 2021 17:01:00 -0700 Subject: [PATCH] HBASE-25847 More DEBUG and TRACE level logging in CatalogJanitor and HbckChore (#3230) Signed-off-by: Bharath Vissapragada Signed-off-by: Michael Stack --- .../org/apache/hadoop/hbase/master/HbckChore.java | 29 ++++++++- .../hbase/master/janitor/CatalogJanitor.java | 76 ++++++++++++++++++---- 2 files changed, 89 insertions(+), 16 deletions(-) diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/HbckChore.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/HbckChore.java index 050c03aeea..903f4ee45c 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/HbckChore.java +++ b/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 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()); } diff --git a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/janitor/CatalogJanitor.java b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/janitor/CatalogJanitor.java index dd3b6fc32f..1674bb06c8 100644 --- a/hbase-server/src/main/java/org/apache/hadoop/hbase/master/janitor/CatalogJanitor.java +++ b/hbase-server/src/main/java/org/apache/hadoop/hbase/master/janitor/CatalogJanitor.java @@ -73,6 +73,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); @@ -87,7 +89,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; } @@ -157,20 +160,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 mergedRegions = this.lastReport.mergedRegions; for (Map.Entry 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; } @@ -187,6 +200,9 @@ public class CatalogJanitor extends ScheduledChore { for (Map.Entry 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; } @@ -234,6 +250,9 @@ public class CatalogJanitor extends ScheduledChore { */ private boolean cleanMergeRegion(final RegionInfo mergedRegion, List 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()); @@ -246,16 +265,23 @@ public class CatalogJanitor extends ScheduledChore { LOG.warn("Merged region does not exist: " + mergedRegion.getEncodedName()); } if (regionFs == null || !regionFs.hasReferences(htd)) { - LOG.debug( - "Deleting parents ({}) from fs; merged child {} no longer holds references", parents - .stream().map(r -> RegionInfo.getShortNameToLog(r)).collect(Collectors.joining(", ")), - mergedRegion); + if (LOG.isDebugEnabled()) { + LOG.debug( + "Deleting parents ({}) from fs; merged child {} no longer holds references", parents + .stream().map(r -> RegionInfo.getShortNameToLog(r)).collect(Collectors.joining(", ")), + mergedRegion); + } ProcedureExecutor pe = this.services.getMasterProcedureExecutor(); - pe.submitProcedure( - new GCMultipleMergedRegionsProcedure(pe.getEnvironment(), mergedRegion, parents)); + GCMultipleMergedRegionsProcedure mergeRegionProcedure = + 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); } @@ -299,9 +325,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 (MetaTableAccessor.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. @@ -313,14 +345,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 -- " + - daughterA + ", " + daughterB + " -- no longer hold references"); + if (LOG.isDebugEnabled()) { + LOG.debug("Deleting region " + parent.getShortNameToLog() + " because daughters -- " + + daughterA + ", " + daughterB + " -- no longer hold references"); + } ProcedureExecutor 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; } -- 2.11.4.GIT