Skip to content

Commit d8c4c3a

Browse files
tkrodrigueztkrodriguez
committed
[GR-59275] Use nanoTime derived milliseconds for various timeouts and watchdogs
PullRequest: graal/19213
2 parents 658b06c + 0bedc4b commit d8c4c3a

File tree

18 files changed

+220
-131
lines changed

18 files changed

+220
-131
lines changed

‎compiler/src/jdk.graal.compiler.test/src/jdk/graal/compiler/core/test/CheckGraalInvariants.java‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -195,6 +195,10 @@ public boolean shouldVerifyFoldableMethods() {
195195
return true;
196196
}
197197

198+
public boolean shouldVerifyCurrentTimeMillis() {
199+
return true;
200+
}
201+
198202
/**
199203
* Makes edits to the list of verifiers to be run.
200204
*/
@@ -362,6 +366,10 @@ public static void runTest(InvariantsTool tool) {
362366
verifiers.add(foldableMethodsVerifier);
363367
}
364368

369+
if (tool.shouldVerifyCurrentTimeMillis()) {
370+
verifiers.add(new VerifyCurrentTimeMillisUsage());
371+
}
372+
365373
tool.updateVerifiers(verifiers);
366374

367375
for (Method m : BadUsageWithEquals.class.getDeclaredMethods()) {

‎compiler/src/jdk.graal.compiler.test/src/jdk/graal/compiler/core/test/CompilationWatchDogTest.java‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -32,15 +32,15 @@
3232
import java.util.List;
3333
import java.util.stream.Collectors;
3434

35+
import org.junit.Assert;
36+
import org.junit.Test;
37+
3538
import jdk.graal.compiler.core.CompilationWatchDog;
3639
import jdk.graal.compiler.core.CompilationWatchDog.EventHandler;
3740
import jdk.graal.compiler.core.common.CompilationIdentifier;
3841
import jdk.graal.compiler.debug.TTY;
3942
import jdk.graal.compiler.nodes.StructuredGraph;
4043
import jdk.graal.compiler.options.OptionValues;
41-
import org.junit.Assert;
42-
import org.junit.Test;
43-
4444
import jdk.vm.ci.code.InstalledCode;
4545
import jdk.vm.ci.meta.ResolvedJavaMethod;
4646

@@ -130,7 +130,7 @@ public void onLongCompilation(CompilationWatchDog watchDog, Thread watched, Comp
130130
}
131131

132132
@Override
133-
public void onStuckCompilation(CompilationWatchDog watchDog, Thread watched, CompilationIdentifier stuckCompilation, StackTraceElement[] stackTrace, int stackTraceCount) {
133+
public void onStuckCompilation(CompilationWatchDog watchDog, Thread watched, CompilationIdentifier stuckCompilation, StackTraceElement[] stackTrace, long stackTraceCount) {
134134
event("onStuckCompilation");
135135
stuckCompilations.add(stuckCompilation);
136136
}

‎compiler/src/jdk.graal.compiler.test/src/jdk/graal/compiler/core/test/VerifyCurrentTimeMillisUsage.java‎

Lines changed: 60 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,60 @@
1+
/*
2+
* Copyright (c) 2024, Oracle and/or its affiliates. All rights reserved.
3+
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4+
*
5+
* This code is free software; you can redistribute it and/or modify it
6+
* under the terms of the GNU General Public License version 2 only, as
7+
* published by the Free Software Foundation. Oracle designates this
8+
* particular file as subject to the "Classpath" exception as provided
9+
* by Oracle in the LICENSE file that accompanied this code.
10+
*
11+
* This code is distributed in the hope that it will be useful, but WITHOUT
12+
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
13+
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
14+
* version 2 for more details (a copy is included in the LICENSE file that
15+
* accompanied this code).
16+
*
17+
* You should have received a copy of the GNU General Public License version
18+
* 2 along with this work; if not, write to the Free Software Foundation,
19+
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
20+
*
21+
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
22+
* or visit www.oracle.com if you need additional information or have any
23+
* questions.
24+
*/
25+
package jdk.graal.compiler.core.test;
26+
27+
import jdk.graal.compiler.nodes.StructuredGraph;
28+
import jdk.graal.compiler.nodes.java.MethodCallTargetNode;
29+
import jdk.graal.compiler.nodes.spi.CoreProviders;
30+
import jdk.graal.compiler.phases.VerifyPhase;
31+
import jdk.graal.compiler.serviceprovider.GraalServices;
32+
import jdk.vm.ci.meta.ResolvedJavaMethod;
33+
import jdk.vm.ci.meta.ResolvedJavaType;
34+
35+
/**
36+
* {@link System#currentTimeMillis} shouldn't be used to measure elapsed time so require callers
37+
* that want the current time in milliseconds to go through {@link GraalServices#milliTimeStamp()}.
38+
* {@link System#nanoTime()} should be used for measuring elapsed time.
39+
*/
40+
public class VerifyCurrentTimeMillisUsage extends VerifyPhase<CoreProviders> {
41+
private static final String CURRENT_TIME_MILLIS_NAME = "currentTimeMillis";
42+
43+
@Override
44+
protected void verify(StructuredGraph graph, CoreProviders context) {
45+
final ResolvedJavaType systemType = context.getMetaAccess().lookupJavaType(System.class);
46+
for (MethodCallTargetNode t : graph.getNodes(MethodCallTargetNode.TYPE)) {
47+
ResolvedJavaMethod callee = t.targetMethod();
48+
if (callee.getDeclaringClass().equals(systemType)) {
49+
String calleeName = callee.getName();
50+
if (calleeName.equals(CURRENT_TIME_MILLIS_NAME)) {
51+
final ResolvedJavaType services = context.getMetaAccess().lookupJavaType(GraalServices.class);
52+
if (graph.method().getDeclaringClass().equals(services)) {
53+
return;
54+
}
55+
throw new VerificationError(t, "Should use System.nanoTime for measuring elapsed time or GraalServices.milliTimeStamp for the time since the epoch");
56+
}
57+
}
58+
}
59+
}
60+
}

‎compiler/src/jdk.graal.compiler.test/src/jdk/graal/compiler/hotspot/test/LibGraalCompilationDriver.java‎

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -326,14 +326,11 @@ public long readBytesAllocated() {
326326
return UNSAFE.getLong(getAddress());
327327
}
328328

329-
static final long NANOS_IN_MILLI = 1_000_000;
330-
331329
/**
332330
* @return compilation time as output by libgraal, in nanoseconds.
333331
*/
334332
public long readTimeElapsed() {
335-
// Libgraal uses milliseconds, convert to nano for consistency.
336-
return UNSAFE.getLong(getAddress() + Long.BYTES) * NANOS_IN_MILLI;
333+
return UNSAFE.getLong(getAddress() + Long.BYTES);
337334
}
338335
}
339336

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/core/CompilationWatchDog.java‎

Lines changed: 28 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,8 @@
3131
import java.util.concurrent.ThreadFactory;
3232
import java.util.concurrent.TimeUnit;
3333

34+
import org.graalvm.nativeimage.ImageInfo;
35+
3436
import jdk.graal.compiler.core.common.CompilationIdentifier;
3537
import jdk.graal.compiler.core.common.util.Util;
3638
import jdk.graal.compiler.debug.TTY;
@@ -40,9 +42,7 @@
4042
import jdk.graal.compiler.options.OptionValues;
4143
import jdk.graal.compiler.serviceprovider.GraalServices;
4244
import jdk.graal.compiler.serviceprovider.IsolateUtil;
43-
4445
import jdk.vm.ci.common.NativeImageReinitialize;
45-
import org.graalvm.nativeimage.ImageInfo;
4646

4747
/**
4848
* A watch dog for {@linkplain #watch watching} and reporting on long running compilations.
@@ -101,15 +101,15 @@ public interface EventHandler {
101101
* @param watchDog the watch dog watching the compilation
102102
* @param watched the watched compiler thread
103103
* @param compilation the compilation
104-
* @param elapsed milliseconds the compilation has been observed by the watch dog task which
104+
* @param elapsed nanoseconds the compilation has been observed by the watch dog task which
105105
* may be shorter that time since compilation started
106106
* @param stackTrace snapshot stack trace for {@code watched}
107107
*/
108108
default void onLongCompilation(CompilationWatchDog watchDog, Thread watched, CompilationIdentifier compilation,
109109
long elapsed, StackTraceElement[] stackTrace) {
110110
TTY.printf("======================= WATCH DOG =======================%n" +
111111
"%s: detected long running compilation %s [%.3f seconds]%n%s", CURRENT_THREAD_LABEL, compilation,
112-
secs(elapsed), Util.toString(stackTrace));
112+
seconds(elapsed), Util.toString(stackTrace));
113113
}
114114

