From 71435d55ba52b44f02c9d376858e229f57f6006d Mon Sep 17 00:00:00 2001
From: Ivan Bella <ivan@bella.name>
Date: Tue, 17 Sep 2024 15:03:18 +0000
Subject: [PATCH] Added timing details around fillSet (#2540)

---
 ...DatawaveFieldIndexCachingIteratorJexl.java | 22 ++++++++++++++++---
 1 file changed, 19 insertions(+), 3 deletions(-)

diff --git a/warehouse/query-core/src/main/java/datawave/core/iterators/DatawaveFieldIndexCachingIteratorJexl.java b/warehouse/query-core/src/main/java/datawave/core/iterators/DatawaveFieldIndexCachingIteratorJexl.java
index 1dcc248d6f4..f9a7ce19cb8 100644
--- a/warehouse/query-core/src/main/java/datawave/core/iterators/DatawaveFieldIndexCachingIteratorJexl.java
+++ b/warehouse/query-core/src/main/java/datawave/core/iterators/DatawaveFieldIndexCachingIteratorJexl.java
@@ -769,8 +769,8 @@ protected void findTop() throws IOException {
                     // no need to check containership if not returning sorted uids
                     if (!sortedUIDs || this.lastRangeSeeked.contains(key)) {
                         this.topKey = key;
-                        if (log.isDebugEnabled()) {
-                            log.debug("setting as topKey " + topKey);
+                        if (log.isTraceEnabled()) {
+                            log.trace("setting as topKey " + topKey);
                         }
                         break;
                     }
@@ -879,6 +879,7 @@ private void fillSortedSets() throws IOException {
         if (log.isDebugEnabled()) {
             log.debug("Processing " + boundingFiRanges + " for " + this);
         }
+        long startFillSets = System.currentTimeMillis();
 
         TotalResults totalResults = new TotalResults(maxResults);
 
@@ -916,8 +917,11 @@ private void fillSortedSets() throws IOException {
             }
         }
 
+        long fillSetTiming = System.currentTimeMillis() - startFillSets;
+        log.info("Filled ivarator sets for " + boundingFiRanges.size() + " ranges took " + fillSetTiming + "ms for " + this);
+
         if (failed) {
-            log.error("Failed to complete ivarator cache: " + result, exception);
+            log.error("Failed to complete ivarator cache: " + result + " for " + this, exception);
             throw new IvaratorException("Failed to complete ivarator cache: " + result, exception);
         }
 
@@ -1102,6 +1106,7 @@ protected Future<?> fillSet(final Range boundingFiRange, final TotalResults tota
 
         // create runnable
         Runnable runnable = () -> {
+            long startFillSet = System.currentTimeMillis();
             if (log.isDebugEnabled()) {
                 log.debug("Starting fillSet(" + boundingFiRange + ')');
             }
@@ -1210,6 +1215,8 @@ protected Future<?> fillSet(final Range boundingFiRange, final TotalResults tota
                 log.error("Failed to complete fillSet(" + boundingFiRange + ")", e);
                 throw new RuntimeException(e);
             } finally {
+                long timing = System.currentTimeMillis() - startFillSet;
+                log.info("Completed " + boundingFiRange + " ivarator in " + timing + "ms");
                 // return the ivarator source back to the pool.
                 returnPoolSource(source);
                 if (log.isDebugEnabled()) {
@@ -1644,4 +1651,13 @@ public void setCollectTimingDetails(boolean collectTimingDetails) {
     public void setQuerySpanCollector(QuerySpanCollector querySpanCollector) {
         this.querySpanCollector = querySpanCollector;
     }
+
+    @Override
+    public String toString() {
+        StringBuilder builder = new StringBuilder();
+        builder.append("DatawaveFieldIndexCachingIteratorJexl (").append(queryId).append(") fName=").append(getFieldName()).append(", fValue=")
+                        .append(getFieldValue()).append(", negated=").append(isNegated()).append("}");
+        return builder.toString();
+    }
+
 }