1 /*
2 * Copyright (c) 2016, 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.
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 */
23 package org.graalvm.compiler.hotspot;
24
25 import static org.graalvm.compiler.hotspot.HotSpotGraalCompiler.fmt;
26 import static org.graalvm.compiler.hotspot.HotSpotGraalCompilerFactory.GRAAL_OPTION_PROPERTY_PREFIX;
27
28 import java.util.Arrays;
29 import java.util.HashMap;
30 import java.util.Map;
31 import java.util.concurrent.atomic.AtomicInteger;
32
33 import org.graalvm.compiler.debug.TTY;
34 import org.graalvm.compiler.options.Option;
35 import org.graalvm.compiler.options.OptionType;
36 import org.graalvm.compiler.options.OptionValue;
37
38 import jdk.vm.ci.code.CompilationRequest;
39
40 /**
41 * A watch dog that monitors the duration and compilation rate during a
42 * {@linkplain HotSpotGraalRuntimeProvider#isBootstrapping() bootstrap}. If time spent bootstrapping
43 * exceeds a specified timeout or the compilation rate falls below a given ratio of the maximum
44 * observed compilation rate (i.e., compilation slows down too much), the compiler will ignore all
45 * subsequent compilation requests, effectively draining the bootstrap completion queue and
46 * expediting completion of bootstrap. Note that the compilation rate is computed over the whole
47 * execution, not just the most recent measurement period. This means a sudden but temporary drop in
48 * any given measurement period won't cause bootstrapping to terminate early.
49 *
50 * This mechanism is based on past observations that a significantly falling bootstrap compilation
51 * rate implies a configuration where bootstrapping will take an unreasonably long time and it's
52 * better to drain the bootstrap compilation queue at some point that risk triggering timeouts in
53 * external harnesses such as integration tests.
54 */
55 final class BootstrapWatchDog extends Thread {
56
57 public static class Options {
58 // @formatter:off
59 @Option(help = "Ratio of the maximum compilation rate below which the bootstrap compilation rate must not fall " +
60 "(0 or less disables monitoring).", type = OptionType.Debug)
61 public static final OptionValue<Double> BootstrapWatchDogCriticalRateRatio = new OptionValue<>(0.25D);
62 @Option(help = "Maximum time in minutes to spend bootstrapping (0 to disable this limit).", type = OptionType.Debug)
63 public static final OptionValue<Double> BootstrapTimeout = new OptionValue<>(15D);
64 // @formatter:on
65 }
66
67 /**
68 * Count of completed compilations. This is updated by the compiler threads and read by the
69 * watch dog thread.
70 */
71 private final AtomicInteger compilations = new AtomicInteger();
72
73 /**
74 * Set to true once the compilation rate drops too low or bootstrapping times out.
75 */
76 private boolean hitCriticalRateOrTimeout;
77
78 /**
79 * The maximum compilation rate seen during execution.
80 */
81 private double maxRate;
82
83 private final HotSpotGraalRuntimeProvider graalRuntime;
84
85 /**
86 * Creates and returns a {@link BootstrapWatchDog} if
87 * {@link Options#BootstrapWatchDogCriticalRateRatio} is not set to 0 otherwise returns
88 * {@code null}.
89 */
90 static BootstrapWatchDog maybeCreate(HotSpotGraalRuntimeProvider graalRuntime) {
91 return MAX_RATE_DECREASE <= 0.0D && TIMEOUT == 0 ? null : new BootstrapWatchDog(graalRuntime);
92 }
93
94 private BootstrapWatchDog(HotSpotGraalRuntimeProvider graalRuntime) {
95 this.setName(getClass().getSimpleName());
96 this.start();
97 this.graalRuntime = graalRuntime;
98 }
99
100 /**
101 * Set to true to debug the watch dog.
102 */
103 private static final boolean DEBUG = Boolean.getBoolean("debug.graal.BootstrapWatchDog");
104
105 /**
106 * Seconds to delay before starting to measure the compilation rate.
107 */
108 private static final int INITIAL_DELAY = 10;
109
110 /**
111 * Seconds between each compilation rate measurement.
112 */
113 private static final long EPOCH = 5;
114
115 /**
116 * Time in seconds before stopping a bootstrap.
117 */
118 private static final int TIMEOUT = (int) (Options.BootstrapTimeout.getValue() * 60);
119
120 /**
121 * The watch dog {@link #hitCriticalCompilationRateOrTimeout() hits} a critical compilation rate
122 * if the current compilation rate falls below this ratio of the maximum compilation rate.
123 */
124 private static final double MAX_RATE_DECREASE = Options.BootstrapWatchDogCriticalRateRatio.getValue();
125
126 @Override
127 public void run() {
128 if (DEBUG) {
129 TTY.printf("%nStarted %s%n", this);
130 }
131 long start = System.currentTimeMillis();
132 Map<Thread, Watch> requestsAtTimeout = null;
133 Map<Thread, StackTraceElement[]> stacksAtTimeout = null;
134 try {
135 Thread.sleep(INITIAL_DELAY * 1000);
136 while (true) {
137 int currentCompilations = compilations.get();
138 long elapsed = System.currentTimeMillis() - start;
139 double rate = currentCompilations / seconds(elapsed);
140 if (DEBUG) {
141 TTY.printf("%.2f: compilation rate is %.2f/sec%n", seconds(elapsed), rate);
142 }
143 if (rate > maxRate) {
144 maxRate = rate;
145 } else if (rate < (maxRate * MAX_RATE_DECREASE)) {
146 TTY.printf("%nAfter %.2f seconds bootstrapping, compilation rate is %.2f compilations per second " +
147 "which is below %.2f times the max compilation rate of %.2f%n", seconds(elapsed), rate, MAX_RATE_DECREASE, maxRate);
148 TTY.printf("To enable monitoring of long running individual compilations, re-run with -D%s%s=%.2f%n",
149 GRAAL_OPTION_PROPERTY_PREFIX, CompilationWatchDog.Options.CompilationWatchDogStartDelay.getName(),
150 seconds(elapsed) - 5);
151 hitCriticalRateOrTimeout = true;
152 return;
153 }
154 if (elapsed > TIMEOUT * 1000) {
155 if (requestsAtTimeout == null) {
156 requestsAtTimeout = snapshotRequests();
157 stacksAtTimeout = new HashMap<>();
158 for (Thread t : requestsAtTimeout.keySet()) {
159 stacksAtTimeout.put(t, t.getStackTrace());
160 }
161 } else {
162 TTY.printf("%nHit bootstrapping timeout after %.2f seconds%n", seconds(elapsed));
163 Map<Thread, Watch> requestsNow = snapshotRequests();
164 for (Map.Entry<Thread, Watch> e : requestsAtTimeout.entrySet()) {
165 Thread t = e.getKey();
166 CompilationRequest request1 = requestsAtTimeout.get(t).request;
167 CompilationRequest request2 = requestsNow.get(t).request;
168 if (request1 != null && request1 == request2) {
169 StackTraceElement[] stackTraceNow = t.getStackTrace();
170 TTY.printf("Printing stack trace for current compilation of %s lasting more than %d seconds:%n%s",
171 fmt(request1.getMethod()), EPOCH, fmt(stackTraceNow));
172 if (Arrays.equals(stacksAtTimeout.get(t), stackTraceNow)) {
173 TTY.printf("\t** Identical stack trace %d seconds ago, implying a hung compilation **%n",
174 EPOCH);
175 }
176 } else {
177 if (DEBUG) {
178 TTY.printf("%s was compiling %s%n", t, fmt(request1.getMethod()));
179 }
180 }
181 }
182 hitCriticalRateOrTimeout = true;
183 return;
184 }
185 }
186 if (!graalRuntime.isBootstrapping()) {
187 return;
188 }
189
190 Thread.sleep(EPOCH * 1000);
191 }
192 } catch (InterruptedException e) {
193 e.printStackTrace(TTY.out);
194 }
195 }
196
197 private Map<Thread, Watch> snapshotRequests() {
198 synchronized (requests) {
199 return new HashMap<>(requests);
200 }
201 }
202
203 private static double seconds(long ms) {
204 return (double) ms / 1000;
205 }
206
207 /**
208 * Queries whether a critically low compilation rate or {@link #TIMEOUT} occurred.
209 */
210 boolean hitCriticalCompilationRateOrTimeout() {
211 return hitCriticalRateOrTimeout;
212 }
213
214 private final Map<Thread, Watch> requests = new HashMap<>();
215 private final ThreadLocal<Watch> requestForThread = new ThreadLocal<>();
216
217 /**
218 * Opens a scope for watching the compilation of a given method.
219 *
220 * @param request a compilation request about to be processed
221 * @return {@code null} if the compilation watch dog is disabled otherwise this object. The
222 * returned value should be used in a {@code try}-with-resources statement whose scope
223 * is the whole compilation so that leaving the scope will cause {@link Watch#close()}
224 * to be called.
225 */
226 Watch watch(CompilationRequest request) {
227 Watch watch = requestForThread.get();
228 if (watch == null) {
229 watch = new Watch();
230 synchronized (requests) {
231 requests.put(Thread.currentThread(), watch);
232 }
233 }
234 watch.open(request);
235 return watch;
236 }
237
238 /**
239 * Object for watching the compilations requests of a single compiler thread.
240 */
241 class Watch implements AutoCloseable {
242 CompilationRequest request;
243
244 void open(CompilationRequest r) {
245 assert this.request == null;
246 this.request = r;
247 }
248
249 @Override
250 public void close() {
251 compilations.incrementAndGet();
252 request = null;
253 }
254 }
255 }