001 /*
002 * This library is free software; you can redistribute it and/or
003 * modify it under the terms of the GNU Lesser General Public
004 * License as published by the Free Software Foundation; either
005 * version 2.1 of the License, or (at your option) any later version.
006 *
007 * This library is distributed in the hope that it will be useful,
008 * but WITHOUT ANY WARRANTY; without even the implied warranty of
009 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
010 * Lesser General Public License for more details.
011 *
012 * You should have received a copy of the GNU Lesser General Public
013 * License along with this library; if not, write to the Free Software
014 * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
015 */
016
017 package org.jdesktop.swinghelper.debug;
018
019 import org.slf4j.Logger;
020 import org.slf4j.LoggerFactory;
021
022 import java.awt.AWTEvent;
023 import java.awt.EventQueue;
024 import java.awt.Toolkit;
025 import java.awt.event.WindowEvent;
026 import java.lang.management.ManagementFactory;
027 import java.lang.management.ThreadInfo;
028 import java.lang.management.ThreadMXBean;
029 import java.util.LinkedList;
030 import java.util.Timer;
031 import java.util.TimerTask;
032
033 import static griffon.core.GriffonExceptionHandler.sanitize;
034
035
036 /**
037 * Monitors the AWT event dispatch thread for events that take longer than
038 * a certain time to be dispatched.
039 * <p/>
040 * The principle is to record the time at which we start processing an event,
041 * and have another thread check frequently to see if we're still processing.
042 * If the other thread notices that we've been processing a single event for
043 * too long, it prints a stack trace showing what the event dispatch thread
044 * is doing, and continues to time it until it finally finishes.
045 * <p/>
046 * This is useful in determining what code is causing your Java application's
047 * GUI to be unresponsive.
048 * <p/>
049 * <p>The original blog can be found here<br>
050 * <a href="http://elliotth.blogspot.com/2005/05/automatically-detecting-awt-event.html">
051 * Automatically detecting AWT event dispatch thread hangs</a>
052 * </p>
053 *
054 * @author Elliott Hughes <enh@jessies.org>
055 * <p/>
056 * Advice, bug fixes, and test cases from
057 * Alexander Potochkin and Oleg Sukhodolsky.
058 * <p/>
059 * https://swinghelper.dev.java.net/
060 */
061 public final class EventDispatchThreadHangMonitor extends EventQueue {
062 private static final Logger LOG = LoggerFactory.getLogger(EventDispatchThreadHangMonitor.class);
063 private static final EventDispatchThreadHangMonitor INSTANCE = new EventDispatchThreadHangMonitor();
064
065 // Time to wait between checks that the event dispatch thread isn't hung.
066 private static final long CHECK_INTERVAL_MS = 100;
067
068 // Maximum time we won't warn about. This used to be 500 ms, but 1.5 on
069 // late-2004 hardware isn't really up to it; there are too many parts of
070 // the JDK that can go away for that long (often code that has to be
071 // called on the event dispatch thread, like font loading).
072 private static final long UNREASONABLE_DISPATCH_DURATION_MS = 1000;
073
074 // Help distinguish multiple hangs in the log, and match start and end too.
075 // Only access this via getNewHangNumber.
076 private static int hangCount = 0;
077
078 // Prevents us complaining about hangs during start-up, which are probably
079 // the JVM vendor's fault.
080 private boolean haveShownSomeComponent = false;
081
082 // The currently outstanding event dispatches. The implementation of
083 // modal dialogs is a common cause for multiple outstanding dispatches.
084 private final LinkedList<DispatchInfo> dispatches = new LinkedList<>();
085
086 // Time to wait before warning of slow operation
087 private long timeout = UNREASONABLE_DISPATCH_DURATION_MS;
088
089 private static class DispatchInfo {
090 // The last-dumped hung stack trace for this dispatch.
091 private StackTraceElement[] lastReportedStack;
092 // If so; what was the identifying hang number?
093 private int hangNumber;
094
095 // The EDT for this dispatch (for the purpose of getting stack traces).
096 // I don't know of any API for getting the event dispatch thread,
097 // but we can assume that it's the current thread if we're in the
098 // middle of dispatching an AWT event...
099 // We can't cache this because the EDT can die and be replaced by a
100 // new EDT if there's an uncaught exception.
101 private final Thread eventDispatchThread = Thread.currentThread();
102
103 // The last time in milliseconds at which we saw a dispatch on the above thread.
104 private long lastDispatchTimeMillis = System.currentTimeMillis();
105
106 private final long timeout;
107
108 public DispatchInfo(long timeout) {
109 // All initialization is done by the field initializers.
110 this.timeout = timeout;
111 }
112
113 public void checkForHang() {
114 if (timeSoFar() > timeout) {
115 examineHang();
116 }
117 }
118
119 // We can't use StackTraceElement.equals because that insists on checking the filename and line number.
120 // That would be version-specific.
121 private static boolean stackTraceElementIs(StackTraceElement e, String className, String methodName, boolean isNative) {
122 return e.getClassName().equals(className) && e.getMethodName().equals(methodName) && e.isNativeMethod() == isNative;
123 }
124
125 // Checks whether the given stack looks like it's waiting for another event.
126 // This relies on JDK implementation details.
127 private boolean isWaitingForNextEvent(StackTraceElement[] currentStack) {
128 return stackTraceElementIs(currentStack[0], "java.lang.Object", "wait", true) && stackTraceElementIs(currentStack[1], "java.lang.Object", "wait", false) && stackTraceElementIs(currentStack[2], "java.awt.EventQueue", "getNextEvent", false);
129 }
130
131 private void examineHang() {
132 StackTraceElement[] currentStack = sanitize(eventDispatchThread.getStackTrace());
133
134 if (isWaitingForNextEvent(currentStack)) {
135 // Don't be fooled by a modal dialog if it's waiting for its next event.
136 // As long as the modal dialog's event pump doesn't get stuck, it's okay for the outer pump to be suspended.
137 return;
138 }
139
140 if (stacksEqual(lastReportedStack, currentStack)) {
141 // Don't keep reporting the same hang every time the timer goes off.
142 return;
143 }
144
145 hangNumber = getNewHangNumber();
146 String stackTrace = stackTraceToString(currentStack);
147 lastReportedStack = currentStack;
148 if (LOG.isWarnEnabled()) {
149 LOG.warn("(hang #" + hangNumber + ") event dispatch thread stuck processing event for " + timeSoFar() + " ms:" + stackTrace);
150 }
151 checkForDeadlock();
152 }
153
154 private static boolean stacksEqual(StackTraceElement[] a, StackTraceElement[] b) {
155 if (a == null) {
156 return false;
157 }
158 if (a.length != b.length) {
159 return false;
160 }
161 for (int i = 0; i < a.length; ++i) {
162 if (!a[i].equals(b[i])) {
163 return false;
164 }
165 }
166 return true;
167 }
168
169 /**
170 * Returns how long this dispatch has been going on (in milliseconds).
171 */
172 private long timeSoFar() {
173 return (System.currentTimeMillis() - lastDispatchTimeMillis);
174 }
175
176 public void dispose() {
177 if (lastReportedStack != null) {
178 if (LOG.isWarnEnabled()) {
179 LOG.warn("(hang #" + hangNumber + ") event dispatch thread unstuck after " + timeSoFar() + " ms.");
180 }
181 }
182 }
183 }
184
185 private EventDispatchThreadHangMonitor() {
186 initTimer();
187 }
188
189 /**
190 * Sets up a timer to check for hangs frequently.
191 */
192 private void initTimer() {
193 final long initialDelayMs = 0;
194 final boolean isDaemon = true;
195 Timer timer = new Timer("EventDispatchThreadHangMonitor", isDaemon);
196 timer.schedule(new HangChecker(), initialDelayMs, CHECK_INTERVAL_MS);
197 }
198
199 private class HangChecker extends TimerTask {
200 @Override
201 public void run() {
202 synchronized (dispatches) {
203 if (dispatches.isEmpty() || !haveShownSomeComponent) {
204 // Nothing to do.
205 // We don't destroy the timer when there's nothing happening
206 // because it would mean a lot more work on every single AWT
207 // event that gets dispatched.
208 return;
209 }
210 // Only the most recent dispatch can be hung; nested dispatches
211 // by their nature cause the outer dispatch pump to be suspended.
212 dispatches.getLast().checkForHang();
213 }
214 }
215 }
216
217 /**
218 * Sets up hang detection for the event dispatch thread.
219 */
220 public static void initMonitoring() {
221 Toolkit.getDefaultToolkit().getSystemEventQueue().push(INSTANCE);
222 }
223
224 public static EventDispatchThreadHangMonitor getInstance() {
225 return INSTANCE;
226 }
227
228 public long getTimeout() {
229 return timeout;
230 }
231
232 public void setTimeout(long timeout) {
233 this.timeout = timeout > UNREASONABLE_DISPATCH_DURATION_MS ? timeout : UNREASONABLE_DISPATCH_DURATION_MS;
234 }
235
236 /**
237 * Overrides EventQueue.dispatchEvent to call our pre and post hooks either
238 * side of the system's event dispatch code.
239 */
240 @Override
241 protected void dispatchEvent(AWTEvent event) {
242 try {
243 preDispatchEvent();
244 super.dispatchEvent(event);
245 } finally {
246 postDispatchEvent();
247 if (!haveShownSomeComponent &&
248 event instanceof WindowEvent && event.getID() == WindowEvent.WINDOW_OPENED) {
249 haveShownSomeComponent = true;
250 }
251 }
252 }
253
254 /**
255 * Starts tracking a dispatch.
256 */
257 private synchronized void preDispatchEvent() {
258 synchronized (dispatches) {
259 dispatches.addLast(new DispatchInfo(timeout));
260 }
261 }
262
263 /**
264 * Stops tracking a dispatch.
265 */
266 private synchronized void postDispatchEvent() {
267 synchronized (dispatches) {
268 // We've finished the most nested dispatch, and don't need it any longer.
269 DispatchInfo justFinishedDispatch = dispatches.removeLast();
270 justFinishedDispatch.dispose();
271
272 // The other dispatches, which have been waiting, need to be credited extra time.
273 // We do this rather simplistically by pretending they've just been redispatched.
274 Thread currentEventDispatchThread = Thread.currentThread();
275 for (DispatchInfo dispatchInfo : dispatches) {
276 if (dispatchInfo.eventDispatchThread == currentEventDispatchThread) {
277 dispatchInfo.lastDispatchTimeMillis = System.currentTimeMillis();
278 }
279 }
280 }
281 }
282
283 private static void checkForDeadlock() {
284 ThreadMXBean threadBean = ManagementFactory.getThreadMXBean();
285 long[] threadIds = threadBean.findMonitorDeadlockedThreads();
286 if (threadIds == null) {
287 return;
288 }
289 if (LOG.isWarnEnabled()) {
290 StringBuilder b = new StringBuilder("Deadlock detected involving the following threads:");
291 ThreadInfo[] threadInfos = threadBean.getThreadInfo(threadIds, Integer.MAX_VALUE);
292 for (ThreadInfo info : threadInfos) {
293 b.append("Thread #")
294 .append(info.getThreadId())
295 .append(" ")
296 .append(info.getThreadName())
297 .append(" (")
298 .append(info.getThreadState()).
299 append(") waiting on ")
300 .append(info.getLockName())
301 .append(" held by ")
302 .append(info.getLockOwnerName())
303 .append(stackTraceToString(sanitize(info.getStackTrace())));
304 }
305 LOG.warn(b.toString());
306 }
307 }
308
309 private static String stackTraceToString(StackTraceElement[] stackTrace) {
310 StringBuilder result = new StringBuilder();
311 // We used to avoid showing any code above where this class gets
312 // involved in event dispatch, but that hides potentially useful
313 // information when dealing with modal dialogs. Maybe we should
314 // reinstate that, but search from the other end of the stack?
315 for (StackTraceElement stackTraceElement : stackTrace) {
316 String indentation = " ";
317 result.append("\n").append(indentation).append(stackTraceElement);
318 }
319 return result.toString();
320 }
321
322 private synchronized static int getNewHangNumber() {
323 return ++hangCount;
324 }
325 }
|