HBASE-20232 [LOGGING] Formatting around close and flush

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/ChunkCreator.java

@@ -495,8 +495,8 @@ public class ChunkCreator {
           " must be between 0.0 and 1.0");
     }
     int initialCount = (int) (initialCountPercentage * maxCount);
-    LOG.info("{} allocating {} MemStoreChunkPool with chunk size {}, max count {}, " +
-            "initial count {}", label, StringUtils.byteDesc(chunkSize), maxCount, initialCount);
+    LOG.info("Allocating {} MemStoreChunkPool with chunk size {}, max count {}, initial count {}",
+        label, StringUtils.byteDesc(chunkSize), maxCount, initialCount);
     MemStoreChunkPool memStoreChunkPool = new MemStoreChunkPool(label, chunkSize, maxCount,
             initialCount, poolSizePercentage);
     if (heapMemoryManager != null && memStoreChunkPool != null) {

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/CompactingMemStore.java

@@ -198,11 +198,8 @@ public class CompactingMemStore extends AbstractMemStore {
       LOG.warn("Snapshot called again without clearing previous. " +
           "Doing nothing. Another ongoing flush or did we fail last attempt?");
     } else {
-      if (LOG.isDebugEnabled()) {
-        LOG.debug("FLUSHING TO DISK: region "
-            + getRegionServices().getRegionInfo().getRegionNameAsString() + "store: "
-            + getFamilyName());
-      }
+      LOG.debug("FLUSHING TO DISK {}, store={}",
+            getRegionServices().getRegionInfo().getEncodedName(), getFamilyName());
       stopCompaction();
       pushActiveToPipeline(this.active);
       snapshotId = EnvironmentEdgeManager.currentTime();

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/DefaultStoreFlusher.java

@@ -82,10 +82,9 @@ public class DefaultStoreFlusher extends StoreFlusher {
     } finally {
       scanner.close();
     }
-    LOG.info("Flushed, sequenceid=" + cacheFlushId +", memsize="
-        + StringUtils.TraditionalBinaryPrefix.long2String(snapshot.getDataSize(), "", 1) +
-        ", hasBloomFilter=" + writer.hasGeneralBloom() +
-        ", into tmp file " + writer.getPath());
+    LOG.info("Flushed memstore data size={} at sequenceid={} (bloomFilter={}), to={}",
+        StringUtils.byteDesc(snapshot.getDataSize()), cacheFlushId, writer.hasGeneralBloom(),
+        writer.getPath());
     result.add(writer.getPath());
     return result;
   }

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HRegion.java

@@ -1444,7 +1444,7 @@ public class HRegion implements HeapSize, PropagatingConfigurationObserver, Regi
     // Only allow one thread to close at a time. Serialize them so dual
     // threads attempting to close will run up against each other.
     MonitoredTask status = TaskMonitor.get().createStatus(
-        "Closing region " + this +
+        "Closing region " + this.getRegionInfo().getEncodedName() +
         (abort ? " due to abort" : ""));
 
     status.setStatus("Waiting for close lock");
@@ -1496,7 +1496,8 @@ public class HRegion implements HeapSize, PropagatingConfigurationObserver, Regi
       // region.
       canFlush = !writestate.readOnly;
       writestate.writesEnabled = false;
-      LOG.debug("Closing " + this + ": disabling compactions & flushes");
+      LOG.debug("Closing {}, disabling compactions & flushes",
+          this.getRegionInfo().getEncodedName());
       waitForFlushesAndCompactions();
     }
     // If we were not just flushing, is it worth doing a preflush...one
