HDDS-11509. logging improvements for directory deletion

hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/impl/BlockDeletingService.java

@@ -33,6 +33,7 @@
 import org.apache.hadoop.ozone.container.common.transport.server.ratis.XceiverServerRatis;
 import org.apache.hadoop.ozone.container.keyvalue.statemachine.background.BlockDeletingTask;
 import org.apache.hadoop.ozone.container.ozoneimpl.OzoneContainer;
+import org.apache.hadoop.util.Time;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -133,12 +134,13 @@ public BackgroundTaskQueue getTasks() {
       // We must ensure there is no empty container in this result.
       // The chosen result depends on what container deletion policy is
       // configured.
+      long startTime = Time.monotonicNow();
+      int blocksLimitPerInterval = getBlockLimitPerInterval();
       List<ContainerBlockInfo> containers =
-          chooseContainerForBlockDeletion(getBlockLimitPerInterval(),
+          chooseContainerForBlockDeletion(blocksLimitPerInterval,
               containerDeletionPolicy);
 
-      BackgroundTask
-          containerBlockInfos = null;
+      BackgroundTask containerBlockInfos = null;
       long totalBlocks = 0;
       for (ContainerBlockInfo containerBlockInfo : containers) {
         BlockDeletingTaskBuilder builder =
@@ -153,8 +155,8 @@ public BackgroundTaskQueue getTasks() {
       metrics.incrTotalBlockChosenCount(totalBlocks);
       metrics.incrTotalContainerChosenCount(containers.size());
       if (containers.size() > 0) {
-        LOG.debug("Queued {} blocks from {} containers for deletion",
-            totalBlocks, containers.size());
+        LOG.info("Queued {} blocks from {} containers for deletion, blocksLimit was {}, elapsed time {}ms.",
+            totalBlocks, containers.size(), blocksLimitPerInterval, Time.monotonicNow() - startTime);
       }
     } catch (StorageContainerException e) {
       LOG.warn("Failed to initiate block deleting tasks, "

hadoop-ozone/ozone-manager/src/main/java/org/apache/hadoop/ozone/om/service/AbstractKeyDeletingService.java

@@ -402,6 +402,7 @@ public long optimizeDirDeletesAndSubmitRequest(long remainNum,
       int remainingBufLimit, KeyManager keyManager,
       UUID expectedPreviousSnapshotId) {
 
+    long limit = remainNum;
     // Optimization to handle delete sub-dir and keys to remove quickly
     // This case will be useful to handle when depth of directory is high
     int subdirDelNum = 0;
@@ -452,9 +453,9 @@ public long optimizeDirDeletesAndSubmitRequest(long remainNum,
       LOG.info("Number of dirs deleted: {}, Number of sub-dir " +
               "deleted: {}, Number of sub-files moved:" +
               " {} to DeletedTable, Number of sub-dirs moved {} to " +
-              "DeletedDirectoryTable, iteration elapsed: {}ms," +
+              "DeletedDirectoryTable, current iteration limit: {}, iteration elapsed: {}ms," +
               " totalRunCount: {}",
-          dirNum, subdirDelNum, subFileNum, (subDirNum - subdirDelNum),
+          dirNum, subdirDelNum, subFileNum, (subDirNum - subdirDelNum), limit,
           Time.monotonicNow() - startTime, getRunCount());
     }
     return remainNum;

hadoop-ozone/ozone-manager/src/main/java/org/apache/hadoop/ozone/om/service/DirectoryDeletingService.java

@@ -154,11 +154,11 @@ public int getPriority() {
     @Override
     public BackgroundTaskResult call() {
       if (shouldRun()) {
+        isRunningOnAOS.set(true);
+        final long run = getRunCount().incrementAndGet();
         if (LOG.isDebugEnabled()) {
-          LOG.debug("Running DirectoryDeletingService");
+          LOG.debug("Running DirectoryDeletingService {}", run);
         }
-        isRunningOnAOS.set(true);
-        getRunCount().incrementAndGet();
         long dirNum = 0L;
         long subDirNum = 0L;
         long subFileNum = 0L;

hadoop-ozone/ozone-manager/src/main/java/org/apache/hadoop/ozone/om/service/OpenKeyCleanupService.java

@@ -32,6 +32,7 @@
 import org.apache.hadoop.ozone.om.OzoneManager;
 import org.apache.hadoop.ozone.om.helpers.BucketLayout;
 import org.apache.hadoop.ozone.om.ratis.utils.OzoneManagerRatisUtils;
+import org.apache.hadoop.ozone.protocol.proto.OzoneManagerProtocolProtos;
 import org.apache.hadoop.ozone.protocol.proto.OzoneManagerProtocolProtos.CommitKeyRequest;
 import org.apache.hadoop.ozone.protocol.proto.OzoneManagerProtocolProtos.DeleteOpenKeysRequest;
 import org.apache.hadoop.ozone.protocol.proto.OzoneManagerProtocolProtos.OMRequest;
@@ -50,6 +51,7 @@
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicLong;
+import java.util.stream.Collectors;
 import java.util.stream.Stream;
 
 /**
@@ -189,7 +191,9 @@ public BackgroundTaskResult call() throws Exception {
       if (!shouldRun()) {
         return BackgroundTaskResult.EmptyTaskResult.newResult();
       }
-      runCount.incrementAndGet();
+      final long run = runCount.incrementAndGet();
+      LOG.debug("Running OpenKeyCleanupService {}", run);
+
       long startTime = Time.monotonicNow();
       final ExpiredOpenKeys expiredOpenKeys;
       try {
@@ -212,6 +216,16 @@ public BackgroundTaskResult call() throws Exception {
         final OMResponse response = submitRequest(omRequest);
         if (response != null && response.getSuccess()) {
           ozoneManager.getMetrics().incNumOpenKeysCleaned(numOpenKeys);
+          if (LOG.isDebugEnabled()) {
+            StringBuilder sb = new StringBuilder();
+            for (OpenKeyBucket.Builder openKey : openKeyBuckets) {
+              sb.append(openKey.getVolumeName() + "." +  openKey.getBucketName() + ": ")
+                  .append(openKey.getKeysList().stream().map(OzoneManagerProtocolProtos.OpenKey::getName)
+                      .collect(Collectors.toList()))
+                  .append("\n");
+            }
+            LOG.debug("Non-hsync'ed openKeys being deleted in current iteration: \n" + sb);
+          }
         }
       }
 
@@ -224,15 +238,22 @@ public BackgroundTaskResult call() throws Exception {
           final OMResponse response = submitRequest(createCommitKeyRequest(b));
           if (response != null && response.getSuccess()) {
             ozoneManager.getMetrics().incNumOpenKeysHSyncCleaned();
+            if (LOG.isDebugEnabled()) {
+              StringBuilder sb = new StringBuilder();
+              for (CommitKeyRequest.Builder openKey : hsyncKeys) {
+                sb.append(openKey.getKeyArgs().getVolumeName() + "." +  openKey.getKeyArgs().getBucketName() + ": ")
+                    .append(openKey.getKeyArgs().getKeyName())
+                    .append(", ");
+              }
+              LOG.debug("hsync'ed openKeys committed in current iteration: \n" + sb);
+            }
           }
         });
       }
 
-      if (LOG.isDebugEnabled()) {
-        LOG.debug("Number of expired open keys submitted for deletion: {},"
-                + " for commit: {}, elapsed time: {}ms",
-            numOpenKeys, numHsyncKeys, Time.monotonicNow() - startTime);
-      }
+      LOG.info("Number of expired open keys submitted for deletion: {},"
+              + " for commit: {}, cleanupLimit: {}, elapsed time: {}ms",
+          numOpenKeys, numHsyncKeys, cleanupLimitPerTask, Time.monotonicNow() - startTime);
       final int numKeys = numOpenKeys + numHsyncKeys;
       submittedOpenKeyCount.addAndGet(numKeys);
       return () -> numKeys;