Debugging unresponsive Java GUI applications

Posted on June 25, 2011. Filed under: Uncategorized | Tags: , , , , , , , , |

You probably heard about it: one should not run time-consuming operations on the event dispatch thread in Java GUI applications but use SwingWorker instead to run lengthy tasks, possibly showing a dialog box once the task is completed. One typical case of running tasks on the event dispatch thread is in a callback to the user’s action such as pressing a button or selecting a menu item from a pop-up menu.

I’m working on an application which runs external commands very often and the running time of such commands can be several minutes. Wherever possible, commands are run only on demand and the states of the objects in the application are updated according to the command’s output. While care was taken to use SwingWorker in obvious places the application still became unresponsive (i.e. the windows were not repainted for minutes) because the event dispatching thread was waiting to lock an object which was locked by another thread running a lengthy task (an external command in this case). In the following I describe how I found such locks with the standard Java debugger.

Starting the program and the debugger

The application I was working on was packaged into a single .jar file. So instead of starting the program with

java -jar myapp.jar

I started the Java virtual machine and my application and made them listen to connections from a debugger:

java -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=localhost:10101 -jar myapp.jar

This instructs the Java virtual machine to bind to socket 10101 on localhost to listen to a connection from jdb. The suspend=n part instructs it to start program execution immediately.

WARNING: as far as I understood is there no authentication involved when connecting with jdb (at least not when running it as described above). In other words: all users having access to this machine can also connect to the process you are debugging and control it !

On a second console, I started the Java debugger:

jdb -attach localhost:10101

The command help on the debugger console will give a short list of all commands understood by jdb.

Finding the locks

I waited until the GUI froze. At that point, I did:

suspend

to suspend all threads. I got a quick overview of the state of all threads by using the command threads:

Group system:
  (java.lang.ref.Reference$ReferenceHandler)0x832 Reference Handler           cond. waiting
  (java.lang.ref.Finalizer$FinalizerThread)0x831  Finalizer                   cond. waiting
  (java.lang.Thread)0x830                         Signal Dispatcher           running
  (java.lang.Thread)0x82f                         Java2D Disposer             cond. waiting
  (java.lang.Thread)0x901                         TimerQueue                  cond. waiting
Group main:
  (java.lang.Thread)0x82e                         AWT-XAWT                    running
  (java.lang.Thread)0x82d                         AWT-Shutdown                cond. waiting
  (java.awt.EventDispatchThread)0x82c             AWT-EventQueue-0            waiting in a monitor
  (java.lang.Thread)0x82b                         pool-2-thread-1             cond. waiting
  (java.lang.Thread)0x82a                         pool-1-thread-1             cond. waiting
  (java.lang.Thread)0x829                         pool-1-thread-2             cond. waiting
  (java.lang.Thread)0x828                         pool-1-thread-3             cond. waiting
  (java.lang.Thread)0x827                         pool-1-thread-4             cond. waiting
  (java.lang.Thread)0x826                         pool-1-thread-5             cond. waiting
  (java.lang.Thread)0x825                         pool-1-thread-6             cond. waiting
  (java.lang.Thread)0x824                         pool-1-thread-7             cond. waiting
  (java.lang.Thread)0x823                         pool-1-thread-8             cond. waiting
  (java.lang.Thread)0x8db                         DestroyJavaVM               running
  (java.lang.Thread)0x9cd                         SwingWorker-pool-3-thread-1 cond. waiting
  (java.lang.Thread)0x9d6                         SwingWorker-pool-3-thread-2 waiting in a monitor
  (java.lang.Thread)0x9d8                         SwingWorker-pool-3-thread-3 cond. waiting
  (java.lang.UNIXProcess$1$1)0x9d9                process reaper              running
  (java.lang.Thread)0x9da                         SwingWorker-pool-3-thread-4 waiting in a monitor
  (java.lang.Thread)0x9db                         SwingWorker-pool-3-thread-5 waiting in a monitor
  (java.lang.Thread)0x9dc                         SwingWorker-pool-3-thread-6 waiting in a monitor
  (java.lang.Thread)0x9dd                         SwingWorker-pool-3-thread-7 cond. waiting
  (java.lang.UNIXProcess$1$1)0x9de                process reaper              running
  (java.lang.Thread)0x9df                         SwingWorker-pool-3-thread-8 cond. waiting
  (java.lang.UNIXProcess$1$1)0x9e0                process reaper              running
  (java.lang.UNIXProcess$1$1)0x9e1                process reaper              running

The important thing to note is the line:

  (java.awt.EventDispatchThread)0x82c             AWT-EventQueue-0            waiting in a monitor

Which means that the event dispatch thread is actually waiting to obtain a lock on an object — but which one ? First of all, I wanted to know where (in the source code) the thread was waiting. I could print the stack trace of this thread by doing:

where 0x82c

(0x82c is the thread id obtained from the above output). This gave me something like:

[1] MyTableModel.getValueAt (MyTableModel.java:136)
[2] javax.swing.JTable.getValueAt (JTable.java:2,686)
[3] javax.swing.JTable.prepareRenderer (JTable.java:5,703)
...

So indeed, the thread was stuck somewhere in my code. Looking at the corresponding line of source code, I had to go up a few lines to find the variable (the field myList of the class MyTableModel) in the synchronized statement which I was locking on.

However, I needed also to find out which other thread currently holds the lock on this variable in order to solve the problem. I could do this by doing running the following command in jdb:

lock this.myList

(where the jdb prompt showed me that the current thread was AWT-EventQueue0 because of the previous commands and the current stack frame was 1, so no need to set the current thread or stack frame). The output of the above command was:

com.sun.tools.example.debug.expr.ParseException: Unable to complete expression. Thread not suspended for method invoke
Owned by: SwingWorker-pool-3-thread-1, entry count: 1
Waiting thread: SwingWorker-pool-3-thread-2
Waiting thread: AWT-EventQueue-0

again, from the output of the threads command (see above) I could find the thread id of the thread SwingWorker-pool-3-thread-1 which owned the lock on myList. A quick

where 0x9cd

revealed that indeed the lock on myList was held by a thread which was waiting for an external command to complete:

[1] java.lang.Object.wait (native method)
[2] java.lang.Object.wait (Object.java:485)
[3] java.lang.UNIXProcess.waitFor (UNIXProcess.java:165)
[4] Utils.runCommand (Utils.java:102)
...

and I could also easily find the synchronized statement which acquired the lock on myList.

Advertisements

Make a Comment

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

One Response to “Debugging unresponsive Java GUI applications”

RSS Feed for Andre Holzner's Blog Comments RSS Feed

An alternative would be using the JVisualVM.
But nevertheless a good post


Where's The Comment Form?

Liked it here?
Why not try sites on the blogroll...

%d bloggers like this: