Log in Help
Print
HomegatepluginsDeveloper_Toolssrcorgjdesktopswinghelperdebug 〉 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 gate.gui.MainFrame;

import java.awt.AWTEvent;
import java.awt.EventQueue;
import java.awt.FlowLayout;
import java.awt.Toolkit;
import java.awt.event.ActionEvent;
import java.awt.event.ActionListener;
import java.awt.event.WindowAdapter;
import java.awt.event.WindowEvent;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.util.LinkedList;
import java.util.Timer;
import java.util.TimerTask;

import javax.swing.JButton;
import javax.swing.JDialog;
import javax.swing.JFrame;
import javax.swing.JLabel;
import javax.swing.SwingUtilities;

/**
 * Monitors the AWT event dispatch thread for events that take longer than a
 * certain time to be dispatched. 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. This is useful in determining what code is causing your Java
 * application's GUI to be unresponsive. 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>
 * 
 * @author Elliott Hughes <enh@jessies.org>
 */
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);
      // MAG: we already check for deadlocks in GATE
      // 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() {
    //do the switch on the EDT as a fix for this bug
    //http://bugs.java.com/bugdatabase/view_bug.do?bug_id=7097333
    SwingUtilities.invokeLater(new Runnable() {
      @Override
      public void run() {
        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;
      }
    }
  }

  @SuppressWarnings("unused")
  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");
  }

  @SuppressWarnings("unused")
  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) {
      // MAG: send messages to the console, because if the AWT is locked
      // then they won't show up anyway
      MainFrame.getInstance().getOriginalOut().println(str);
    }
  }
}