Bruce Chapman's Blog

Hot Threads

I'm setting up my new desktop development machine, and netbeans installation is atrociously slow, like several minutes just to display the splash screen. The task manager shows the process consuming 50% CPU (on a dual core). After stuffing around barking up several wrong trees I drag out a JMX based tool I wrote a while back to find hot threads in a running application.

I had previously encountered slow startup with Netbeans 5.5 (itself - not the installer) and based on A. Sundararajan's blog Using Mustang's Attach API I had written a tool to output the stack traces for the three busiest threads in a java process.

Here's the source code. And for those that just need to do the same thing without understanding internals, Download the jar file

The program attaches to the local java process (specified by the PID on the command line), it grabs information about the processing time of all threads, twice 500ms apart, and uses that to find the three busiest threads. It then takes 10 stacktrace snapshots of those three threads at 10ms intervals, and looks for the common parts on those stack traces for each thread. If a thread is busy, normally most of the stack stays the same, and just the top part changes. The program then outputs to common parts of the stack traces. From there you can see which thread is running hot, and where it is.

So I enabled PID display in the Window's task Manager and ran the program. Here's what I saw...

C:\>java -jar C:\projects\experimental\HotThread\dist\HotThread.jar 3544
java.lang.UnsatisfiedLinkError: no attach in java.library.path
Exception in thread "main" com.sun.tools.attach.AttachNotSupportedException: no
        at com.sun.tools.attach.VirtualMachine.attach(VirtualMachine.java:190)
        at hotthread.Main.main(Main.java:52)

That was due to java's installation running the JRE's copy of java.exe, but it doesn't have some of the attach API support files, so you need to run the JDK version of java.exe. Trying again...

C:\>"C:\Program Files\Java\jdk1.6.0_05\bin\java.exe"  -jar C:\projects\experimental\HotThread\dist\HotThread.jar 3544
106.3% CPU Usage by Thread 'Swing-Shell'
  10/10 snapshots sharing following 10 elements
    sun.awt.shell.Win32ShellFolder2.getAttributes0(Native Method)
    sun.awt.shell.Win32ShellFolder2.access$600(Unknown Source)
    sun.awt.shell.Win32ShellFolder2$6.call(Unknown Source)
    sun.awt.shell.Win32ShellFolder2$6.call(Unknown Source)
    java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source)
    java.util.concurrent.FutureTask.run(Unknown Source)
    java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
    java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    sun.awt.shell.Win32ShellFolderManager2$ComInvoker$3.run(Unknown Source)
    java.lang.Thread.run(Unknown Source)

 1.6% CPU Usage by Thread 'RMI TCP Connection(9)-172.30.41.210'
  10/10 snapshots sharing following 32 elements
    sun.management.ThreadImpl.getThreadInfo0(Native Method)
    sun.management.ThreadImpl.getThreadInfo(Unknown Source)
    sun.reflect.GeneratedMethodAccessor106.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    java.lang.reflect.Method.invoke(Unknown Source)
    com.sun.jmx.mbeanserver.ConvertingMethod.invokeWithOpenReturn(Unknown Source)
    com.sun.jmx.mbeanserver.MXBeanIntrospector.invokeM2(Unknown Source)
    com.sun.jmx.mbeanserver.MXBeanIntrospector.invokeM2(Unknown Source)
    com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(Unknown Source)
    com.sun.jmx.mbeanserver.PerInterface.invoke(Unknown Source)
    com.sun.jmx.mbeanserver.MBeanSupport.invoke(Unknown Source)
    javax.management.StandardMBean.invoke(Unknown Source)
    com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source)
    com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source)
    javax.management.remote.rmi.RMIConnectionImpl.doOperation(Unknown Source)
    javax.management.remote.rmi.RMIConnectionImpl.access$200(Unknown Source)
    javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(Unknown Source)
    javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(Unknown Source)
    javax.management.remote.rmi.RMIConnectionImpl.invoke(Unknown Source)
    sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
    sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    java.lang.reflect.Method.invoke(Unknown Source)
    sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)
    sun.rmi.transport.Transport$1.run(Unknown Source)
    java.security.AccessController.doPrivileged(Native Method)
    sun.rmi.transport.Transport.serviceCall(Unknown Source)
    sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
    sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
    sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
    java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
    java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    java.lang.Thread.run(Unknown Source)

 0.0% CPU Usage by Thread 'Reference Handler'
  10/10 snapshots sharing following 3 elements
    java.lang.Object.wait(Native Method)
    java.lang.Object.wait(Object.java:485)
    java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)

So armed with this information, a quick search of the JDK bug database looking for "sun.awt.shell.Win32ShellFolder2" yields Bug ID: 5033747 JFileChooser is very slow on Windows XP but that is about JFileChooser which doesn't seem related to my problem, however the stack trace matches. One of the related bugs is Bug ID: 5050516 JFileChooser very slow in XP if directory contains large zip files and a light turns on. I have some big zip files on my desktop temporarily while I set things up. In that bug it shows how to disable XP's feature of treating zip files as directories which seems like it might be the root cause.

So I disabled XP's horrible ZIP file handling (which would be marvellous if it wasn't so pathetically slow), and ... Drum roll ... netbeans was installed in a couple of minutes.

Thank you JMX. Maybe a hot thread detector would be useful in jconsole and visualVM.

Comments

• Should this work on a linux system?

  [joebob@xyz ~]$ /usr/java/jdk1.6.0_03/bin/java -jar /root/hotthread.jar 26954                                                      
  Exception in thread "main" java.lang.NoClassDefFoundError: com/sun/tools/attach/VirtualMachine
          at hotthread.Main.main(Main.java:52)
  

  Is there something else I need to install?

  Posted by: stevefeinstein on May 08, 2008 at 12:35 PM

• I got further today and also wrote about it at Javalobby: http://java.dzone.com/news/porting-hot-thread-detector-vi

  Posted by: geertjan on April 03, 2008 at 02:02 PM

• For jconsole there is the JTop plugin: http://weblogs.java.net/blog/mandychung/archive/2006/05/mustang_jconsol_1.html

  Thanks for the link, but JTop seems pretty crappy. First it has a really basic bug so only whole seconds are shown, then it shows the total accumulated CPU use (whole seconds with ".0000" appended) for each thread, whereas what people are interested in is how much it is currently using (but thats not possible so how much in the most recent sample period is an acceptable approximation), shown as a percentage of the total in such situations to make it easily understandable. - Bruce

  Posted by: mgoe on March 27, 2008 at 01:40 AM

• VisualVM already has a threads window but I played with your code and did a very rough first draft plugin, based on porting your code to a VisualVM plugin which I then installed in VisualVM Beta. I will work on it some more to make it more graphical: http://blogs.sun.com/geertjan/resource/hot-threads.png

  Posted by: geertjan on March 26, 2008 at 04:23 PM

This work is licensed under a Creative Commons License.