Log aggregate stats instead of individual calls

Author: DomGarguilo

server/manager/src/main/java/org/apache/accumulo/manager/tableOps/bulkVer2/LoadFiles.java

@@ -19,11 +19,11 @@
 package org.apache.accumulo.manager.tableOps.bulkVer2;
 
 import static java.nio.charset.StandardCharsets.UTF_8;
-import static java.util.concurrent.TimeUnit.MILLISECONDS;
 import static org.apache.accumulo.core.metadata.schema.TabletMetadata.ColumnType.LOADED;
 import static org.apache.accumulo.core.metadata.schema.TabletMetadata.ColumnType.LOCATION;
 import static org.apache.accumulo.core.metadata.schema.TabletMetadata.ColumnType.PREV_ROW;
 
+import java.time.Duration;
 import java.util.ArrayList;
 import java.util.Comparator;
 import java.util.HashMap;
@@ -315,6 +315,16 @@ long finish() throws Exception {
     }
   }
 
+  /**
+   * Stats for the loadFiles method. Helps track wasted time and iterations.
+   */
+  private static class ImportTimingStats {
+    Duration totalWastedTime = Duration.ZERO;
+    long wastedIterations = 0;
+    long tabletCount = 0;
+    long callCount = 0;
+  }
+
   /**
    * Make asynchronous load calls to each overlapping Tablet in the bulk mapping. Return a sleep
    * time to isReady based on a factor of the TabletServer with the most Tablets. This method will
@@ -344,20 +354,33 @@ private long loadFiles(TableId tableId, Path bulkDir, LoadMappingIterator loadMa
 
     loader.start(bulkDir, manager, tid, bulkInfo.setTime);
 
-    long t1 = System.currentTimeMillis();
+    ImportTimingStats importTimingStats = new ImportTimingStats();
+
+    Timer timer = Timer.startNew();
     while (lmi.hasNext()) {
       loadMapEntry = lmi.next();
       List<TabletMetadata> tablets =
-          findOverlappingTablets(fmtTid, loadMapEntry.getKey(), tabletIter);
+          findOverlappingTablets(fmtTid, loadMapEntry.getKey(), tabletIter, importTimingStats);
       loader.load(tablets, loadMapEntry.getValue());
     }
+    Duration totalProcessingTime = timer.elapsed();
 
     log.trace("{}: Completed Finding Overlapping Tablets", fmtTid);
 
+    if (importTimingStats.callCount > 0) {
+      log.info(
+          "Bulk import stats for {} (tid = {}): processed {} tablets in {} calls which took {}ms ({} nanos). Skipped {} iterations which took {}ms ({} nanos) or {}% of the processing time.",
+          bulkInfo.sourceDir, FateTxId.formatTid(tid), importTimingStats.tabletCount,
+          importTimingStats.callCount, totalProcessingTime.toMillis(),
+          totalProcessingTime.toNanos(), importTimingStats.wastedIterations,
+          importTimingStats.totalWastedTime.toMillis(), importTimingStats.totalWastedTime.toNanos(),
+          (importTimingStats.totalWastedTime.toNanos() * 100) / totalProcessingTime.toNanos());
+    }
+
     long sleepTime = loader.finish();
     if (sleepTime > 0) {
       log.trace("{}: Tablet Max Sleep is {}", fmtTid, sleepTime);
-      long scanTime = Math.min(System.currentTimeMillis() - t1, 30_000);
+      long scanTime = Math.min(totalProcessingTime.toMillis(), 30_000);
       log.trace("{}: Scan time is {}", fmtTid, scanTime);
       sleepTime = Math.max(sleepTime, scanTime * 2);
     }
@@ -372,7 +395,7 @@ private long loadFiles(TableId tableId, Path bulkDir, LoadMappingIterator loadMa
    * Find all the tablets within the provided bulk load mapping range.
    */
   private List<TabletMetadata> findOverlappingTablets(String fmtTid, KeyExtent loadRange,
-      Iterator<TabletMetadata> tabletIter) {
+      Iterator<TabletMetadata> tabletIter, ImportTimingStats importTimingStats) {
 
     TabletMetadata currTablet = null;
 
@@ -394,7 +417,7 @@ private List<TabletMetadata> findOverlappingTablets(String fmtTid, KeyExtent loa
         currTablet = tabletIter.next();
       }
 
-      long wastedMillis = timer.elapsed(MILLISECONDS);
+      Duration wastedTime = timer.elapsed();
 
       if (cmp != 0) {
         throw new IllegalStateException(
@@ -416,11 +439,10 @@ private List<TabletMetadata> findOverlappingTablets(String fmtTid, KeyExtent loa
         throw new IllegalStateException("Unexpected end row " + currTablet + " " + loadRange);
       }
 
-      if (wastedIterations > 0) {
-        log.debug(
-            "Skipped {} tablets searching for prevEndRow of loadRange in {} ms to return {} tablets total in {}ms.",
-            wastedIterations, wastedMillis, tablets.size(), timer.elapsed(MILLISECONDS));
-      }
+      importTimingStats.wastedIterations += wastedIterations;
+      importTimingStats.totalWastedTime = importTimingStats.totalWastedTime.plus(wastedTime);
+      importTimingStats.tabletCount += tablets.size();
+      importTimingStats.callCount++;
 
       return tablets;
     } catch (NoSuchElementException e) {