Debugging unresponsive Java GUI applications
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.
Read Full Post | Make a Comment ( 1 so far )
Andre Holzner's Blog 