src/main/java/org/jdesktop/swinghelper/debug/EventDispatchThreadHangMonitor.java

/*
 * This library is free software; you can redistribute it and/or
 * modify it under the terms of the GNU Lesser General Public
 * License as published by the Free Software Foundation; either
 * version 2.1 of the License, or (at your option) any later version.
 *
 * This library is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
 * Lesser General Public License for more details.
 *
 * You should have received a copy of the GNU Lesser General Public
 * License along with this library; if not, write to the Free Software
 * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 */

package org.jdesktop.swinghelper.debug;

import java.awt.*;
import java.awt.event.*;
import java.lang.management.*;
import java.util.*;
import java.util.Timer;

import javax.swing.*;

/**
 * Monitors the AWT event dispatch thread for events that take longer than
 * a certain time to be dispatched.
 * <p/>
 * The principle is to record the time at which we start processing an event,
 * and have another thread check frequently to see if we're still processing.
 * If the other thread notices that we've been processing a single event for
 * too long, it prints a stack trace showing what the event dispatch thread
 * is doing, and continues to time it until it finally finishes.
 * <p/>
 * This is useful in determining what code is causing your Java application's
 * GUI to be unresponsive.
 * 
 * <p>The original blog can be found here<br>  
 * <a href="http://elliotth.blogspot.com/2005/05/automatically-detecting-awt-event.html">
 * Automatically detecting AWT event dispatch thread hangs</a>
 * </p>
 *
 * @author Elliott Hughes <enh@jessies.org>
 * 
 * Advice, bug fixes, and test cases from
 * Alexander Potochkin and Oleg Sukhodolsky.
 * 
 * https://swinghelper.dev.java.net/
 */
public final class EventDispatchThreadHangMonitor extends EventQueue {
    private static final EventDispatchThreadHangMonitor INSTANCE = new EventDispatchThreadHangMonitor();

    // Time to wait between checks that the event dispatch thread isn't hung.
    private static final long CHECK_INTERVAL_MS = 100;

    // Maximum time we won't warn about. This used to be 500 ms, but 1.5 on
    // late-2004 hardware isn't really up to it; there are too many parts of
    // the JDK that can go away for that long (often code that has to be
    // called on the event dispatch thread, like font loading).
    private static final long UNREASONABLE_DISPATCH_DURATION_MS = 1000;

    // Help distinguish multiple hangs in the log, and match start and end too.
    // Only access this via getNewHangNumber.
    private static int hangCount = 0;

    // Prevents us complaining about hangs during start-up, which are probably
    // the JVM vendor's fault.
    private boolean haveShownSomeComponent = false;

    // The currently outstanding event dispatches. The implementation of
    // modal dialogs is a common cause for multiple outstanding dispatches.
    private final LinkedList<DispatchInfo> dispatches = new LinkedList<DispatchInfo>();

    private static class DispatchInfo {
        // The last-dumped hung stack trace for this dispatch.
        private StackTraceElement[] lastReportedStack;
        // If so; what was the identifying hang number?
        private int hangNumber;

        // The EDT for this dispatch (for the purpose of getting stack traces).
        // I don't know of any API for getting the event dispatch thread,
        // but we can assume that it's the current thread if we're in the
        // middle of dispatching an AWT event...
        // We can't cache this because the EDT can die and be replaced by a
        // new EDT if there's an uncaught exception.
        private final Thread eventDispatchThread = Thread.currentThread();

        // The last time in milliseconds at which we saw a dispatch on the above thread.
        private long lastDispatchTimeMillis = System.currentTimeMillis();

        public DispatchInfo() {
            // All initialization is done by the field initializers.
        }

        public void checkForHang() {
            if (timeSoFar() > UNREASONABLE_DISPATCH_DURATION_MS) {
                examineHang();
            }
        }

        // We can't use StackTraceElement.equals because that insists on checking the filename and line number.
        // That would be version-specific.
        private static boolean stackTraceElementIs(StackTraceElement e, String className, String methodName, boolean isNative) {
            return e.getClassName().equals(className) && e.getMethodName().equals(methodName) && e.isNativeMethod() == isNative;
        }

        // Checks whether the given stack looks like it's waiting for another event.
        // This relies on JDK implementation details.
        private boolean isWaitingForNextEvent(StackTraceElement[] currentStack) {
            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);
        }

        private void examineHang() {
            StackTraceElement[] currentStack = eventDispatchThread.getStackTrace();

            if (isWaitingForNextEvent(currentStack)) {
                // Don't be fooled by a modal dialog if it's waiting for its next event.
                // As long as the modal dialog's event pump doesn't get stuck, it's okay for the outer pump to be suspended.
                return;
            }

            if (stacksEqual(lastReportedStack, currentStack)) {
                // Don't keep reporting the same hang every time the timer goes off.
                return;
            }

            hangNumber = getNewHangNumber();
            String stackTrace = stackTraceToString(currentStack);
            lastReportedStack = currentStack;
            Log.warn("(hang #" + hangNumber + ") event dispatch thread stuck processing event for " + timeSoFar() + " ms:" + stackTrace);
            checkForDeadlock();
        }

