EDT Lockup Detection (in Java)

It was long-long ago in February of 2001 when Dr. Heinz M. Kabutz discovered and described in Issue 007 how an alternative EventQueue could be installed in an application. In his application he used this technique to install a global hotkey manager. Today I would like to share another use for overriding EventQueue:
All of us have heard the winged phrase "Swing is slow!" at least once. In my personal opinion it isn't. The problem of many applications is that all of the processing is triggered by the user interface and performed by the Events Dispatching Thread (EDT). The more complex processing becomes, the more time it takes to complete and the lower overall GUI responsiveness becomes. It's clear that the longer your code will block EDT, the longer your GUI will be in a seemingly frozen state.
Low GUI responsiveness is one part of the problem, the other is complete GUI lockups. Sometimes EDT gets completely deadlocked and is unable to process application events crowding in the queue. At this point you can call your application "dead". The background tasks can still be running normally, but the users will never see the results of their work. As might seem clear by now, I wish to share my own method of detecting excessive use and lockups of EDT. In the product I participate as developer (BlogBridge - news feeds reader) we have chosen to use EDT over-usage reporting (during development) to improve GUI performance. Also we use complete GUI lockup detection to prevent data losses by saving application state, reporting the accident to the team and doing preventive application termination. We understand that it's not very good to force application termination, but it's definitely better that forcing users to do it by means of operation system and lose valuable data.

So how we will do the trick?

