diff --git a/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/BasePerformanceEntry.java b/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/BasePerformanceEntry.java index 02271b9cae4..96cb58547f6 100644 --- a/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/BasePerformanceEntry.java +++ b/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,25 @@ 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(); + final QueryPerformanceRecorderState.ReadTracker readTracker = + QueryPerformanceRecorderState.getReadTrackerForCurrentThread(); + + startDataReadNanos = readTracker.getDataReadNanos(); + startDataReadCount = readTracker.getDataReadCount(); + startDataReadBytes = readTracker.getDataReadBytes(); + startMetadataReadNanos = readTracker.getMetadataReadNano(); + startMetadataReadCount = readTracker.getMetadataReadCount(); + startUserCpuNanos = ThreadProfiler.DEFAULT.getCurrentThreadUserTime(); startCpuNanos = ThreadProfiler.DEFAULT.getCurrentThreadCpuTime(); startTimeNanos = System.nanoTime(); @@ -54,12 +76,27 @@ public synchronized void onBaseEntryEnd() { allocatedBytes = plus(allocatedBytes, minus(ThreadProfiler.DEFAULT.getCurrentThreadAllocatedBytes(), startAllocatedBytes)); + final QueryPerformanceRecorderState.ReadTracker readTracker = + QueryPerformanceRecorderState.getReadTrackerForCurrentThread(); + + dataReadNanos += readTracker.getDataReadNanos() - startDataReadNanos; + dataReadCount += readTracker.getDataReadCount() - startDataReadCount; + dataReadBytes += readTracker.getDataReadBytes() - startDataReadBytes; + metadataReadNanos += readTracker.getMetadataReadNano() - startMetadataReadNanos; + metadataReadCount += readTracker.getMetadataReadCount() - 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 +109,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,6 +173,58 @@ 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{") @@ -131,7 +232,12 @@ public LogOutput append(@NotNull final LogOutput logOutput) { .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 +263,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; } } diff --git a/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/PerformanceEntry.java b/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/PerformanceEntry.java index 7126732f2d3..c5a79f53c2c 100644 --- a/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/PerformanceEntry.java +++ b/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) { diff --git a/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/QueryPerformanceLogThreshold.java b/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/QueryPerformanceLogThreshold.java index 670b5d298cc..c41b3fee6a0 100644 --- a/engine/table/src/main/java/io/deephaven/engine/table/impl/perf/QueryPerformanceLogThreshold.java +++ b/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. *