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 1 commit
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
7 changes: 5 additions & 2 deletions IO/src/main/java/io/deephaven/io/log/LogEntry.java
Original file line number Diff line number Diff line change
Expand Up @@ -91,7 +91,7 @@ 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
Expand All @@ -102,7 +102,7 @@ default LogEntry appendDoubleToDecimalPlaces(final double doubleValue, final int
}

/**
* Append a double with decimal places up to the given number.
* Append a double with decimal places up to the given number, rounding half up.
*
* @param doubleValue a double value to append to the logEntry
* @param decimalPlaces a positive integer between 0 and 9
Expand All @@ -114,6 +114,9 @@ default LogEntry appendDoubleToMaxDecimalPlaces(final double doubleValue, final

private static LogEntry appendDoubleDecimalPlacesImpl(
LogEntry entry, final double doubleValue, final int decimalPlaces, final boolean exact) {
if (decimalPlaces < 0 || decimalPlaces > 9) {
throw new IllegalArgumentException("Invalid value for decimalPlaces = " + decimalPlaces);
}
final int decimalPlacesAsPowerOf10 = MathUtil.pow10(decimalPlaces);
final boolean negative = doubleValue < 0.0;
final long longWeightedValue;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -64,15 +64,12 @@ tasks.withType(JavaCompile).configureEach {
options.compilerArgs << '-parameters'

if (!excludeReleaseFlag) {
if (name == 'compileTestJava') {
if (compilerVersion != testLanguageLevel) {
def checkLevel = (name == 'compileTestJava') ? testLanguageLevel : languageLevel
if (compilerVersion != checkLevel) {
options.release.set testLanguageLevel
jcferretti marked this conversation as resolved.
Show resolved Hide resolved
}
} else {
if (compilerVersion != languageLevel) {
options.release.set languageLevel
}
}
} else {
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 @@ -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 safePointTimePct = 100.0 * safePointPauseTimeMillis / cycleTimeMillis;
entry = entry.appendDoubleToDecimalPlaces(safePointTimePct, 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,6 +1513,49 @@ 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 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 safePointTimePct = 100.0 * safePointPauseTimeMillis / cycleTimeMillis;
entry = entry.appendDoubleToDecimalPlaces(safePointTimePct, 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();
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: ")
Expand Down
2 changes: 1 addition & 1 deletion hotspot-impl/gradle.properties
Original file line number Diff line number Diff line change
@@ -1,2 +1,2 @@
io.deephaven.project.ProjectType=JAVA_LOCAL
excludeReleaseFlag
excludeReleaseFlag=
Original file line number Diff line number Diff line change
Expand Up @@ -3,17 +3,23 @@
import com.google.auto.service.AutoService;
import io.deephaven.hotspot.HotSpot;
import sun.management.ManagementFactoryHelper;
import sun.management.HotspotRuntimeMBean;

@AutoService(HotSpot.class)
public class HotSpotImpl implements HotSpot {
private HotspotRuntimeMBean hotspotRuntimeMBean;
jcferretti marked this conversation as resolved.
Show resolved Hide resolved

public HotSpotImpl() {
hotspotRuntimeMBean = ManagementFactoryHelper.getHotspotRuntimeMBean();
}

@Override
public long getSafepointCount() {
return ManagementFactoryHelper.getHotspotRuntimeMBean().getSafepointCount();
return hotspotRuntimeMBean.getSafepointCount();
}

@Override
public long getTotalSafepointTimeMillis() {
return ManagementFactoryHelper.getHotspotRuntimeMBean().getTotalSafepointTime();
return hotspotRuntimeMBean.getTotalSafepointTime();
}
}