43972
|
1 |
/*
|
58299
|
2 |
* Copyright (c) 2016, 2019, Oracle and/or its affiliates. All rights reserved.
|
43972
|
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.
|
|
8 |
*
|
|
9 |
* This code is distributed in the hope that it will be useful, but WITHOUT
|
|
10 |
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
|
|
11 |
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
|
|
12 |
* version 2 for more details (a copy is included in the LICENSE file that
|
|
13 |
* accompanied this code).
|
|
14 |
*
|
|
15 |
* You should have received a copy of the GNU General Public License version
|
|
16 |
* 2 along with this work; if not, write to the Free Software Foundation,
|
|
17 |
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
|
|
18 |
*
|
|
19 |
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
|
|
20 |
* or visit www.oracle.com if you need additional information or have any
|
|
21 |
* questions.
|
|
22 |
*/
|
50858
|
23 |
|
|
24 |
|
43972
|
25 |
package org.graalvm.compiler.hotspot;
|
|
26 |
|
|
27 |
import static org.graalvm.compiler.hotspot.HotSpotGraalCompiler.fmt;
|
|
28 |
|
|
29 |
import java.util.Arrays;
|
|
30 |
|
55509
|
31 |
import org.graalvm.compiler.core.GraalServiceThread;
|
43972
|
32 |
import org.graalvm.compiler.debug.TTY;
|
|
33 |
import org.graalvm.compiler.options.Option;
|
46344
|
34 |
import org.graalvm.compiler.options.OptionKey;
|
43972
|
35 |
import org.graalvm.compiler.options.OptionType;
|
46344
|
36 |
import org.graalvm.compiler.options.OptionValues;
|
43972
|
37 |
|
|
38 |
import jdk.vm.ci.meta.ResolvedJavaMethod;
|
54328
|
39 |
import jdk.vm.ci.services.Services;
|
43972
|
40 |
|
|
41 |
/**
|
|
42 |
* A watch dog for reporting long running compilations. This is designed to be an always on
|
|
43 |
* mechanism for the purpose of getting better reports from customer sites. As such, it only exits
|
|
44 |
* the VM when it is very sure about a stuck compilation as opposed to only observing a long running
|
|
45 |
* compilation. In both cases, it logs messages to {@link TTY}.
|
|
46 |
*
|
|
47 |
* A watch dog thread is associated with each compiler thread. It wakes up every
|
|
48 |
* {@value #SPIN_TIMEOUT_MS} milliseconds to observe the state of the compiler thread. After the
|
|
49 |
* first {@link Options#CompilationWatchDogStartDelay} seconds of a specific compilation, the watch
|
|
50 |
* dog reports a long running compilation. Every
|
|
51 |
* {@link Options#CompilationWatchDogStackTraceInterval} seconds after that point in time where the
|
|
52 |
* same compilation is still executing, the watch dog takes a stack trace of the compiler thread. If
|
55509
|
53 |
* more than {@link Options#NonFatalIdenticalCompilationSnapshots} contiguous identical stack traces
|
|
54 |
* are seen, the watch dog reports a stuck compilation and exits the VM.
|
43972
|
55 |
*/
|
55509
|
56 |
class CompilationWatchDog implements Runnable, AutoCloseable {
|
43972
|
57 |
|
|
58 |
public static class Options {
|
|
59 |
// @formatter:off
|
|
60 |
@Option(help = "Delay in seconds before watch dog monitoring a compilation (0 disables monitoring).", type = OptionType.Debug)
|
46344
|
61 |
public static final OptionKey<Double> CompilationWatchDogStartDelay = new OptionKey<>(0.0D);
|
43972
|
62 |
@Option(help = "Interval in seconds between a watch dog reporting stack traces for long running compilations.", type = OptionType.Debug)
|
46344
|
63 |
public static final OptionKey<Double> CompilationWatchDogStackTraceInterval = new OptionKey<>(60.0D);
|
43972
|
64 |
@Option(help = "Number of contiguous identical compiler thread stack traces allowed before the VM exits " +
|
|
65 |
"on the basis of a stuck compilation.", type = OptionType.Debug)
|
46344
|
66 |
public static final OptionKey<Integer> NonFatalIdenticalCompilationSnapshots = new OptionKey<>(20);
|
43972
|
67 |
// @formatter:on
|
|
68 |
}
|
|
69 |
|
|
70 |
private enum WatchDogState {
|
|
71 |
/**
|
|
72 |
* The watch dog thread sleeps currently, either no method is currently compiled, or no
|
|
73 |
* method is compiled long enough to be monitored.
|
|
74 |
*/
|
|
75 |
SLEEPING,
|
|
76 |
/**
|
|
77 |
* The watch dog thread identified a compilation that already takes long enough to be
|
|
78 |
* interesting. It will sleep and wake up periodically and check if the current compilation
|
|
79 |
* takes too long. If it takes too long it will start collecting stack traces from the
|
|
80 |
* compiler thread.
|
|
81 |
*/
|
|
82 |
WATCHING_WITHOUT_STACK_INSPECTION,
|
|
83 |
/**
|
|
84 |
* The watch dog thread is fully monitoring the compiler thread. It takes stack traces
|
|
85 |
* periodically and sleeps again until the next period. If the number of stack traces
|
|
86 |
* reaches a certain upper bound and those stack traces are equal it will shut down the
|
|
87 |
* entire VM with an error.
|
|
88 |
*/
|
|
89 |
WATCHING_WITH_STACK_INSPECTION
|
|
90 |
}
|
|
91 |
|
|
92 |
/**
|
|
93 |
* The number of milliseconds a watch dog thread sleeps between observing the state of the
|
|
94 |
* compilation thread it is associated with. Most compilations are expected to complete within
|
|
95 |
* this time period and thus not be actively monitored by the watch dog.
|
|
96 |
*/
|
|
97 |
private static final int SPIN_TIMEOUT_MS = 1000;
|
|
98 |
|
|
99 |
private WatchDogState state = WatchDogState.SLEEPING;
|
|
100 |
private final Thread compilerThread;
|
46344
|
101 |
private final long startDelayMilliseconds;
|
|
102 |
private final long stackTraceIntervalMilliseconds;
|
|
103 |
private final int nonFatalIdenticalCompilationSnapshots;
|
43972
|
104 |
private volatile ResolvedJavaMethod currentMethod;
|
|
105 |
private volatile int currentId;
|
|
106 |
private ResolvedJavaMethod lastWatched;
|
|
107 |
|
|
108 |
// The 4 fields below are for a single compilation being watched
|
|
109 |
private long elapsed;
|
|
110 |
private int traceIntervals;
|
|
111 |
private int numberOfIdenticalStackTraces;
|
|
112 |
private StackTraceElement[] lastStackTrace;
|
|
113 |
|
46344
|
114 |
CompilationWatchDog(Thread compilerThread, long startDelayMilliseconds, long stackTraceIntervalMilliseconds, int nonFatalIdenticalCompilationSnapshots) {
|
43972
|
115 |
this.compilerThread = compilerThread;
|
46344
|
116 |
this.startDelayMilliseconds = startDelayMilliseconds;
|
|
117 |
this.stackTraceIntervalMilliseconds = stackTraceIntervalMilliseconds;
|
|
118 |
this.nonFatalIdenticalCompilationSnapshots = nonFatalIdenticalCompilationSnapshots;
|
43972
|
119 |
}
|
|
120 |
|
|
121 |
public void startCompilation(ResolvedJavaMethod method, int id) {
|
|
122 |
trace("start %s", fmt(method));
|
|
123 |
this.currentMethod = method;
|
|
124 |
this.currentId = id;
|
|
125 |
}
|
|
126 |
|
|
127 |
public void stopCompilation() {
|
|
128 |
trace(" stop %s", fmt(currentMethod));
|
|
129 |
this.currentMethod = null;
|
|
130 |
}
|
|
131 |
|
|
132 |
private void reset() {
|
|
133 |
elapsed = 0;
|
|
134 |
traceIntervals = 0;
|
|
135 |
numberOfIdenticalStackTraces = 0;
|
|
136 |
lastWatched = null;
|
|
137 |
lastStackTrace = null;
|
|
138 |
state = WatchDogState.SLEEPING;
|
|
139 |
}
|
|
140 |
|
|
141 |
private void tick(WatchDogState newState) {
|
|
142 |
state = newState;
|
|
143 |
}
|
|
144 |
|
|
145 |
/**
|
|
146 |
* Saves the current stack trace {@link StackTraceElement} of the monitored compiler thread
|
|
147 |
* {@link CompilationWatchDog#compilerThread}.
|
|
148 |
*
|
|
149 |
* @param newStackTrace the current stack trace of the monitored compiler thread
|
|
150 |
* @return {@code true} if the stack trace is equal to the last stack trace (or if it is the
|
|
151 |
* first one) and {@code false} if it is not equal to the last one.
|
|
152 |
*/
|
|
153 |
private boolean recordStackTrace(StackTraceElement[] newStackTrace) {
|
|
154 |
if (lastStackTrace == null) {
|
|
155 |
lastStackTrace = newStackTrace;
|
|
156 |
return true;
|
|
157 |
}
|
|
158 |
if (!Arrays.equals(lastStackTrace, newStackTrace)) {
|
|
159 |
lastStackTrace = newStackTrace;
|
|
160 |
return false;
|
|
161 |
}
|
|
162 |
return true;
|
|
163 |
}
|
|
164 |
|
|
165 |
/**
|
|
166 |
* Set to true to debug the watch dog.
|
|
167 |
*/
|
54328
|
168 |
private static final boolean DEBUG = Boolean.parseBoolean(Services.getSavedProperties().get("debug.graal.CompilationWatchDog"));
|
43972
|
169 |
|
|
170 |
private void trace(String format, Object... args) {
|
|
171 |
if (DEBUG) {
|
|
172 |
TTY.println(this + ": " + String.format(format, args));
|
|
173 |
}
|
|
174 |
}
|
|
175 |
|
|
176 |
private static long ms(double seconds) {
|
|
177 |
return (long) seconds * 1000;
|
|
178 |
}
|
|
179 |
|
|
180 |
private static double secs(long ms) {
|
|
181 |
return (double) ms / 1000;
|
|
182 |
}
|
|
183 |
|
|
184 |
@Override
|
|
185 |
public String toString() {
|
55509
|
186 |
return "WatchDog[" + compilerThread.getName() + "]";
|
43972
|
187 |
}
|
|
188 |
|
|
189 |
@Override
|
|
190 |
public void run() {
|
|
191 |
try {
|
46344
|
192 |
trace("Started%n", this);
|
43972
|
193 |
while (true) {
|
|
194 |
// get a copy of the last set method
|
|
195 |
final ResolvedJavaMethod currentlyCompiling = currentMethod;
|
|
196 |
if (currentlyCompiling == null) {
|
|
197 |
// continue sleeping, compilation is either over before starting
|
|
198 |
// to watch the compiler thread or no compilation at all started
|
|
199 |
reset();
|
|
200 |
} else {
|
|
201 |
switch (state) {
|
|
202 |
case SLEEPING:
|
|
203 |
lastWatched = currentlyCompiling;
|
|
204 |
elapsed = 0;
|
|
205 |
tick(WatchDogState.WATCHING_WITHOUT_STACK_INSPECTION);
|
|
206 |
break;
|
|
207 |
case WATCHING_WITHOUT_STACK_INSPECTION:
|
46344
|
208 |
if (currentlyCompiling.equals(lastWatched)) {
|
|
209 |
if (elapsed >= startDelayMilliseconds) {
|
43972
|
210 |
// we looked at the same compilation for a certain time
|
|
211 |
// so now we start to collect stack traces
|
|
212 |
tick(WatchDogState.WATCHING_WITH_STACK_INSPECTION);
|
|
213 |
trace("changes mode to watching with stack traces");
|
|
214 |
} else {
|
46344
|
215 |
// we still compile the same method but won't collect traces
|
|
216 |
// yet
|
43972
|
217 |
trace("watching without stack traces [%.2f seconds]", secs(elapsed));
|
|
218 |
}
|
|
219 |
elapsed += SPIN_TIMEOUT_MS;
|
|
220 |
} else {
|
46344
|
221 |
// compilation finished before we exceeded initial watching
|
|
222 |
// period
|
43972
|
223 |
reset();
|
|
224 |
}
|
|
225 |
break;
|
|
226 |
case WATCHING_WITH_STACK_INSPECTION:
|
46344
|
227 |
if (currentlyCompiling.equals(lastWatched)) {
|
|
228 |
if (elapsed >= startDelayMilliseconds + (traceIntervals * stackTraceIntervalMilliseconds)) {
|
43972
|
229 |
trace("took a stack trace");
|
|
230 |
boolean newStackTrace = recordStackTrace(compilerThread.getStackTrace());
|
|
231 |
if (!newStackTrace) {
|
|
232 |
trace("%d identical stack traces in a row", numberOfIdenticalStackTraces);
|
|
233 |
numberOfIdenticalStackTraces = 0;
|
|
234 |
}
|
|
235 |
numberOfIdenticalStackTraces++;
|
46344
|
236 |
if (numberOfIdenticalStackTraces > nonFatalIdenticalCompilationSnapshots) {
|
43972
|
237 |
synchronized (CompilationWatchDog.class) {
|
|
238 |
TTY.printf("======================= WATCH DOG THREAD =======================%n" +
|
|
239 |
"%s took %d identical stack traces, which indicates a stuck compilation (id=%d) of %s%n%sExiting VM%n", this,
|
|
240 |
numberOfIdenticalStackTraces, currentId, fmt(currentMethod), fmt(lastStackTrace));
|
57537
|
241 |
HotSpotGraalServices.exit(-1);
|
43972
|
242 |
}
|
|
243 |
} else if (newStackTrace) {
|
|
244 |
synchronized (CompilationWatchDog.class) {
|
|
245 |
TTY.printf("======================= WATCH DOG THREAD =======================%n" +
|
|
246 |
"%s detected long running compilation (id=%d) of %s [%.2f seconds]%n%s", this, currentId, fmt(currentMethod),
|
|
247 |
secs(elapsed), fmt(lastStackTrace));
|
|
248 |
}
|
|
249 |
}
|
|
250 |
traceIntervals++;
|
|
251 |
} else {
|
|
252 |
// we still watch the compilation in the same trace interval
|
|
253 |
trace("watching with stack traces [%.2f seconds]", secs(elapsed));
|
|
254 |
}
|
|
255 |
elapsed += SPIN_TIMEOUT_MS;
|
|
256 |
} else {
|
46344
|
257 |
// compilation finished before we are able to collect stack
|
|
258 |
// traces
|
43972
|
259 |
reset();
|
|
260 |
}
|
|
261 |
break;
|
|
262 |
default:
|
|
263 |
break;
|
|
264 |
}
|
|
265 |
}
|
46344
|
266 |
try {
|
|
267 |
Thread.sleep(SPIN_TIMEOUT_MS);
|
|
268 |
} catch (InterruptedException e) {
|
|
269 |
// Silently swallow
|
|
270 |
}
|
43972
|
271 |
}
|
46344
|
272 |
} catch (VirtualMachineError vmError) {
|
|
273 |
/*
|
|
274 |
* We encounter a VM error. This includes for example OutOfMemoryExceptions. In such a
|
|
275 |
* case we silently swallow the error. If it happens again the application thread will
|
|
276 |
* most likely encounter the same problem. If not the watchdog thread will no longer
|
|
277 |
* monitor the compilation and thus the error cannot happen again.
|
|
278 |
*/
|
43972
|
279 |
} catch (Throwable t) {
|
46344
|
280 |
/*
|
|
281 |
* A real exception happened on the compilation watchdog. This is unintended behavior
|
|
282 |
* and must not happen in any case.
|
|
283 |
*/
|
|
284 |
throw new InternalError(String.format("%s encountered an exception%n%s%n", this, fmt(t)), t);
|
43972
|
285 |
}
|
|
286 |
}
|
|
287 |
|
46344
|
288 |
private static final ThreadLocal<CompilationWatchDog> WATCH_DOGS = new ThreadLocal<>();
|
43972
|
289 |
|
|
290 |
/**
|
|
291 |
* Opens a scope for watching the compilation of a given method.
|
|
292 |
*
|
|
293 |
* @param method a method about to be compiled
|
|
294 |
* @param id compilation request identifier
|
|
295 |
* @return {@code null} if the compilation watch dog is disabled otherwise this object. The
|
|
296 |
* returned value should be used in a {@code try}-with-resources statement whose scope
|
|
297 |
* is the whole compilation so that leaving the scope will cause {@link #close()} to be
|
|
298 |
* called.
|
|
299 |
*/
|
46344
|
300 |
static CompilationWatchDog watch(ResolvedJavaMethod method, int id, OptionValues options) {
|
|
301 |
long startDelayMilliseconds = ms(Options.CompilationWatchDogStartDelay.getValue(options));
|
|
302 |
if (startDelayMilliseconds > 0.0D) {
|
43972
|
303 |
// Lazily get a watch dog thread for the current compiler thread
|
|
304 |
CompilationWatchDog watchDog = WATCH_DOGS.get();
|
|
305 |
if (watchDog == null) {
|
55509
|
306 |
Thread currentThread = Thread.currentThread();
|
46344
|
307 |
long stackTraceIntervalMilliseconds = ms(Options.CompilationWatchDogStackTraceInterval.getValue(options));
|
|
308 |
int nonFatalIdenticalCompilationSnapshots = Options.NonFatalIdenticalCompilationSnapshots.getValue(options);
|
|
309 |
watchDog = new CompilationWatchDog(currentThread, startDelayMilliseconds, stackTraceIntervalMilliseconds, nonFatalIdenticalCompilationSnapshots);
|
43972
|
310 |
WATCH_DOGS.set(watchDog);
|
55509
|
311 |
GraalServiceThread thread = new GraalServiceThread(watchDog);
|
|
312 |
thread.setName(thread.getId() + " " + watchDog.toString());
|
|
313 |
thread.setPriority(Thread.MAX_PRIORITY);
|
|
314 |
thread.setDaemon(true);
|
|
315 |
thread.start();
|
43972
|
316 |
}
|
|
317 |
watchDog.startCompilation(method, id);
|
|
318 |
return watchDog;
|
|
319 |
}
|
|
320 |
return null;
|
|
321 |
}
|
|
322 |
|
|
323 |
@Override
|
|
324 |
public void close() {
|
|
325 |
stopCompilation();
|
|
326 |
}
|
|
327 |
}
|