Improves GC logging

Adds batch counter to log messages.
Adds in-progress counters to long-running methods.

Author: ddanielr

server/gc/src/main/java/org/apache/accumulo/gc/GCRun.java

@@ -25,6 +25,7 @@
 
 import java.io.FileNotFoundException;
 import java.io.IOException;
+import java.time.Duration;
 import java.util.ArrayList;
 import java.util.Collection;
 import java.util.Collections;
@@ -38,6 +39,7 @@
 import java.util.SortedMap;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicInteger;
 import java.util.stream.Stream;
 
 import org.apache.accumulo.core.Constants;
@@ -65,6 +67,7 @@
 import org.apache.accumulo.core.metadata.schema.TabletsMetadata;
 import org.apache.accumulo.core.security.Authorizations;
 import org.apache.accumulo.core.util.Pair;
+import org.apache.accumulo.core.util.Timer;
 import org.apache.accumulo.core.util.UtilWaitThread;
 import org.apache.accumulo.core.util.threads.ThreadPools;
 import org.apache.accumulo.core.volume.Volume;
@@ -99,12 +102,14 @@ public class GCRun implements GarbageCollectionEnvironment {
   private long inUse = 0;
   private long deleted = 0;
   private long errors = 0;
+  private AtomicInteger batchCount;
 
   public GCRun(Ample.DataLevel level, ServerContext context) {
     this.log = LoggerFactory.getLogger(GCRun.class.getName() + "." + level.name());
     this.level = level;
     this.context = context;
     this.config = context.getConfiguration();
+    this.batchCount = new AtomicInteger(0);
   }
 
   @Override
@@ -132,7 +137,8 @@ public void deleteGcCandidates(Collection<GcCandidate> gcCandidates, GcCandidate
       return;
     }
 
-    log.info("Attempting to delete gcCandidates of type {} from metadata", type);
+    log.info("Batch {} attempting to delete {} gcCandidates of type {} from metadata",
+        batchCount.get(), gcCandidates.size(), type);
     context.getAmple().deleteGcCandidates(level, gcCandidates, type);
   }
 
@@ -143,6 +149,7 @@ public List<GcCandidate> readCandidatesThatFitInMemory(Iterator<GcCandidate> can
     long candidateBatchSize = getCandidateBatchSize() / 2;
 
     List<GcCandidate> candidatesBatch = new ArrayList<>();
+    batchCount.incrementAndGet();
 
     while (candidates.hasNext()) {
       GcCandidate candidate = candidates.next();
@@ -295,8 +302,12 @@ public void deleteConfirmedCandidates(SortedMap<String,GcCandidate> confirmedDel
 
     final List<Pair<Path,Path>> replacements = context.getVolumeReplacements();
 
+    log.debug("Batch {} attempting to delete {} gcCandidate files", batchCount.get(),
+        confirmedDeletes.size());
+    int deleteCounter = 0;
+    Timer timer = Timer.startNew();
     for (final GcCandidate delete : confirmedDeletes.values()) {
-
+      deleteCounter++;
       Runnable deleteTask = () -> {
         boolean removeFlag = false;
 
@@ -320,7 +331,7 @@ public void deleteConfirmedCandidates(SortedMap<String,GcCandidate> confirmedDel
           }
 
           for (Path pathToDel : GcVolumeUtil.expandAllVolumesUri(fs, fullPath)) {
-            log.debug("{} Deleting {}", fileActionPrefix, pathToDel);
+            log.debug("Batch {} {} Deleting {}", batchCount.get(), fileActionPrefix, pathToDel);
 
             if (moveToTrash(pathToDel) || fs.deleteRecursively(pathToDel)) {
               // delete succeeded, still want to delete
@@ -368,6 +379,11 @@ public void deleteConfirmedCandidates(SortedMap<String,GcCandidate> confirmedDel
       };
 
       deleteThreadPool.execute(deleteTask);
+      if (timer.hasElapsed(Duration.ofMinutes(1))) {
+        log.info("Batch {} deleting file {} of {}", batchCount.get(), deleteCounter,
+            confirmedDeletes.size());
+        timer.restart();
+      }
     }
 
     deleteThreadPool.shutdown();
@@ -451,7 +467,10 @@ static void minimizeDeletes(SortedMap<String,GcCandidate> confirmedDeletes,
 
     String lastDirRel = null;
     Path lastDirAbs = null;
+    Timer progressTimer = Timer.startNew();
+    int progressCount = 0;
     while (cdIter.hasNext()) {
+      progressCount++;
       Map.Entry<String,GcCandidate> entry = cdIter.next();
       String relPath = entry.getKey();
       Path absPath = new Path(entry.getValue().getPath());
@@ -492,6 +511,10 @@ static void minimizeDeletes(SortedMap<String,GcCandidate> confirmedDeletes,
         }
       }
     }
+    if (progressTimer.hasElapsed(Duration.ofMinutes(1))) {
+      logger.debug("Minimizing delete {} of {}", progressCount, confirmedDeletes.size());
+      progressTimer.restart();
+    }
   }
 
   /**

server/gc/src/main/java/org/apache/accumulo/gc/GarbageCollectionAlgorithm.java

@@ -387,6 +387,7 @@ public long collect(GarbageCollectionEnvironment gce)
 
     Iterator<GcCandidate> candidatesIter = gce.getCandidates();
     long totalBlips = 0;
+    int batchCount = 0;
 
     while (candidatesIter.hasNext()) {
       List<GcCandidate> batchOfCandidates;
@@ -399,19 +400,21 @@ public long collect(GarbageCollectionEnvironment gce)
       } finally {
         candidatesSpan.end();
       }
-      totalBlips = deleteBatch(gce, batchOfCandidates);
+      batchCount++;
+      totalBlips = deleteBatch(gce, batchOfCandidates, batchCount);
     }
     return totalBlips;
   }
 
   /**
    * Given a sub-list of possible deletion candidates, process and remove valid deletion candidates.
    */
-  private long deleteBatch(GarbageCollectionEnvironment gce, List<GcCandidate> currentBatch)
-      throws InterruptedException, TableNotFoundException, IOException {
+  private long deleteBatch(GarbageCollectionEnvironment gce, List<GcCandidate> currentBatch,
+      int batchCount) throws InterruptedException, TableNotFoundException, IOException {
 
     long origSize = currentBatch.size();
     gce.incrementCandidatesStat(origSize);
+    log.debug("Batch {} total deletion candidates: {}", batchCount, origSize);
 
     SortedMap<String,GcCandidate> candidateMap = makeRelative(currentBatch);