        private static boolean stacksEqual(StackTraceElement[] a, StackTraceElement[] b) {
            if (a == null) {
                return false;
            }
            if (a.length != b.length) {
                return false;
            }
            for (int i = 0; i < a.length; ++i) {
                if (a[i].equals(b[i]) == false) {
                    return false;
                }
            }
            return true;
        }

        /**
         * Returns how long this dispatch has been going on (in milliseconds).
         */
        private long timeSoFar() {
            return (System.currentTimeMillis() - lastDispatchTimeMillis);
        }

        public void dispose() {
            if (lastReportedStack != null) {
                Log.warn("(hang #" + hangNumber + ") event dispatch thread unstuck after " + timeSoFar() + " ms.");
            }
        }
    }

    private EventDispatchThreadHangMonitor() {
        initTimer();
    }

    /**
     * Sets up a timer to check for hangs frequently.
     */
    private void initTimer() {
        final long initialDelayMs = 0;
        final boolean isDaemon = true;
        Timer timer = new Timer("EventDispatchThreadHangMonitor", isDaemon);
        timer.schedule(new HangChecker(), initialDelayMs, CHECK_INTERVAL_MS);
    }

    private class HangChecker extends TimerTask {
        @Override
        public void run() {
            synchronized (dispatches) {
                if (dispatches.isEmpty() || !haveShownSomeComponent) {
                    // Nothing to do.
                    // We don't destroy the timer when there's nothing happening
                    // because it would mean a lot more work on every single AWT
                    // event that gets dispatched.
                    return;
                }
                // Only the most recent dispatch can be hung; nested dispatches
                // by their nature cause the outer dispatch pump to be suspended.
                dispatches.getLast().checkForHang();
            }
        }
    }

    /**
     * Sets up hang detection for the event dispatch thread.
     */
    public static void initMonitoring() {
        Toolkit.getDefaultToolkit().getSystemEventQueue().push(INSTANCE);
    }

    /**
     * Overrides EventQueue.dispatchEvent to call our pre and post hooks either
     * side of the system's event dispatch code.
     */
    @Override
    protected void dispatchEvent(AWTEvent event) {
        try {
            preDispatchEvent();
            super.dispatchEvent(event);
        } finally {
            postDispatchEvent();
            if (!haveShownSomeComponent && 
                    event instanceof WindowEvent && event.getID() == WindowEvent.WINDOW_OPENED) {
                haveShownSomeComponent = true;
            }
        }
    }

    private void debug(String which) {
        if (false) {
            for (int i = dispatches.size(); i >= 0; --i) {
                System.out.print(' ');
            }
            System.out.println(which);
        }
    }

    /**
     * Starts tracking a dispatch.
     */
    private synchronized void preDispatchEvent() {
        debug("pre");
        synchronized (dispatches) {
            dispatches.addLast(new DispatchInfo());
        }
    }

    /**
     * Stops tracking a dispatch.
     */
    private synchronized void postDispatchEvent() {
        synchronized (dispatches) {
            // We've finished the most nested dispatch, and don't need it any longer.
            DispatchInfo justFinishedDispatch = dispatches.removeLast();
            justFinishedDispatch.dispose();

            // The other dispatches, which have been waiting, need to be credited extra time.
            // We do this rather simplistically by pretending they've just been redispatched.
            Thread currentEventDispatchThread = Thread.currentThread();
            for (DispatchInfo dispatchInfo : dispatches) {
                if (dispatchInfo.eventDispatchThread == currentEventDispatchThread) {
                    dispatchInfo.lastDispatchTimeMillis = System.currentTimeMillis();
                }
            }
        }
        debug("post");
    }

    private static void checkForDeadlock() {
        ThreadMXBean threadBean = ManagementFactory.getThreadMXBean();
        long[] threadIds = threadBean.findMonitorDeadlockedThreads();
        if (threadIds == null) {
            return;
        }
        Log.warn("deadlock detected involving the following threads:");
        ThreadInfo[] threadInfos = threadBean.getThreadInfo(threadIds, Integer.MAX_VALUE);
        for (ThreadInfo info : threadInfos) {
            Log.warn("Thread #" + info.getThreadId() + " " + info.getThreadName() + 
                    " (" + info.getThreadState() + ") waiting on " + info.getLockName() + 
                    " held by " + info.getLockOwnerName() + stackTraceToString(info.getStackTrace()));
        }
    }

    private static String stackTraceToString(StackTraceElement[] stackTrace) {
        StringBuilder result = new StringBuilder();
        // We used to avoid showing any code above where this class gets
        // involved in event dispatch, but that hides potentially useful
        // information when dealing with modal dialogs. Maybe we should
        // reinstate that, but search from the other end of the stack?
        for (StackTraceElement stackTraceElement : stackTrace) {
            String indentation = "    ";
            result.append("\n" + indentation + stackTraceElement);
        }
        return result.toString();
    }

    private synchronized static int getNewHangNumber() {
        return ++hangCount;
    }

    public static void main(String[] args) {
        initMonitoring();
        //special case for deadlock test
        if (args.length > 0 && "deadlock".equals(args[0])) {
            EventDispatchThreadHangMonitor.INSTANCE.haveShownSomeComponent = true;
            Tests.runDeadlockTest();
            return;
        }
        Tests.main(args);
    }

    private static class Tests {
        public static void main(final String[] args) {

            java.awt.EventQueue.invokeLater(new Runnable() {
                public void run() {
                    for (String arg : args) {
                        final JFrame frame = new JFrame();
                        frame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
                        frame.setLocationRelativeTo(null);
                        if (arg.equals("exception")) {
                            runExceptionTest(frame);
                        } else if (arg.equals("focus")) {
                            runFocusTest(frame);
                        } else if (arg.equals("modal-hang")) {
                            runModalTest(frame, true);
                        } else if (arg.equals("modal-no-hang")) {
                            runModalTest(frame, false);
                        } else {
                            System.err.println("unknown regression test '" + arg + "'");
                            System.exit(1);
                        }
                        frame.pack();
                        frame.setVisible(true);
                    }
                }
            });
        }

        private static void runDeadlockTest() {
            class Locker {
                private Locker locker;

                public void setLocker(Locker locker) {
                    this.locker = locker;
                }

                public synchronized void tryToDeadlock() {
                    locker.toString();
                }

                public synchronized String toString() {
                    try {
                        Thread.sleep(50);
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                    return super.toString();
                }
            }
            final Locker one = new Locker();
            final Locker two = new Locker();
            one.setLocker(two);
            two.setLocker(one);

            //Deadlock expected here:
            for (int i = 0; i < 100; i++) {
                SwingUtilities.invokeLater(new Runnable() {
                    public void run() {
                        one.tryToDeadlock();
                    }
                });
                two.tryToDeadlock();
            }
        }

        // If we don't do our post-dispatch activity in a finally block, we'll
        // report bogus hangs.
        private static void runExceptionTest(final JFrame frame) {
            JButton button = new JButton("Throw Exception");
            button.addActionListener(new ActionListener() {
                public void actionPerformed(ActionEvent e) {
                    // This shouldn't cause us to report a hang.
                    throw new RuntimeException("Nobody expects the Spanish Inquisition!");
                }
            });
            frame.add(button);
        }

        // A demonstration of nested calls to dispatchEvent caused by SequencedEvent.
        private static void runFocusTest(final JFrame frame) {
            final JDialog dialog = new JDialog(frame, "Non-Modal Dialog");
            dialog.add(new JLabel("Close me!"));
            dialog.pack();
            dialog.setLocationRelativeTo(frame);
            dialog.addWindowFocusListener(new WindowAdapter() {
                public void windowGainedFocus(WindowEvent e) {
                    System.out.println("FocusTest.windowGainedFocus");
                    // If you don't cope with nested calls to dispatchEvent, you won't detect this.
                    // See java.awt.SequencedEvent for an example.
                    sleep(2500);
                }
            });
            JButton button = new JButton("Show Non-Modal Dialog");
            button.addActionListener(new ActionListener() {
                public void actionPerformed(ActionEvent e) {
                    dialog.setVisible(true);
                }
            });
            frame.add(button);
        }

        // A demonstration of the problems of dealing with modal dialogs.
        private static void runModalTest(final JFrame frame, final boolean shouldSleep) {
            System.out.println(shouldSleep ? "Expect hangs!" : "There should be no hangs...");
            JButton button = new JButton("Show Modal Dialog");
            button.addActionListener(new ActionListener() {
                public void actionPerformed(ActionEvent e) {
                    if (shouldSleep) {
                        sleep(2500); // This is easy.
                    }
                    JDialog dialog = new JDialog(frame, "Modal dialog", true);
                    dialog.setLayout(new FlowLayout());
                    dialog.add(new JLabel("Close this dialog!"));
                    final JLabel label = new JLabel(" ");
                    dialog.add(label);
                    dialog.pack();
                    dialog.setLocation(frame.getX() - 100, frame.getY());

                    // Make sure the new event pump has some work to do, each unit of which is insufficient to cause a hang.
                    new Thread(new Runnable() {
                        public void run() {
                            for (int i = 0; i <= 100000; ++i) {
                                final int value = i;
                                EventQueue.invokeLater(new Runnable() {
                                    public void run() {
                                        label.setText(Integer.toString(value));
                                    }
                                });
                            }
                        }
                    }).start();

                    dialog.setVisible(true);

                    if (shouldSleep) {
                        sleep(2500); // If you don't distinguish different stack traces, you won't report this.
                    }
                }
            });
            frame.add(button);
        }

        private static void sleep(long ms) {
            try {
                System.out.println("Sleeping for " + ms + " ms on " + Thread.currentThread() + "...");
                Thread.sleep(ms);
                System.out.println("Finished sleeping...");
            } catch (Exception ex) {
                ex.printStackTrace();
            }
        }
    }

    private static class Log {
        public static void warn(String str) {
            System.out.println(str);
        }
    }
}