Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add SafePoint times to UpdateGraphProcessor cycle times logging. #2123

Merged
merged 17 commits into from
Apr 1, 2022
Merged
Show file tree
Hide file tree
Changes from 6 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
53 changes: 30 additions & 23 deletions IO/src/main/java/io/deephaven/io/log/LogEntry.java
Original file line number Diff line number Diff line change
Expand Up @@ -91,56 +91,63 @@ default LogEntry appendDouble(Double f) {
}

/**
* Append a double to the given number of decimal places, rounding up.
* Append a double to the exact given number of decimal places, rounding half up.
*
* @param doubleValue a double value to append to the logEntry
* @param decimalPlaces a positive integer between 0 and 9
* @return the resulting {@code LogEntry}
*/
default LogEntry appendDoubleToDecimalPlaces(final double doubleValue, final int decimalPlaces) {
return appendDoubleDecimalPlacesImpl(this, doubleValue, decimalPlaces, true);
default LogEntry appendDouble(final double doubleValue, final int decimalPlaces) {
return appendDoubleDecimalPlacesImpl(this, doubleValue, decimalPlaces, decimalPlaces);
}

/**
* Append a double with decimal places up to the given number.
* Append a double rounded to the given number of decimal places, rounding half up. If to the given decimal places
* of precision
*
* @param doubleValue a double value to append to the logEntry
* @param decimalPlaces a positive integer between 0 and 9
* @param decimalPlaces a positive integer between 0 and 9 for the target number of decimal places to round to
* @param maxTrailingZeroesToDiscard a positive integer between 0 and 9 for the maximum trailing zeroes (if any) to
* discard from the fractional part of the result. The fractional part of the result will have always at
* least {@code (decimalPlaces - maxTrailingZeroesToDiscard)} places.
* @return the resulting {@code LogEntry}
*/
default LogEntry appendDoubleToMaxDecimalPlaces(final double doubleValue, final int decimalPlaces) {
return appendDoubleDecimalPlacesImpl(this, doubleValue, decimalPlaces, false);
default LogEntry appendDouble(final double doubleValue, final int decimalPlaces,
final int maxTrailingZeroesToDiscard) {
return appendDoubleDecimalPlacesImpl(this, doubleValue, decimalPlaces,
decimalPlaces - maxTrailingZeroesToDiscard);
}

private static LogEntry appendDoubleDecimalPlacesImpl(
LogEntry entry, final double doubleValue, final int decimalPlaces, final boolean exact) {
final int decimalPlacesAsPowerOf10 = MathUtil.pow10(decimalPlaces);
LogEntry entry, final double doubleValue, final int roundToDecimalPlaces, final int minDecimalPlaces) {
if (roundToDecimalPlaces < 0 || roundToDecimalPlaces > 9) {
throw new IllegalArgumentException("Invalid value for decimalPlaces = " + roundToDecimalPlaces);
}
final int roundToAsPowerOf10 = MathUtil.pow10(roundToDecimalPlaces);
final boolean negative = doubleValue < 0.0;
final long longWeightedValue;
if (negative) {
longWeightedValue = -(long) (-0.5 + doubleValue * decimalPlacesAsPowerOf10);
longWeightedValue = -(long) (-0.5 + doubleValue * roundToAsPowerOf10);
} else {
longWeightedValue = (long) (0.5 + doubleValue * decimalPlacesAsPowerOf10);
longWeightedValue = (long) (0.5 + doubleValue * roundToAsPowerOf10);
}
final long integral = longWeightedValue / decimalPlacesAsPowerOf10;
final long integral = longWeightedValue / roundToAsPowerOf10;
if (negative) {
entry = entry.append(-integral);
} else {
entry = entry.append(integral);
}
if (decimalPlaces == 0) {
if (roundToDecimalPlaces == 0) {
return entry;
}
int fractional = (int) (longWeightedValue % decimalPlacesAsPowerOf10);
int actualDecimalPlaces = decimalPlaces;
if (!exact) {
while (fractional > 0 && (fractional % 10 == 0)) {
fractional /= 10;
--actualDecimalPlaces;
}
if (fractional == 0) {
return entry;
}
int fractional = (int) (longWeightedValue % roundToAsPowerOf10);
int actualDecimalPlaces = roundToDecimalPlaces;
while (minDecimalPlaces < actualDecimalPlaces && fractional > 0 && (fractional % 10 == 0)) {
fractional /= 10;
--actualDecimalPlaces;
}
if (minDecimalPlaces == 0 && fractional == 0) {
return entry;
}
entry = entry.append(".");
final int base10FractionalDigits = MathUtil.base10digits(fractional);
Expand Down
48 changes: 28 additions & 20 deletions IO/src/test/java/io/deephaven/io/log/impl/TestLogOutput.java
Original file line number Diff line number Diff line change
Expand Up @@ -63,24 +63,28 @@ public void testBoolean() {
}

public void testPositiveDoubleToDecimalPlaces() {
logger.info().appendDoubleToDecimalPlaces(1.2345, 3).end();
logger.info().appendDoubleToDecimalPlaces(0.112255, 2).end();
logger.info().appendDoubleToDecimalPlaces(11111111.112255, 3).end();
logger.info().appendDoubleToDecimalPlaces(11111111.112255, 4).end();
logger.info().appendDoubleToDecimalPlaces(1111.4, 0).end();
logger.info().appendDoubleToDecimalPlaces(1111.5, 0).end();
logger.info().appendDoubleToDecimalPlaces(111.1234567894, 9).end();
logger.info().appendDoubleToDecimalPlaces(111.1234567895, 9).end();
logger.info().appendDoubleToMaxDecimalPlaces(111.1234567895, 9).end();
logger.info().appendDoubleToDecimalPlaces(111.123456789, 9).end();
logger.info().appendDoubleToMaxDecimalPlaces(111.123456789, 9).end();
logger.info().appendDoubleToDecimalPlaces(111.12, 4).end();
logger.info().appendDoubleToMaxDecimalPlaces(111.12, 4).end();
logger.info().appendDoubleToDecimalPlaces(111.14, 2).end();
logger.info().appendDoubleToDecimalPlaces(111.15, 2).end();
logger.info().appendDoubleToDecimalPlaces(111.15, 0).end();
logger.info().appendDoubleToDecimalPlaces(0, 0).end();
logger.info().appendDoubleToDecimalPlaces(0, 3).end();
logger.info().appendDouble(1.2345, 3).end();
logger.info().appendDouble(0.112255, 2).end();
logger.info().appendDouble(11111111.112255, 3).end();
logger.info().appendDouble(11111111.112255, 4).end();
logger.info().appendDouble(1111.4, 0).end();
logger.info().appendDouble(1111.5, 0).end();
logger.info().appendDouble(111.1234567894, 9).end();
logger.info().appendDouble(111.1234567895, 9).end();
logger.info().appendDouble(111.1234567895, 9, 9).end();
logger.info().appendDouble(111.123456789, 9).end();
logger.info().appendDouble(111.123456789, 9, 9).end();
logger.info().appendDouble(111.12, 4).end();
logger.info().appendDouble(111.12, 4, 4).end();
logger.info().appendDouble(111.14, 2).end();
logger.info().appendDouble(111.15, 2).end();
logger.info().appendDouble(111.15, 0).end();
logger.info().appendDouble(0, 0).end();
logger.info().appendDouble(0, 3).end();
logger.info().appendDouble(111.1995, 3).end();
logger.info().appendDouble(111.1995, 3, 1).end();
logger.info().appendDouble(111.1995, 3, 2).end();
logger.info().appendDouble(111.1995, 3, 3).end();
String[] results = logger.takeAll();
int c = 0;
assertEquals("1.235", results[c++]);
Expand All @@ -101,11 +105,15 @@ public void testPositiveDoubleToDecimalPlaces() {
assertEquals("111", results[c++]);
assertEquals("0", results[c++]);
assertEquals("0.000", results[c++]);
assertEquals("111.200", results[c++]);
assertEquals("111.20", results[c++]);
assertEquals("111.2", results[c++]);
assertEquals("111.2", results[c++]);
}

public void testNegativeDoubleToDecimalPlaces() {
logger.info().appendDoubleToDecimalPlaces(-1.235, 2).end();
logger.info().appendDoubleToDecimalPlaces(-1.234, 2).end();
logger.info().appendDouble(-1.235, 2).end();
logger.info().appendDouble(-1.234, 2).end();
String[] results = logger.takeAll();
int c = 0;
assertEquals("-1.24", results[c++]);
Expand Down
25 changes: 0 additions & 25 deletions Util/src/main/java/io/deephaven/util/hotspot/HotSpot.java

This file was deleted.

Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,8 @@ def runtimeVersion = Integer.parseInt((String)project.findProperty('runtimeVersi
def testLanguageLevel = Integer.parseInt((String)project.findProperty('testLanguageLevel') ?: '11')
def testRuntimeVersion = Integer.parseInt((String)project.findProperty('testRuntimeVersion') ?: '11')

def excludeReleaseFlag = project.hasProperty('excludeReleaseFlag')

if (languageLevel > compilerVersion) {
throw new IllegalArgumentException("languageLevel must be less than or equal to compileVersion")
}
Expand Down Expand Up @@ -61,15 +63,15 @@ tasks.withType(JavaCompile).configureEach {
options.incremental = true
options.compilerArgs << '-parameters'

def isTestCompile = name == 'compileTestJava'
if (isTestCompile) {
if (compilerVersion != testLanguageLevel) {
options.release.set testLanguageLevel
if (!excludeReleaseFlag) {
def checkLevel = (name == 'compileTestJava') ? testLanguageLevel : languageLevel
if (compilerVersion != checkLevel) {
options.release.set checkLevel
}
} else {
if (compilerVersion != languageLevel) {
options.release.set languageLevel
}
// This is a special case; without this we still get a failure about
// --add-opens together with --release for the hotspot-impl module.
sourceCompatibility = languageLevel
jcferretti marked this conversation as resolved.
Show resolved Hide resolved
}
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,6 @@ enum ProjectType {
JAVA_EXTERNAL(true, 'io.deephaven.project.java-external'),
JAVA_LOCAL(false, 'io.deephaven.project.java-local'),
JAVA_PUBLIC(true, 'io.deephaven.project.java-public'),
JAVA_OPTIONAL_IMPL(true, 'io.deephaven.project.java-public'),
BOM_PUBLIC(true, 'io.deephaven.project.bom-public'),
ROOT(false, 'io.deephaven.project.root');

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,6 @@ class CombinedJavadoc {
}
switch (type) {
case ProjectType.BOM_PUBLIC:
case ProjectType.JAVA_OPTIONAL_IMPL:
return false
case ProjectType.JAVA_EXTERNAL:
case ProjectType.JAVA_PUBLIC:
Expand Down
1 change: 1 addition & 0 deletions debezium/perf/sample_top.py
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,7 @@

results={}
for line in top_out:
line = line.strip()
for name, regex in name_pidre.items():
if re.search(regex, line) is not None:
cols = line.split(maxsplit=12)
Expand Down
2 changes: 1 addition & 1 deletion engine/updategraph/build.gradle
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,9 @@ dependencies {
api project(':qst')

implementation project(':engine-chunk')
implementation project(':hotspot')

compileOnly 'com.google.code.findbugs:jsr305:3.0.2'
runtimeOnly project(':hotspot')

testImplementation 'junit:junit:4.13.2'

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
import io.deephaven.engine.liveness.LivenessScopeStack;
import io.deephaven.engine.util.reference.CleanupReferenceProcessorInstance;
import io.deephaven.engine.util.systemicmarking.SystemicObjectTracker;
import io.deephaven.hotspot.JvmIntrospectionContext;
import io.deephaven.internal.log.LoggerFactory;
import io.deephaven.io.log.LogEntry;
import io.deephaven.io.log.impl.LogOutputStringImpl;
Expand All @@ -25,7 +26,6 @@
import io.deephaven.io.sched.TimedJob;
import io.deephaven.net.CommBase;
import io.deephaven.util.FunctionalInterfaces;
import io.deephaven.util.JvmIntrospectionContext;
import io.deephaven.util.SafeCloseable;
import io.deephaven.util.annotations.TestUseOnly;
import io.deephaven.util.datastructures.SimpleReferenceManager;
Expand Down Expand Up @@ -1469,7 +1469,7 @@ private boolean blockUntilNotificationAdded(final long nanosToWait) {

private static LogEntry appendAsMillisFromNanos(final LogEntry entry, final long nanos) {
if (nanos > 0) {
return entry.appendDoubleToDecimalPlaces(nanos / 1_000_000.0, 3);
return entry.appendDouble(nanos / 1_000_000.0, 3);
}
return entry.append(0);
}
Expand Down Expand Up @@ -1503,44 +1503,7 @@ private void refreshTablesAndFlushNotifications() {
}
jvmIntrospectionContext.endSample();
final long cycleTimeNanos = System.nanoTime() - startTimeNanos;
if (cycleTimeNanos >= minimumCycleDurationToLogNanos) {
if (suppressedCycles > 0) {
logSuppressedCycles();
}
final long safePointPauseTimeMillis = jvmIntrospectionContext.deltaSafePointPausesTimeMillis();
final double cycleTimeMillis = cycleTimeNanos / 1_000_000.0;
LogEntry entry = log.info()
.append("Update Graph Processor cycleTime=").appendDoubleToDecimalPlaces(cycleTimeMillis, 3);
if (JvmIntrospectionContext.hasSafePointData()) {
entry = entry
.append("ms, safePointTime=")
.append(safePointPauseTimeMillis)
.append("ms, safePointTimePct=");
if (safePointPauseTimeMillis > 0 && cycleTimeMillis > 0.0) {
final double gcTimePct = 100.0 * safePointPauseTimeMillis / cycleTimeMillis;
entry = entry.appendDoubleToDecimalPlaces(gcTimePct, 2);
} else {
entry = entry.append("0");
}
entry = entry.append("%");
} else {
entry = entry.append("ms");
}
entry = entry.append(", lockWaitTime=");
entry = appendAsMillisFromNanos(entry, currentCycleLockWaitTotalNanos);
entry = entry.append("ms, yieldTime=");
entry = appendAsMillisFromNanos(entry, currentCycleSleepTotalNanos);
entry = entry.append("ms, sleepTime=");
entry = appendAsMillisFromNanos(entry, currentCycleSleepTotalNanos);
entry.append("ms").endl();
} else if (cycleTimeNanos > 0) {
++suppressedCycles;
suppressedCyclesTotalNanos += cycleTimeNanos;
suppressedCyclesTotalSafePontTimeMillis += jvmIntrospectionContext.deltaSafePointPausesTimeMillis();
if (suppressedCyclesTotalNanos >= minimumCycleDurationToLogNanos) {
logSuppressedCycles();
}
}
logCycle(cycleTimeNanos);
}

if (interCycleYield) {
Expand All @@ -1550,15 +1513,57 @@ private void refreshTablesAndFlushNotifications() {
waitForNextCycle(startTime, sched);
}

private void logCycle(final long cycleTimeNanos) {
if (cycleTimeNanos >= minimumCycleDurationToLogNanos) {
if (suppressedCycles > 0) {
logSuppressedCycles();
}
final long safePointPauseTimeMillis = jvmIntrospectionContext.deltaSafePointPausesTimeMillis();
final long safePointSyncTimeMillis = jvmIntrospectionContext.deltaSafePointSyncTimeMillis();
jcferretti marked this conversation as resolved.
Show resolved Hide resolved
final double cycleTimeMillis = cycleTimeNanos / 1_000_000.0;
LogEntry entry = log.info()
.append("Update Graph Processor cycleTime=").appendDouble(cycleTimeMillis, 3);
if (jvmIntrospectionContext.hasSafePointData()) {
entry = entry
.append("ms, safePointTime=")
.append(safePointPauseTimeMillis)
.append("ms, safePointTimePct=");
if (safePointPauseTimeMillis > 0 && cycleTimeMillis > 0.0) {
final double safePointTimePct = 100.0 * safePointPauseTimeMillis / cycleTimeMillis;
entry = entry.appendDouble(safePointTimePct, 2);
} else {
entry = entry.append("0");
}
entry = entry.append("%, safePointSyncTime=").append(safePointSyncTimeMillis);
}
entry = entry.append("ms, lockWaitTime=");
entry = appendAsMillisFromNanos(entry, currentCycleLockWaitTotalNanos);
entry = entry.append("ms, yieldTime=");
entry = appendAsMillisFromNanos(entry, currentCycleSleepTotalNanos);
entry = entry.append("ms, sleepTime=");
entry = appendAsMillisFromNanos(entry, currentCycleSleepTotalNanos);
entry.append("ms").endl();
return;
}
if (cycleTimeNanos > 0) {
++suppressedCycles;
suppressedCyclesTotalNanos += cycleTimeNanos;
suppressedCyclesTotalSafePontTimeMillis += jvmIntrospectionContext.deltaSafePointPausesTimeMillis();
if (suppressedCyclesTotalNanos >= minimumCycleDurationToLogNanos) {
logSuppressedCycles();
}
}
}

private void logSuppressedCycles() {
LogEntry entry = log.info()
.append("Minimal Update Graph Processor cycle times: ")
.appendDoubleToDecimalPlaces((double) (suppressedCyclesTotalNanos) / 1_000_000.0, 3).append("ms / ")
.appendDouble((double) (suppressedCyclesTotalNanos) / 1_000_000.0, 3).append("ms / ")
.append(suppressedCycles).append(" cycles = ")
.appendDoubleToDecimalPlaces(
.appendDouble(
(double) suppressedCyclesTotalNanos / (double) suppressedCycles / 1_000_000.0, 3)
.append("ms/cycle average)");
if (JvmIntrospectionContext.hasSafePointData()) {
if (jvmIntrospectionContext.hasSafePointData()) {
entry = entry
.append(", safePointTime=")
.append(suppressedCyclesTotalSafePontTimeMillis)
Expand Down
14 changes: 14 additions & 0 deletions hotspot-impl/build.gradle
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
plugins {
id 'io.deephaven.project.register'
}

description 'Implementation for the HotSpot service to obtain JVM instrospection data.'

dependencies {
implementation project(':hotspot')
Classpaths.inheritAutoService(project)
}

tasks.withType(JavaCompile).configureEach {
options.compilerArgs += ['--add-exports', 'java.management/sun.management=ALL-UNNAMED']
}
2 changes: 2 additions & 0 deletions hotspot-impl/gradle.properties
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
io.deephaven.project.ProjectType=JAVA_LOCAL
excludeReleaseFlag=
Loading