feat: DH-18079: Record data read info across performance logs QPL, QOPL, and UPL

engine/table/src/main/java/io/deephaven/engine/table/impl/perf/BasePerformanceEntry.java

@@ -16,6 +16,7 @@
  * A smaller entry that simply records usage data, meant for aggregating into the larger entry.
  */
 public class BasePerformanceEntry implements LogOutputAppendable {
+
     private long usageNanos;
 
     private long cpuNanos;
@@ -24,6 +25,12 @@ public class BasePerformanceEntry implements LogOutputAppendable {
     private long allocatedBytes;
     private long poolAllocatedBytes;
 
+    private long dataReadNanos;
+    private long dataReadCount;
+    private long dataReadBytes;
+    private long metadataReadNanos;
+    private long metadataReadCount;
+
     private long startTimeNanos;
 
     private long startCpuNanos;
@@ -32,10 +39,22 @@ public class BasePerformanceEntry implements LogOutputAppendable {
     private long startAllocatedBytes;
     private long startPoolAllocatedBytes;
 
+    private long startDataReadNanos;
+    private long startDataReadCount;
+    private long startDataReadBytes;
+    private long startMetadataReadNanos;
+    private long startMetadataReadCount;
+
     public synchronized void onBaseEntryStart() {
         startAllocatedBytes = ThreadProfiler.DEFAULT.getCurrentThreadAllocatedBytes();
         startPoolAllocatedBytes = QueryPerformanceRecorderState.getPoolAllocatedBytesForCurrentThread();
 
+        startDataReadNanos = QueryPerformanceRecorderState.getDataReadNanosForCurrentThread();
+        startDataReadCount = QueryPerformanceRecorderState.getDataReadCountForCurrentThread();
+        startDataReadBytes = QueryPerformanceRecorderState.getDataReadBytesForCurrentThread();
+        startMetadataReadNanos = QueryPerformanceRecorderState.getMetadataReadNanosForCurrentThread();
+        startMetadataReadCount = QueryPerformanceRecorderState.getMetadataReadCountForCurrentThread();
+
         startUserCpuNanos = ThreadProfiler.DEFAULT.getCurrentThreadUserTime();
         startCpuNanos = ThreadProfiler.DEFAULT.getCurrentThreadCpuTime();
         startTimeNanos = System.nanoTime();
@@ -54,12 +73,26 @@ public synchronized void onBaseEntryEnd() {
         allocatedBytes = plus(allocatedBytes,
                 minus(ThreadProfiler.DEFAULT.getCurrentThreadAllocatedBytes(), startAllocatedBytes));
 
+        dataReadNanos += QueryPerformanceRecorderState.getDataReadNanosForCurrentThread() - startDataReadNanos;
+        dataReadCount += QueryPerformanceRecorderState.getDataReadCountForCurrentThread() - startDataReadCount;
+        dataReadBytes += QueryPerformanceRecorderState.getDataReadBytesForCurrentThread() - startDataReadBytes;
+        metadataReadNanos +=
+                QueryPerformanceRecorderState.getMetadataReadNanosForCurrentThread() - startMetadataReadNanos;
+        metadataReadCount +=
+                QueryPerformanceRecorderState.getMetadataReadCountForCurrentThread() - startMetadataReadCount;
+
         startAllocatedBytes = 0;
         startPoolAllocatedBytes = 0;
 
         startUserCpuNanos = 0;
         startCpuNanos = 0;
         startTimeNanos = 0;
+
+        startDataReadNanos = 0;
+        startDataReadCount = 0;
+        startDataReadBytes = 0;
+        startMetadataReadNanos = 0;
+        startMetadataReadCount = 0;
     }
 
     synchronized void baseEntryReset() {
@@ -72,6 +105,18 @@ synchronized void baseEntryReset() {
 
         allocatedBytes = 0;
         poolAllocatedBytes = 0;
+
+        dataReadNanos = 0;
+        dataReadCount = 0;
+        dataReadBytes = 0;
+        metadataReadNanos = 0;
+        metadataReadCount = 0;
+
+        startDataReadNanos = 0;
+        startDataReadCount = 0;
+        startDataReadBytes = 0;
+        startMetadataReadNanos = 0;
+        startMetadataReadCount = 0;
     }
 
     /**
@@ -124,14 +169,71 @@ public long getPoolAllocatedBytes() {
         return poolAllocatedBytes;
     }
 
+    /**
+     * Get the aggregate time spent reading data in nanoseconds. This getter should be called by exclusive owners of the
+     * entry, and never concurrently with mutators.
+     *
+     * @return total data read time in nanos
+     */
+    public long getDataReadNanos() {
+        return dataReadNanos;
+    }
+
+    /**
+     * Get the aggregate number of data read operations. This getter should be called by exclusive owners of the entry,
+     * and never concurrently with mutators.
+     *
+     * @return total number of data read operations
+     */
+    public long getDataReadCount() {
+        return dataReadCount;
+    }
+
+    /**
+     * Get the aggregate number of bytes read in data read operations. This getter should be called by exclusive owners
+     * of the entry, and never concurrently with mutators.
+     *
+     * @return total number of bytes read
+     */
+    public long getDataReadBytes() {
+        return dataReadBytes;
+    }
+
+    /**
+     * Get the aggregate time spent on metadata operations (e.g. listing files, checking existence, determining file
+     * sizes) in nanoseconds. This getter should be called by exclusive owners of the entry, and never concurrently with
+     * mutators.
+     *
+     * @return total metadata operation time in nanos
+     */
+    public long getMetadataReadNanos() {
+        return metadataReadNanos;
+    }
+
+    /**
+     * Get the aggregate number of metadata operations. This getter should be called by exclusive owners of the entry,
+     * and never concurrently with mutators.
+     *
+     * @return total number of metadata operations
+     */
+    public long getMetadataReadCount() {
+        return metadataReadCount;
+    }
+
+
     @Override
     public LogOutput append(@NotNull final LogOutput logOutput) {
         final LogOutput currentValues = logOutput.append("BasePerformanceEntry{")
                 .append(", intervalUsageNanos=").append(usageNanos)
                 .append(", intervalCpuNanos=").append(cpuNanos)
                 .append(", intervalUserCpuNanos=").append(userCpuNanos)
                 .append(", intervalAllocatedBytes=").append(allocatedBytes)
-                .append(", intervalPoolAllocatedBytes=").append(poolAllocatedBytes);
+                .append(", intervalPoolAllocatedBytes=").append(poolAllocatedBytes)
+                .append(", dataReadNanos=").append(dataReadNanos)
+                .append(", dataReadCount=").append(dataReadCount)
+                .append(", dataReadBytes=").append(dataReadBytes)
+                .append(", metadataReadNanos=").append(metadataReadNanos)
+                .append(", metadataReadCount=").append(metadataReadCount);
         return appendStart(currentValues)
                 .append('}');
     }
@@ -157,5 +259,11 @@ public synchronized void accumulate(@NotNull final BasePerformanceEntry entry) {
 
         this.allocatedBytes = plus(this.allocatedBytes, entry.allocatedBytes);
         this.poolAllocatedBytes = plus(this.poolAllocatedBytes, entry.poolAllocatedBytes);
+
+        this.dataReadNanos += entry.dataReadNanos;
+        this.dataReadCount += entry.dataReadCount;
+        this.dataReadBytes += entry.dataReadBytes;
+        this.metadataReadNanos += entry.metadataReadNanos;
+        this.metadataReadCount += entry.metadataReadCount;
     }
 }

engine/table/src/main/java/io/deephaven/engine/table/impl/perf/PerformanceEntry.java

@@ -237,7 +237,8 @@ boolean shouldLogEntryInterval() {
             loggedOnce = true;
             return true;
         }
-        return invocationCount > 0 && UpdatePerformanceTracker.LOG_THRESHOLD.shouldLog(getUsageNanos());
+        return invocationCount > 0
+                && UpdatePerformanceTracker.LOG_THRESHOLD.shouldLog(getUsageNanos(), getDataReadCount());
     }
 
     public void accumulate(PerformanceEntry entry) {

engine/table/src/main/java/io/deephaven/engine/table/impl/perf/QueryPerformanceLogThreshold.java

@@ -11,9 +11,10 @@
  */
 public class QueryPerformanceLogThreshold {
     private final long minimumDurationNanos;
+    private final long minimumReadCount;
 
     /**
-     * Create a log threshold object for a particular kind of log update
+     * Create a log threshold object for a particular kind of log update.
      * <ul>
      * <li>"" is for instrumented QueryPerformanceLog/QueryOperationPerformanceLog nuggets</li>
      * <li>"Uninstrumented" is for uninstrumented QueryPerformanceLog/QueryOperationPerformanceLog nuggets, and
@@ -22,50 +23,60 @@ public class QueryPerformanceLogThreshold {
      *
      * @param kind kind of update to derive property names
      * @param defaultDuration default value for duration nanos
-     * @param defaultRepeatedReads default value for repeated read threshold
-     * @param defaultInitialReads default value for initial read threshold
+     * @param defaultReadCount default value for the minimum read count threshold
      */
-    private QueryPerformanceLogThreshold(String kind, long defaultDuration, long defaultRepeatedReads,
-            long defaultInitialReads) {
+    public QueryPerformanceLogThreshold(String kind, long defaultDuration, long defaultReadCount) {
         minimumDurationNanos = Configuration.getInstance()
                 .getLongWithDefault("QueryPerformance.minimum" + kind + "LogDurationNanos", defaultDuration);
+        minimumReadCount = Configuration.getInstance()
+                .getLongWithDefault("QueryPerformance.minimum" + kind + "LogReadCount", defaultReadCount);
     }
 
     /**
-     * Create a log threshold object for a particular kind of log update
+     * Create a log threshold object for a particular kind of log update. The minimum read count defaults to 1.
      * <ul>
      * <li>"" is for instrumented QueryPerformanceLog/QueryOperationPerformanceLog nuggets</li>
      * <li>"Uninstrumented" is for uninstrumented QueryPerformanceLog/QueryOperationPerformanceLog nuggets, and
      * <li>"Update" is for UpdatePerformanceLog entry intervals.</li>
      * </ul>
      *
-     * The initial and repeated read threshold defaults to 1.
-     *
      * @param kind kind of update to derive property names
      * @param defaultDuration default value for duration nanos
      */
     public QueryPerformanceLogThreshold(String kind, long defaultDuration) {
-        this(kind, defaultDuration, 1, 1);
+        this(kind, defaultDuration, 1);
     }
 
     /**
-     * The minimum duration for an QueryPerformanceNugget to be logged based on its duration (or entry interval usage
-     * for the UpdatePerformanceLog). The value 0 logs everything. The value -1 will not log anything based on duration.
+     * The minimum duration for a QueryPerformanceNugget to be logged based on its duration (or entry interval usage for
+     * the UpdatePerformanceLog). The value 0 logs everything. The value -1 will not log anything based on duration.
      */
     private long getMinimumDurationNanos() {
         return minimumDurationNanos;
     }
 
+    /**
+     * The minimum data read count for a QueryPerformanceNugget to be logged. The value 0 means that reads alone will
+     * never trigger logging. The default value of 1 means any read will trigger logging.
+     */
+    private long getMinimumReadCount() {
+        return minimumReadCount;
+    }
+
     /**
      * Should this item be logged?
      *
      * @param duration the duration (or usage) of the item
+     * @param dataReadCount the number of data read operations performed
      * @return true if the item exceeds our logging threshold, and thus should be logged
      */
-    public boolean shouldLog(final long duration) {
+    public boolean shouldLog(final long duration, final long dataReadCount) {
         if (getMinimumDurationNanos() >= 0 && duration >= getMinimumDurationNanos()) {
             return true;
         }
+        if (getMinimumReadCount() > 0 && dataReadCount >= getMinimumReadCount()) {
+            return true;
+        }
         return false;
     }
 }

engine/table/src/main/java/io/deephaven/engine/table/impl/perf/QueryPerformanceNugget.java

@@ -29,14 +29,15 @@ public class QueryPerformanceNugget extends BasePerformanceEntry implements Safe
     private static final int MAX_DESCRIPTION_LENGTH = 16 << 10;
 
     /**
-     * A re-usable "dummy" nugget which will never collect any information or be recorded.
+     * A re-usable "dummy" nugget that will never collect any information or be recorded.
      */
     static final QueryPerformanceNugget DUMMY_NUGGET = new QueryPerformanceNugget() {
         @Override
         public void accumulate(@NotNull BasePerformanceEntry entry) {
             // non-synchronized no-op override
         }
 
+
         @Override
         public boolean shouldLog() {
             return false;

engine/table/src/main/java/io/deephaven/engine/table/impl/perf/QueryPerformanceRecorderImpl.java

@@ -290,9 +290,9 @@ private boolean shouldLogNugget(@NotNull QueryPerformanceNugget nugget) {
             // abnormal condition and the nugget should be logged
             return true;
         } else if (nugget == catchAllNugget) {
-            return UNINSTRUMENTED_LOG_THRESHOLD.shouldLog(nugget.getUsageNanos());
+            return UNINSTRUMENTED_LOG_THRESHOLD.shouldLog(nugget.getUsageNanos(), nugget.getDataReadCount());
         } else {
-            return LOG_THRESHOLD.shouldLog(nugget.getUsageNanos());
+            return LOG_THRESHOLD.shouldLog(nugget.getUsageNanos(), nugget.getDataReadCount());
         }
     }