@@ -1504,7 +1505,7 @@ public class HRegion implements HeapSize, PropagatingConfigurationObserver, Regi
     // the close flag?
     if (!abort && worthPreFlushing() && canFlush) {
       status.setStatus("Pre-flushing region before close");
-      LOG.info("Running close preflush of " + this);
+      LOG.info("Running close preflush of {}" + this.getRegionInfo().getEncodedName());
       try {
         internalFlushcache(status);
       } catch (IOException ioe) {
@@ -2719,11 +2720,11 @@ public class HRegion implements HeapSize, PropagatingConfigurationObserver, Regi
     long flushableDataSize = prepareResult.totalFlushableSize.getDataSize();
     long flushableHeapSize = prepareResult.totalFlushableSize.getHeapSize();
     long memstoresize = this.memStoreSize.getDataSize();
-    String msg = "Finished memstore flush."
-        + " Flushed data size ~" + StringUtils.byteDesc(flushableDataSize) + "/" + flushableDataSize
-        + " Flushed Heap size ~" + StringUtils.byteDesc(flushableHeapSize) + "/" + flushableHeapSize
+    String msg = "Finished memstore flush;"
+        + " data size ~" + StringUtils.byteDesc(flushableDataSize) + "/" + flushableDataSize
+        + ", heap size ~" + StringUtils.byteDesc(flushableHeapSize) + "/" + flushableHeapSize
         + ", currentsize=" + StringUtils.byteDesc(memstoresize) + "/" + memstoresize
-        + " for region " + this + " in " + time + "ms, sequenceid="
+        + " for " + this.getRegionInfo().getEncodedName() + " in " + time + "ms, sequenceid="
         + flushOpSeqId +  ", compaction requested=" + compactionRequested
         + ((wal == null) ? "; wal=null" : "");
     LOG.info(msg);

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HRegionFileSystem.java

@@ -460,7 +460,7 @@ public class HRegionFileSystem {
       throw new FileNotFoundException(buildPath.toString());
     }
     if (LOG.isDebugEnabled()) {
-      LOG.debug("Committing store file " + buildPath + " as " + dstPath);
+      LOG.debug("Committing " + buildPath + " as " + dstPath);
     }
     return dstPath;
   }

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HRegionServer.java

@@ -3397,8 +3397,8 @@ public class HRegionServer extends HasThread implements
       LOG.warn("Not adding moved region record: " + encodedName + " to self.");
       return;
     }
-    LOG.info("Adding moved region record: "
-      + encodedName + " to " + destination + " as of " + closeSeqNum);
+    LOG.info("Adding " + encodedName + " move to " + destination + " record at close sequenceid=" +
+        closeSeqNum);
     movedRegions.put(encodedName, new MovedRegionInfo(destination, closeSeqNum));
   }
 

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/HStore.java

@@ -955,7 +955,7 @@ public class HStore implements Store, HeapSize, StoreConfigInformation, Propagat
         }
         if (ioe != null) throw ioe;
       }
-      LOG.info("Closed {}", this);
+      LOG.trace("Closed {}", this);
       return result;
     } finally {
       this.lock.writeLock().unlock();

hbase-server/src/main/java/org/apache/hadoop/hbase/regionserver/handler/CloseRegionHandler.java

@@ -88,13 +88,13 @@ public class CloseRegionHandler extends EventHandler {
   @Override
   public void process() {
     try {
-      String name = regionInfo.getRegionNameAsString();
-      LOG.debug("Processing close of " + name);
+      String name = regionInfo.getEncodedName();
+      LOG.trace("Processing close of {}", name);
       String encodedRegionName = regionInfo.getEncodedName();
       // Check that this region is being served here
       HRegion region = (HRegion)rsServices.getRegion(encodedRegionName);
       if (region == null) {
-        LOG.warn("Received CLOSE for region " + name + " but currently not serving - ignoring");
+        LOG.warn("Received CLOSE for region {} but currently not serving - ignoring", name);
         // TODO: do better than a simple warning
         return;
       }
@@ -104,8 +104,7 @@ public class CloseRegionHandler extends EventHandler {
         if (region.close(abort) == null) {
           // This region got closed.  Most likely due to a split.
           // The split message will clean up the master state.
-          LOG.warn("Can't close region: was already closed during close(): " +
-            name);
+          LOG.warn("Can't close region {}, was already closed during close()", name);
           return;
         }
       } catch (IOException ioe) {