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