EDT Lockup Detection

2005-02-13 The Java Specialists' Newsletter [Issue 104] - EDT Lockup Detection

Author: Aleksey Gureev

If you are reading this, and have not subscribed, please consider doing it now by going to our subscribe page. You can subscribe either via email or RSS.

Welcome to the 104th edition of The Java(tm) Specialists' Newsletter, now sent to 108 countries! Our latest addition is Cyprus, a hotly disputed island in the Mediterranean Sea. Apparently, the Greek dialect spoken there is the most similar to what Ancient Greek would have been.

I own three laptops. My first one was an Asus, then a Toshiba and for the last year I have worked on a Dell D800. Living down here in beautiful South Africa does have some disadvantages. I once had to wait 6 weeks for a broken DVD-Rom to be replaced! However, not so with my Dell! I want to thank Russel D'Souza for the excellent service with my Dell. On Monday, whilst I was presenting the new course on Java 5 in Johannesburg, 1200km away from Cape Town, the Page Down key popped off and refused to stay attached. I phoned Dell, and the next day before lunchtime, someone from Dell had come to where I was presenting the course, and had swapped out the entire keyboard!

Java 5 - Letting the Tiger out of the cage, will teach you the new features of Tiger, and how to use them. We have not planned any open courses, but will initially be focusing solely on corporates that want to train their staff in the new technology. There is a limit to how much travelling and training I can do, and so I am accepting engagements on a First-Come-First-Serve basis. Since this is a new course, I am holding prices low, so please give me a shout as soon as possible if you are interested :)

This week I am honoured to welcome a new author to our newsletter. Aleksey Gureev has been publishing Russian Java newsletters. He has been a Java fan since Java 1.2. He lives in Crimea in the Ukraine and is a member of the BlogBridge development team. This newsletter therefore first appeared in Russian, so Thank You Aleksey for translating this newsletter for us. Enough from me, let's go over to this excellent idea of Aleksey's:

EDT Lockup Detection

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.

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!

Aleksey Gureev
[nozieramp] Creative Group
http://www.noizeramp.com

This material from The Java(tm) Specialists' Newsletter by Maximum Solutions (South Africa). Please contact Maximum Solutions for more information.