EventDispatchThreadHangMonitor.java
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 }