001/*
002 * This file is part of McIDAS-V
003 *
004 * Copyright 2007-2024
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 https://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                        logger.trace("Thread interrupted", e);
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}