115115
/**
@@ -123,7 +123,7 @@ default void onLongCompilation(CompilationWatchDog watchDog, Thread watched, Com
123123
* @param stuckTime seconds compilation appears to have been stuck for
124124
*/
125125
default void onStuckCompilation(CompilationWatchDog watchDog, Thread watched, CompilationIdentifier compilation,
126-
StackTraceElement[] stackTrace, int stuckTime) {
126+
StackTraceElement[] stackTrace, long stuckTime) {
127127
TTY.printf("======================= WATCH DOG =======================%n" +
128128
"%s: observed identical stack traces for %d seconds, indicating a stuck compilation %s%n%s%n", CURRENT_THREAD_LABEL,
129129
stuckTime, compilation, Util.toString(stackTrace));
@@ -170,7 +170,7 @@ public static class Options {
170170
/**
171171
* @see Options#CompilationWatchDogVMExitDelay
172172
*/
173-
private final int vmExitDelay;
173+
private final long vmExitDelayNS;
174174

175175
/**
176176
* Object representing the compilation being watched. It is volatile as it is used to
@@ -186,7 +186,7 @@ public static class Options {
186186
boolean singleShotExecutor, EventHandler eventHandler) {
187187
this.compilation = compilation;
188188
this.watchedThread = watchedThread;
189-
this.vmExitDelay = vmExitDelay;
189+
this.vmExitDelayNS = TimeUnit.SECONDS.toNanos(vmExitDelay);
190190
this.eventHandler = eventHandler == null ? EventHandler.DEFAULT : eventHandler;
191191
trace("started compiling %s", compilation);
192192
if (singleShotExecutor) {
@@ -242,8 +242,8 @@ private void trace(String format, Object... args) {
242242
}
243243
}
244244

245-
private static double secs(long ms) {
246-
return (double) ms / 1000;
245+
private static double seconds(long ns) {
246+
return (double) ns / TimeUnit.SECONDS.toNanos(1);
247247
}
248248

249249
@Override
@@ -255,38 +255,38 @@ public String toString() {
255255
public void run() {
256256
try {
257257
CompilationIdentifier comp = compilation;
258-
long start = System.currentTimeMillis();
259-
long elapsed = 0;
260-
int reportDelay = 1000;
261-
long nextReport = start;
262-
long lastUniqueStackTrace = start;
258+
long startNS = System.nanoTime();
259+
long elapsedNS = 0;
260+
long reportDelayNS = TimeUnit.SECONDS.toNanos(1);
261+
long nextReportNS = startNS;
262+
long lastUniqueStackTraceNS = startNS;
263263
while (compilation != null) {
264-
long now = System.currentTimeMillis();
264+
long currentNS = System.nanoTime();
265265
comp = compilation;
266-
trace("took a stack trace [%.3f seconds]", secs(elapsed));
266+
trace("took a stack trace [%.3f seconds]", seconds(elapsedNS));
267267
boolean uniqueStackTrace = recordStackTrace(watchedThread.getStackTrace());
268268
if (uniqueStackTrace) {
269-
lastUniqueStackTrace = now;
269+
lastUniqueStackTraceNS = currentNS;
270270
}
271-
int stuckTime = (int) ((now - lastUniqueStackTrace) / 1000);
272-
if (vmExitDelay != 0 && stuckTime >= vmExitDelay) {
273-
eventHandler.onStuckCompilation(this, watchedThread, comp, lastStackTrace, stuckTime);
271+
long stuckTime = currentNS - lastUniqueStackTraceNS;
272+
if (vmExitDelayNS != 0 && stuckTime >= vmExitDelayNS) {
273+
eventHandler.onStuckCompilation(this, watchedThread, comp, lastStackTrace, TimeUnit.NANOSECONDS.toSeconds(stuckTime));
274274
} else if (uniqueStackTrace) {
275-
if (now >= nextReport) {
276-
eventHandler.onLongCompilation(this, watchedThread, comp, elapsed, lastStackTrace);
277-
nextReport = now + reportDelay;
278-
reportDelay <<= 1;
275+
if (currentNS >= nextReportNS) {
276+
eventHandler.onLongCompilation(this, watchedThread, comp, elapsedNS, lastStackTrace);
277+
nextReportNS = currentNS + reportDelayNS;
278+
reportDelayNS <<= 1;
279279
}
280280
}
281281
try {
282282
Thread.sleep(1000);
283-
elapsed = System.currentTimeMillis() - start;
283+
elapsedNS = System.nanoTime() - startNS;
284284
} catch (InterruptedException e) {
285-
elapsed = System.currentTimeMillis() - start;
286-
trace("interrupted [%.3f seconds]", secs(elapsed));
285+
elapsedNS = System.nanoTime() - startNS;
286+
trace("interrupted [%.3f seconds]", seconds(elapsedNS));
287287
}
288288
}
289-
trace("stopped watching %s [%.3f seconds]", comp, secs(elapsed));
289+
trace("stopped watching %s [%.3f seconds]", comp, seconds(elapsedNS));
290290
} catch (Throwable t) {
291291
eventHandler.onException(t);
292292
}

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/core/CompilationWrapper.java‎

Lines changed: 9 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -40,11 +40,12 @@
4040
import java.io.PrintStream;
4141
import java.util.Formatter;
4242
import java.util.Map;
43+
import java.util.concurrent.TimeUnit;
4344

4445
import org.graalvm.collections.EconomicMap;
4546

46-
import jdk.graal.compiler.core.common.util.CompilationAlarm;
4747
import jdk.graal.compiler.core.common.NumUtil;
48+
import jdk.graal.compiler.core.common.util.CompilationAlarm;
4849
import jdk.graal.compiler.debug.DebugCloseable;
4950
import jdk.graal.compiler.debug.DebugContext;
5051
import jdk.graal.compiler.debug.DebugOptions;
@@ -430,7 +431,7 @@ private void maybeExitVM(ExceptionAction action) {
430431
private static final GlobalAtomicLong totalCompilations = new GlobalAtomicLong(0L);
431432
private static final GlobalAtomicLong failedCompilations = new GlobalAtomicLong(0L);
432433
private static final GlobalAtomicLong compilationPeriodStart = new GlobalAtomicLong(0L);
433-
private static final int COMPILATION_FAILURE_DETECTION_PERIOD_MS = 2000;
434+
private static final long COMPILATION_FAILURE_DETECTION_PERIOD_NS = TimeUnit.SECONDS.toNanos(2);
434435
private static final int MIN_COMPILATIONS_FOR_FAILURE_DETECTION = 25;
435436

436437
/**
@@ -475,19 +476,19 @@ private static boolean detectCompilationFailureRateTooHigh(OptionValues options,
475476
}
476477

477478
int maxRate = Math.min(100, NumUtil.safeAbs(maxRateValue));
478-
long now = System.currentTimeMillis();
479-
long start = getCompilationPeriodStart(now);
479+
long nowNS = System.nanoTime();
480+
long startNS = getCompilationPeriodStart(nowNS);
480481

481-
long period = now - start;
482-
boolean periodExpired = period > COMPILATION_FAILURE_DETECTION_PERIOD_MS;
482+
long periodNS = nowNS - startNS;
483+
boolean periodExpired = periodNS > COMPILATION_FAILURE_DETECTION_PERIOD_NS;
483484

484485
// Wait for period to expire or some minimum amount of compilations
485486
// before detecting systemic failure.
486487
if (rate > maxRate && (periodExpired || total > MIN_COMPILATIONS_FOR_FAILURE_DETECTION)) {
487488
Formatter msg = new Formatter();
488489
String option = GraalCompilerOptions.SystemicCompilationFailureRate.getName();
489490
msg.format("Warning: Systemic Graal compilation failure detected: %d of %d (%d%%) of compilations failed during last %d ms [max rate set by %s is %d%%]. ",
490-
failed, total, rate, period, option, maxRateValue);
491+
failed, total, rate, TimeUnit.NANOSECONDS.toMillis(periodNS), option, maxRateValue);
491492
msg.format("To mitigate systemic compilation failure detection, set %s to a higher value. ", option);
492493
msg.format("To disable systemic compilation failure detection, set %s to 0. ", option);
493494
msg.format("To get more information on compilation failures, set %s to Print or Diagnose. ", GraalCompilerOptions.CompilationFailureAction.getName());
@@ -501,7 +502,7 @@ private static boolean detectCompilationFailureRateTooHigh(OptionValues options,
501502

502503
if (periodExpired) {
503504

504-
if (compilationPeriodStart.compareAndSet(start, now)) {
505+
if (compilationPeriodStart.compareAndSet(startNS, nowNS)) {
505506
// Reset compilation counters for new period
506507
failedCompilations.set(0);
507508
totalCompilations.set(0);

‎compiler/src/jdk.graal.compiler/src/jdk/graal/compiler/core/GraalCompiler.java‎

Lines changed: 7 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,8 @@
2424
*/
2525
package jdk.graal.compiler.core;
2626

27+
import java.util.concurrent.TimeUnit;
28+
2729
import jdk.graal.compiler.code.CompilationResult;
2830
import jdk.graal.compiler.core.common.PermanentBailoutException;
2931
import jdk.graal.compiler.core.common.RetryableBailoutException;
@@ -215,14 +217,14 @@ private static void checkForRequestedCrash(StructuredGraph graph, RequestedCrash
215217
* @param graph a graph currently being compiled
216218
*/
217219
private static void checkForRequestedDelay(StructuredGraph graph) {
218-
long delay = Math.max(0, GraalCompilerOptions.InjectedCompilationDelay.getValue(graph.getOptions())) * 1000;
219-
if (delay != 0) {
220+
long delayNS = Math.max(0, TimeUnit.SECONDS.toNanos(GraalCompilerOptions.InjectedCompilationDelay.getValue(graph.getOptions())));
221+
if (delayNS != 0) {
220222
String methodPattern = DebugOptions.MethodFilter.getValue(graph.getOptions());
221223
String matchedLabel = match(graph, methodPattern);
222224
if (matchedLabel != null) {
223-
long start = System.currentTimeMillis();
224-
TTY.printf("[%s] delaying compilation of %s for %d ms%n", Thread.currentThread().getName(), matchedLabel, delay);
225-
while (System.currentTimeMillis() - start < delay) {
225+
long startNS = System.nanoTime();
226+
TTY.printf("[%s] delaying compilation of %s for %d ms%n", Thread.currentThread().getName(), matchedLabel, TimeUnit.NANOSECONDS.toMillis(delayNS));
227+
while (System.nanoTime() - startNS < delayNS) {
226228
try {
227229
Thread.sleep(100);
228230
} catch (InterruptedException e) {

0 commit comments

Comments
 (0)