We need to be able to define:

  • Maximum time the EDT can take to dispatch of single event

  • Action that should be performed when time is exceeded

  • Time-action pairs to have several handlers

  • This should interfere as little as possible with normal dispatching flow. At first, I was thinking about having a separate timer which could be used to trigger actions if not periodically reset. The resetting code should be presented as an event of special flavour and dispatched in scope of EDT. If the EDT gets stuck (or deadlocked) the event isn't dispatched in time and timer triggers notification action. I will show the queue on the picture schematically.
    Event Queue
    WindowEvent
    KeyEvent
    ...
    WatchdogResetEvent
    ...
    WatchdogResetEvent
    The idea is good in general, but has several significant problems:
    1. We load EDT heavily if we don't do pauses between the ends of dispatching our events and additions of them back to the queue.
    2. We can meet the situation when there will be a lot of "short" events and overall time of their dispatching will get over the threshold. Then we will incorrectly detect the overload.
    3. There are many other situations similar to #2 where we will give incorrect results.
    After some thinking I came to conclusion that it is necessary to measure time of single event dispatching and trigger actions when it gets bigger than corresponding maximums. But there was still question how to make that work without affecting normal dispatching process significantly. And then I saw the alternative events queue installation technique described in Issue 007.
    The alternative queue records time of every single event dispatching start and clears it in the end. The setting / resetting of variable with long type is that minimum effect I could only dream. Separate timer thread is populated with tasks for checking the dispatching duration against their own periods and trigger actions associated with them if the dispatching take longer than one period. The idea is very elegant and clean. Here's the implementation:
    import java.awt.*;
    import java.awt.event.*;
    import java.util.*;
    
    /**
     * Alternative events dispatching queue. The benefit over the
     * default Event Dispatch queue is that you can add as many
     * watchdog timers as you need and they will trigger arbitrary
     * actions when processing of single event will take longer than
     * one timer period.
     * <p/>
     * Timers can be of two types:
     * <ul>
     * <li><b>Repetitive</b> - action can be triggered multiple times
     * for the same "lengthy" event dispatching.
     * </li>
     * <li><b>Non-repetitive</b> - action can be triggered only once
     * per event dispatching.</li>
     * </ul>
     * <p/>
     * The queue records time of the event dispatching start.  This
     * time is used by the timers to check if dispatching takes
     * longer than their periods. If so the timers trigger associated
     * actions.
     * <p/>
     * In order to use this queue application should call
     * <code>install()</code> method. This method will create,
     * initialize and register the alternative queue as appropriate.
     * It also will return the instance of the queue for further
     * interactions. Here's an example of how it can be done:
     * <p/>
     * <pre>
     * <p/>
     *  EventQueueWithWD queue = EventQueueWithWD.install();
     *  Action edtOverloadReport = ...;
     * <p/>
     *  // install single-shot wg to report EDT overload after
     *  // 10-seconds timeout
     *  queue.addWatchdog(10000, edtOverloadReport, false);
     * <p/>
     * </pre>
     */
    public class EventQueueWithWD extends EventQueue {
      // Main timer
      private final java.util.Timer timer = new java.util.Timer(true);
    
      // Group of informational fields for describing the event
      private final Object eventChangeLock = new Object();
      private volatile long eventDispatchingStart = -1;
      private volatile AWTEvent event = null;
    
      /**
       * Hidden utility constructor.
       */
      private EventQueueWithWD() { }
    
      /**
       * Install alternative queue.
       *
       * @return instance of queue installed.
       */
      public static EventQueueWithWD install() {
        EventQueue eventQueue =
            Toolkit.getDefaultToolkit().getSystemEventQueue();
        EventQueueWithWD newEventQueue = new EventQueueWithWD();
        eventQueue.push(newEventQueue);
        return newEventQueue;
      }
    
      /**
       * Record the event and continue with usual dispatching.
       *
       * @param anEvent event to dispatch.
       */
      protected void dispatchEvent(AWTEvent anEvent) {
        setEventDispatchingStart(anEvent, System.currentTimeMillis());
        super.dispatchEvent(anEvent);
        setEventDispatchingStart(null, -1);
      }
    
      /**
       * Register event and dispatching start time.
       *
       * @param anEvent   event.
       * @param timestamp dispatching start time.
       */
      private void setEventDispatchingStart(AWTEvent anEvent,
                                            long timestamp) {
        synchronized (eventChangeLock) {
          event = anEvent;
          eventDispatchingStart = timestamp;
        }
      }
    
      /**
       * Add watchdog timer. Timer will trigger <code>listener</code>
       * if the queue dispatching event longer than specified
       * <code>maxProcessingTime</code>. If the timer is
       * <code>repetitive</code> then it will trigger additional
       * events if the processing 2x, 3x and further longer than
       * <code>maxProcessingTime</code>.
       *
       * @param maxProcessingTime maximum processing time.
       * @param listener          listener for events. The listener
       *                          will receive <code>AWTEvent</code>
       *                          as source of event.
       * @param repetitive        TRUE to trigger consequent events
       *                          for 2x, 3x and further periods.
       */
      public void addWatchdog(long maxProcessingTime,
                              ActionListener listener,
                              boolean repetitive) {
        Watchdog checker = new Watchdog(maxProcessingTime, listener,
            repetitive);
        timer.schedule(checker, maxProcessingTime,
            maxProcessingTime);
      }
    
      /**
       * Checks if the processing of the event is longer than the
       * specified <code>maxProcessingTime</code>. If so then
       * listener is notified.
       */
      private class Watchdog extends TimerTask {
        // Settings
        private final long maxProcessingTime;
        private final ActionListener listener;
        private final boolean repetitive;
    
        // Event reported as "lengthy" for the last time. Used to
        // prevent repetitive behaviour in non-repeatitive timers.
        private AWTEvent lastReportedEvent = null;
    
        /**
         * Creates timer.
         *
         * @param maxProcessingTime maximum event processing time
         *                           before listener is notified.
         * @param listener          listener to notify.
         * @param repetitive       TRUE to allow consequent
         *                           notifications for the same event
         */
        private Watchdog(long maxProcessingTime,
                        ActionListener listener,
                        boolean repetitive) {
          if (listener == null)
            throw new IllegalArgumentException(
                "Listener cannot be null.");
          if (maxProcessingTime < 0)
            throw new IllegalArgumentException(
              "Max locking period should be greater than zero");
          this.maxProcessingTime = maxProcessingTime;
          this.listener = listener;
          this.repetitive = repetitive;
        }
    
        public void run() {
          long time;
          AWTEvent currentEvent;
    
          // Get current event requisites
          synchronized (eventChangeLock) {
            time = eventDispatchingStart;
            currentEvent = event;
          }
    
          long currentTime = System.currentTimeMillis();
    
          // Check if event is being processed longer than allowed
          if (time != -1 && (currentTime - time > maxProcessingTime) &&
              (repetitive || currentEvent != lastReportedEvent)) {
            listener.actionPerformed(
                new ActionEvent(currentEvent, -1, null));
            lastReportedEvent = currentEvent;
          }
        }
      }
    }
      
    As you could see the code is also straight-forward and elegant. You install the queue and register any number of timers you need and they will do the excellent job for you. Below an example code showing how the queue can be used to detect and report overloads. One great thing about timer task implementation is that it returns the event which is being dispatched for too long in the source field of ActionEvent passed to triggered action. The handler can use it to make a good report about problem.
    import javax.swing.*;
    import java.awt.*;
    import java.awt.event.ActionEvent;
    import java.util.Date;
    
    /**
     * Sample usage of <code>EventQueueWithWD</code> class.
     */
    public class SampleEQUsage extends JFrame {
      public SampleEQUsage() {
        super("Sample EQ Usage");
        setDefaultCloseOperation(EXIT_ON_CLOSE);
    
        getContentPane().add(new JButton(new AbstractAction("Go") {
          public void actionPerformed(ActionEvent e) {
            System.out.println();
            System.out.println(new Date());
            try {
              // Sleep for 10 seconds
              Thread.sleep(10000);
            } catch (InterruptedException e1) {
            }
          }
        }));
    
        setSize(100, 100);
      }
    
      public static void main(String[] args) {
        initQueue();
    
        SampleEQUsage sequ = new SampleEQUsage();
        sequ.setVisible(true);
      }
    
      // Install and init the alternative queue
      private static void initQueue() {
        EventQueueWithWD queue = EventQueueWithWD.install();
    
        // Install 3-seconds single-shot watchdog timer
        queue.addWatchdog(3000, new AbstractAction() {
          public void actionPerformed(ActionEvent e) {
            System.out.println(new Date() + " 3 seconds - single-shot");
          }
        }, false);
    
        // Install 3-seconds multi-shot watchdog timer
        queue.addWatchdog(3000, new AbstractAction() {
          public void actionPerformed(ActionEvent e) {
            System.out.println(new Date() + " 3 seconds - multi-shot");
          }
        }, true);
    
        // Install 11-seconds multi-shot watchdog timer
        queue.addWatchdog(11000, new AbstractAction() {
          public void actionPerformed(ActionEvent e) {
            System.out.println(new Date() + " 11 seconds - multi-shot");
          }
        }, true);
      }
    }
      
    This code creates a single frame with Go button. By pressing it you freeze the GUI for 10 seconds. There are 3 watchdog timers installed by initQueue() method. The messages printed explain their nature pretty well. Pressing the button 3 times produces the following output for me (your output will be different):
    Tue Feb 08 16:09:57 CAT 2005
        Tue Feb 08 16:10:01 CAT 2005 3 seconds - multi-shot
        Tue Feb 08 16:10:01 CAT 2005 3 seconds - single-shot
        Tue Feb 08 16:10:04 CAT 2005 3 seconds - multi-shot
      
    I think that I don't need to explain why we can have only two 3-second multi-shots (as in second and third packages). ;-)
    So, now you can use this new opportunities to catch your junior developers doing their math in application EDT. :)
    See you soon!

    created by Aleksey Gureev

    0 komentar:

    Posting Komentar

    Twitter Delicious Facebook Digg Stumbleupon Favorites More

     
    This Theme Modified by Kapten Andre based on Structure Theme from MIT-style License by Jason J. Jaeger