001/* 002 * This file is part of McIDAS-V 003 * 004 * Copyright 2007-2017 005 * Space Science and Engineering Center (SSEC) 006 * University of Wisconsin - Madison 007 * 1225 W. Dayton Street, Madison, WI 53706, USA 008 * https://www.ssec.wisc.edu/mcidas 009 * 010 * All Rights Reserved 011 * 012 * McIDAS-V is built on Unidata's IDV and SSEC's VisAD libraries, and 013 * some McIDAS-V source code is based on IDV and VisAD source code. 014 * 015 * McIDAS-V is free software; you can redistribute it and/or modify 016 * it under the terms of the GNU Lesser Public License as published by 017 * the Free Software Foundation; either version 3 of the License, or 018 * (at your option) any later version. 019 * 020 * McIDAS-V is distributed in the hope that it will be useful, 021 * but WITHOUT ANY WARRANTY; without even the implied warranty of 022 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 023 * GNU Lesser Public License for more details. 024 * 025 * You should have received a copy of the GNU Lesser Public License 026 * along with this program. If not, see http://www.gnu.org/licenses. 027 */ 028 029package edu.wisc.ssec.mcidasv.util.gui; 030 031import java.awt.*; 032import java.awt.event.*; 033import java.lang.management.*; 034import java.util.*; 035import java.util.Timer; 036 037import javax.swing.*; 038 039import org.slf4j.Logger; 040import org.slf4j.LoggerFactory; 041 042/** 043 * Monitors the AWT event dispatch thread for events that take longer than 044 * a certain time to be dispatched. 045 * <p/> 046 * The principle is to record the time at which we start processing an event, 047 * and have another thread check frequently to see if we're still processing. 048 * If the other thread notices that we've been processing a single event for 049 * too long, it prints a stack trace showing what the event dispatch thread 050 * is doing, and continues to time it until it finally finishes. 051 * <p/> 052 * This is useful in determining what code is causing your Java application's 053 * GUI to be unresponsive. 054 * 055 * <p>The original blog can be found here<br> 056 * <a href="http://elliotth.blogspot.com/2005/05/automatically-detecting-awt-event.html"> 057 * Automatically detecting AWT event dispatch thread hangs</a> 058 * </p> 059 * 060 * @author Elliott Hughes <enh@jessies.org> 061 * 062 * Advice, bug fixes, and test cases from 063 * Alexander Potochkin and Oleg Sukhodolsky. 064 * 065 * https://swinghelper.dev.java.net/ 066 */ 067public final class EventDispatchThreadHangMonitor extends EventQueue { 068 069 private static final Logger logger = 070 LoggerFactory.getLogger(EventDispatchThreadHangMonitor.class); 071 072 private static final EventDispatchThreadHangMonitor INSTANCE = new EventDispatchThreadHangMonitor(); 073 074 // Time to wait between checks that the event dispatch thread isn't hung. 075 private static final long CHECK_INTERVAL_MS = 100; 076 077 // Maximum time we won't warn about. This used to be 500 ms, but 1.5 on 078 // late-2004 hardware isn't really up to it; there are too many parts of 079 // the JDK that can go away for that long (often code that has to be 080 // called on the event dispatch thread, like font loading). 081 private static final long UNREASONABLE_DISPATCH_DURATION_MS = 1000; 082 083 // Help distinguish multiple hangs in the log, and match start and end too. 084 // Only access this via getNewHangNumber. 085 private static int hangCount = 0; 086 087 // Prevents us complaining about hangs during start-up, which are probably 088 // the JVM vendor's fault. 089 private boolean haveShownSomeComponent = false; 090 091 // The currently outstanding event dispatches. The implementation of 092 // modal dialogs is a common cause for multiple outstanding dispatches. 093 private final LinkedList<DispatchInfo> dispatches = new LinkedList<DispatchInfo>(); 094 095 private static class DispatchInfo { 096 // The last-dumped hung stack trace for this dispatch. 097 private StackTraceElement[] lastReportedStack; 098 // If so; what was the identifying hang number? 099 private int hangNumber; 100 101 // The EDT for this dispatch (for the purpose of getting stack traces). 102 // I don't know of any API for getting the event dispatch thread, 103 // but we can assume that it's the current thread if we're in the 104 // middle of dispatching an AWT event... 105 // We can't cache this because the EDT can die and be replaced by a 106 // new EDT if there's an uncaught exception. 107 private final Thread eventDispatchThread = Thread.currentThread(); 108 109 // The last time in milliseconds at which we saw a dispatch on the above thread. 110 private long lastDispatchTimeMillis = System.currentTimeMillis(); 111 112 public DispatchInfo() { 113 // All initialization is done by the field initializers. 114 } 115 116 public void checkForHang() { 117 if (timeSoFar() > UNREASONABLE_DISPATCH_DURATION_MS) { 118 examineHang(); 119 } 120 } 121 122 // We can't use StackTraceElement.equals because that insists on checking the filename and line number. 123 // That would be version-specific. 124 private static boolean stackTraceElementIs(StackTraceElement e, String className, String methodName, boolean isNative) { 125 return e.getClassName().equals(className) && e.getMethodName().equals(methodName) && e.isNativeMethod() == isNative; 126 } 127 128 // Checks whether the given stack looks like it's waiting for another event. 129 // This relies on JDK implementation details. 130 private boolean isWaitingForNextEvent(StackTraceElement[] currentStack) { 131 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); 132 } 133 134 private void examineHang() { 135 StackTraceElement[] currentStack = eventDispatchThread.getStackTrace(); 136 137 if (isWaitingForNextEvent(currentStack)) { 138 // Don't be fooled by a modal dialog if it's waiting for its next event. 139 // As long as the modal dialog's event pump doesn't get stuck, it's okay for the outer pump to be suspended. 140 return; 141 } 142 143 if (stacksEqual(lastReportedStack, currentStack)) { 144 // Don't keep reporting the same hang every time the timer goes off. 145 return; 146 } 147 148 hangNumber = getNewHangNumber(); 149 String stackTrace = stackTraceToString(currentStack); 150 lastReportedStack = currentStack; 151 logger.debug("(hang #" + hangNumber + ") event dispatch thread stuck processing event for " + timeSoFar() + " ms:" + stackTrace); 152 checkForDeadlock(); 153 } 154 155 private static boolean stacksEqual(StackTraceElement[] a, StackTraceElement[] b) { 156 if (a == null) { 157 return false; 158 } 159 if (a.length != b.length) { 160 return false; 161 } 162 for (int i = 0; i < a.length; ++i) { 163 if (a[i].equals(b[i]) == false) { 164 return false; 165 } 166 } 167 return true; 168 } 169 170 /** 171 * Returns how long this dispatch has been going on (in milliseconds). 172 */ 173 private long timeSoFar() { 174 return (System.currentTimeMillis() - lastDispatchTimeMillis); 175 } 176 177 public void dispose() { 178 if (lastReportedStack != null) { 179 logger.debug("(hang #" + hangNumber + ") event dispatch thread unstuck after " + timeSoFar() + " ms."); 180 } 181 } 182 } 183 184 private EventDispatchThreadHangMonitor() { 185 initTimer(); 186 } 187 188 /** 189 * Sets up a timer to check for hangs frequently. 190 */ 191 private void initTimer() { 192 final long initialDelayMs = 0; 193 final boolean isDaemon = true; 194 Timer timer = new Timer("EventDispatchThreadHangMonitor", isDaemon); 195 timer.schedule(new HangChecker(), initialDelayMs, CHECK_INTERVAL_MS); 196 } 197 198 private class HangChecker extends TimerTask { 199 @Override 200 public void run() { 201 synchronized (dispatches) { 202 if (dispatches.isEmpty() || !haveShownSomeComponent) { 203 // Nothing to do. 204 // We don't destroy the timer when there's nothing happening 205 // because it would mean a lot more work on every single AWT 206 // event that gets dispatched. 207 return; 208 } 209 // Only the most recent dispatch can be hung; nested dispatches 210 // by their nature cause the outer dispatch pump to be suspended. 211 dispatches.getLast().checkForHang(); 212 } 213 } 214 } 215 216 /** 217 * Sets up hang detection for the event dispatch thread. 218 */ 219 public static void initMonitoring() { 220 Toolkit.getDefaultToolkit().getSystemEventQueue().push(INSTANCE); 221 } 222 223 /** 224 * Overrides EventQueue.dispatchEvent to call our pre and post hooks either 225 * side of the system's event dispatch code. 226 */ 227 @Override 228 protected void dispatchEvent(AWTEvent event) { 229 try { 230 preDispatchEvent(); 231 super.dispatchEvent(event); 232 } finally { 233 postDispatchEvent(); 234 if (!haveShownSomeComponent && 235 event instanceof WindowEvent && event.getID() == WindowEvent.WINDOW_OPENED) { 236 haveShownSomeComponent = true; 237 } 238 } 239 } 240 241// private void debug(String which) { 242// if (false) { 243// for (int i = dispatches.size(); i >= 0; --i) { 244// System.out.print(' '); 245// } 246// System.out.println(which); 247// } 248// } 249 250 /** 251 * Starts tracking a dispatch. 252 */ 253 private synchronized void preDispatchEvent() { 254// debug("pre"); 255 synchronized (dispatches) { 256 dispatches.addLast(new DispatchInfo()); 257 } 258 } 259 260 /** 261 * Stops tracking a dispatch. 262 */ 263 private synchronized void postDispatchEvent() { 264 synchronized (dispatches) { 265 // We've finished the most nested dispatch, and don't need it any longer. 266 DispatchInfo justFinishedDispatch = dispatches.removeLast(); 267 justFinishedDispatch.dispose(); 268 269 // The other dispatches, which have been waiting, need to be credited extra time. 270 // We do this rather simplistically by pretending they've just been redispatched. 271 Thread currentEventDispatchThread = Thread.currentThread(); 272 for (DispatchInfo dispatchInfo : dispatches) { 273 if (dispatchInfo.eventDispatchThread == currentEventDispatchThread) { 274 dispatchInfo.lastDispatchTimeMillis = System.currentTimeMillis(); 275 } 276 } 277 } 278// debug("post"); 279 } 280 281 private static void checkForDeadlock() { 282 ThreadMXBean threadBean = ManagementFactory.getThreadMXBean(); 283 long[] threadIds = threadBean.findMonitorDeadlockedThreads(); 284 if (threadIds == null) { 285 return; 286 } 287 logger.debug("deadlock detected involving the following threads:"); 288 ThreadInfo[] threadInfos = threadBean.getThreadInfo(threadIds, Integer.MAX_VALUE); 289 for (ThreadInfo info : threadInfos) { 290 logger.debug("Thread #" + info.getThreadId() + " " + info.getThreadName() + 291 " (" + info.getThreadState() + ") waiting on " + info.getLockName() + 292 " held by " + info.getLockOwnerName() + stackTraceToString(info.getStackTrace())); 293 } 294 } 295 296 private static String stackTraceToString(StackTraceElement[] stackTrace) { 297 StringBuilder result = new StringBuilder(); 298 // We used to avoid showing any code above where this class gets 299 // involved in event dispatch, but that hides potentially useful 300 // information when dealing with modal dialogs. Maybe we should 301 // reinstate that, but search from the other end of the stack? 302 for (StackTraceElement stackTraceElement : stackTrace) { 303 String indentation = " "; 304 result.append("\n" + indentation + stackTraceElement); 305 } 306 return result.toString(); 307 } 308 309 private synchronized static int getNewHangNumber() { 310 return ++hangCount; 311 } 312 313 public static void main(String[] args) { 314 initMonitoring(); 315 //special case for deadlock test 316 if (args.length > 0 && "deadlock".equals(args[0])) { 317 EventDispatchThreadHangMonitor.INSTANCE.haveShownSomeComponent = true; 318 Tests.runDeadlockTest(); 319 return; 320 } 321 Tests.main(args); 322 } 323 324 private static class Tests { 325 public static void main(final String[] args) { 326 327 java.awt.EventQueue.invokeLater(new Runnable() { 328 public void run() { 329 for (String arg : args) { 330 final JFrame frame = new JFrame(); 331 frame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE); 332 frame.setLocationRelativeTo(null); 333 if (arg.equals("exception")) { 334 runExceptionTest(frame); 335 } else if (arg.equals("focus")) { 336 runFocusTest(frame); 337 } else if (arg.equals("modal-hang")) { 338 runModalTest(frame, true); 339 } else if (arg.equals("modal-no-hang")) { 340 runModalTest(frame, false); 341 } else { 342 System.err.println("unknown regression test '" + arg + "'"); 343 System.exit(1); 344 } 345 frame.pack(); 346 frame.setVisible(true); 347 } 348 } 349 }); 350 } 351 352 private static void runDeadlockTest() { 353 class Locker { 354 private Locker locker; 355 356 public void setLocker(Locker locker) { 357 this.locker = locker; 358 } 359 360 public synchronized void tryToDeadlock() { 361 locker.toString(); 362 } 363 364 public synchronized String toString() { 365 try { 366 Thread.sleep(50); 367 } catch (InterruptedException e) { 368 e.printStackTrace(); 369 } 370 return super.toString(); 371 } 372 } 373 final Locker one = new Locker(); 374 final Locker two = new Locker(); 375 one.setLocker(two); 376 two.setLocker(one); 377 378 //Deadlock expected here: 379 for (int i = 0; i < 100; i++) { 380 SwingUtilities.invokeLater(new Runnable() { 381 public void run() { 382 one.tryToDeadlock(); 383 } 384 }); 385 two.tryToDeadlock(); 386 } 387 } 388 389 // If we don't do our post-dispatch activity in a finally block, we'll 390 // report bogus hangs. 391 private static void runExceptionTest(final JFrame frame) { 392 JButton button = new JButton("Throw Exception"); 393 button.addActionListener(new ActionListener() { 394 public void actionPerformed(ActionEvent e) { 395 // This shouldn't cause us to report a hang. 396 throw new RuntimeException("Nobody expects the Spanish Inquisition!"); 397 } 398 }); 399 frame.add(button); 400 } 401 402 // A demonstration of nested calls to dispatchEvent caused by SequencedEvent. 403 private static void runFocusTest(final JFrame frame) { 404 final JDialog dialog = new JDialog(frame, "Non-Modal Dialog"); 405 dialog.add(new JLabel("Close me!")); 406 dialog.pack(); 407 dialog.setLocationRelativeTo(frame); 408 dialog.addWindowFocusListener(new WindowAdapter() { 409 public void windowGainedFocus(WindowEvent e) { 410 System.out.println("FocusTest.windowGainedFocus"); 411 // If you don't cope with nested calls to dispatchEvent, you won't detect this. 412 // See java.awt.SequencedEvent for an example. 413 sleep(2500); 414 } 415 }); 416 JButton button = new JButton("Show Non-Modal Dialog"); 417 button.addActionListener(new ActionListener() { 418 public void actionPerformed(ActionEvent e) { 419 dialog.setVisible(true); 420 } 421 }); 422 frame.add(button); 423 } 424 425 // A demonstration of the problems of dealing with modal dialogs. 426 private static void runModalTest(final JFrame frame, final boolean shouldSleep) { 427 System.out.println(shouldSleep ? "Expect hangs!" : "There should be no hangs..."); 428 JButton button = new JButton("Show Modal Dialog"); 429 button.addActionListener(new ActionListener() { 430 public void actionPerformed(ActionEvent e) { 431 if (shouldSleep) { 432 sleep(2500); // This is easy. 433 } 434 JDialog dialog = new JDialog(frame, "Modal dialog", true); 435 dialog.setLayout(new FlowLayout()); 436 dialog.add(new JLabel("Close this dialog!")); 437 final JLabel label = new JLabel(" "); 438 dialog.add(label); 439 dialog.pack(); 440 dialog.setLocation(frame.getX() - 100, frame.getY()); 441 442 // Make sure the new event pump has some work to do, each unit of which is insufficient to cause a hang. 443 new Thread(new Runnable() { 444 public void run() { 445 for (int i = 0; i <= 100000; ++i) { 446 final int value = i; 447 EventQueue.invokeLater(new Runnable() { 448 public void run() { 449 label.setText(Integer.toString(value)); 450 } 451 }); 452 } 453 } 454 }).start(); 455 456 dialog.setVisible(true); 457 458 if (shouldSleep) { 459 sleep(2500); // If you don't distinguish different stack traces, you won't report this. 460 } 461 } 462 }); 463 frame.add(button); 464 } 465 466 private static void sleep(long ms) { 467 try { 468 logger.debug("Sleeping for " + ms + " ms on " + Thread.currentThread() + "..."); 469 Thread.sleep(ms); 470 logger.debug("Finished sleeping..."); 471 } catch (Exception ex) { 472 logger.debug("Caught exception!", ex); 473 } 474 } 475 } 476}