Platinum Partner
java,netbeans,visualvm,dtrace,profiler,btrace

Using VisualVM, BTrace & Good Old Web Search

The story starts with my pattern of being off the grid half of each day. This really lets me appreciate a good battery and, while my Mac battery is pretty decent, I can literally feel it drain while doing hard Java work with NetBeans IDE, Maven, and big recompiles.

Now, while battery depletion under heavy load is perfectly normal, it does force you to keep a keen eye on CPU usage in the OSX Activity Monitor. That's how I noticed that while idle, NetBeans IDE was taking about 16% of my CPU... doing nothing really.

The first thing I wanted to know was what was going on in there? So I took VisualVM, connected it to the NetBeans IDE instance, and forced a Thread Dump:

VisualVM Threads tab and Thread dump button

This basically is a list of stack traces for all the threads, so that you can see the application's current state of execution. In my case, I probably didn't press the button at the right time, since I caught the threads all in a WAITING state, meaning that not much CPU should have been used: 

VisualVM Thread dump list

Well, since the thread dump is just a quick snapshot, it was clear that I wasn't going to get a good view of what was consuming CPU, so I went to the heavy weight option: CPU Profiling.

Getting this started is quite easy on the VisualVM side, but it takes forever to actually start gathering data. The reason is the bytecode instrumentation that is done for a lot of the NetBeans IDE classes by the Profiler. This means that if VisualVM complains that the application isn't responding and suggests to stop profiling, you'll need to answer "No" and let it do its thing:

VisualVM Profiler tab

Well, with a little patience I could see data coming in. Pretty soon I noticed at the top of the list two classes that shouldn't have been there:

org.netbeans.core.TimableEventQueue.postEvent with 31.3%
apple.laf.CUIAquaProgressBar$Animator.actionPerformed with 25.1%
org.netbeans.core.TimableEventQueue.dispatchEvent with 5%

So, it looked like the EventQueue (well, the one used by NetBeans IDE anyhow) was being really busy this whole time calling an OSX-specific ProgressBar animator class. The only thing was -- there was no progress bar on the screen! Actually, the whole NetBeans IDE was hidden away... so Swing should have been really quiet.

Well, it started looking as if we had some sort of "leak" here, i.e., some object that clearly isn't being disposed properly. I instantly thought that the culprit might be some class inside the NetBeans Progress API/UI, since this is the module that shows that little progress component in the lower-right corner of the main window. This was just a hunch, though, since I know a bit about the internals of NetBeans IDE, but I had no way to prove it yet or, more importantly, to fix it.

I returned to VisualVM knowing what classes to look for and I requested a heap dump. This is a snapshot of the applications' memory at that point. I went into the Classes tab and I searched for our CUIAquaProgressBar$Animator class:

VisualVM Heap dump

 

Now my reasoning was to find some JProgressBar reference and, sure enough, using the Fields area in the Instances tab I found a link to the progress bar:

VisualVM Heapdump reference

 

OK, so indeed we have some wild JProgressBars being called, more to the point NbProgressBars. We are actually getting somewhere now!

At this point I still didn't know what exactly was going on, but it had to do with the NbProgressBar class. So I downloaded a new tool, btrace, and started writing a new btrace script using their online tutorial.

You can think of btrace as a scriptable debugger: you set breakpoints and when your breakpoints are hit some little script gets executed.

First, I wanted to see the animator calls. Those were on the actionPerformed method, resulting in this annotation for a btrace method:

@OnMethod(clazz="apple.laf.CUIAquaProgressBar$Animator",
method="actionPerformed")

I also needed the object itself, so I used the @Self annotation to get it from btrace:

public static void lnfaction(@Self Object animator)

Now, from the heap dump analysis above I knew that I had a reference to the progress bar here, so I used a bit of reflection to get to it:

println( strcat(strcat(str(timeNanos()), " : animator called "),str(animator)));
Field f =  field("apple.laf.CUIAquaProgressBar$Animator", "this$0");
/*apple.laf.CUIAquaProgressBar*/ Object pbar = get(f,animator);
println(pbar);

Field f2 = field("apple.laf.CUIAquaProgressBar", "progressBar");
/*org.netbeans.modules.progress.ui.NbProgressBar*/ Object swingbar = get(f2, pbar);
println(swingbar);

Note how limited you are while writing the script... no method calls are actually allowed except those from com.sun.btrace.BTraceUtils (which are statically imported). Even string concatenation has to be explicit, using BTraceUtils.strcat! Yet, it gives you enough options to progress quite nicely.

Next, I compiled the script using btracec Script.java, then I executed it with btrace $PID Script.class where $PID is the actual numeric process ID (for example 2377). The execution prints a lot of debugging info and I found out that I have some instances that look like this:

org.netbeans.modules.progress.ui.NbProgressBar@48aa00ec

What I care about now is detecting where those instances are created. Of course, I'll need to restart the application to detect when that happens and start the agent as soon as possible.

NOTE: I did this step manually by having the commands ready in the terminal, but presumably you could attach a btrace agent from the start to the IDE and run that script. This didn't work for me and I didn't bother checking it out.

Finding the stacktrace for the constructor is just a matter of another script method and BTraceUtils.jstack():

@OnMethod(clazz="org.netbeans.modules.progress.ui.NbProgressBar",
method="<init>")
public static void instantiate(@Self Object o ){
println(strcat("Instantiated org.netbeans.modules.progress.ui.NbProgressBar: ",str(o)));
jstack();
println("----");
}

And this is where we strike gold! The two common stacktraces are:

org.netbeans.modules.progress.ui.StatusLineComponent.createBar(StatusLineComponent.java:170)
org.netbeans.modules.progress.ui.StatusLineComponent.initiateComponent(StatusLineComponent.java:377)
org.netbeans.modules.progress.ui.StatusLineComponent.processSelectedProgressEvent(StatusLineComponent.java:329)
org.netbeans.progress.module.Controller.run(Controller.java:337)
java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:209)
java.awt.EventQueue.dispatchEvent(EventQueue.java:597)
java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:300)
java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:210)
java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:200)
java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:195)
java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:187)
java.awt.EventDispatchThread.run(EventDispatchThread.java:121)

and

org.netbeans.modules.progress.ui.ListComponent.<init>(ListComponent.java:105)
org.netbeans.modules.progress.ui.StatusLineComponent.createListItem(StatusLineComponent.java:439)
org.netbeans.modules.progress.ui.StatusLineComponent.processProgressEvent(StatusLineComponent.java:290)
org.netbeans.progress.module.Controller.run(Controller.java:339)
java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:209)
java.awt.EventQueue.dispatchEvent(EventQueue.java:597)
java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:300)
java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:210)
java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:200)
java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:195)
java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:187)
java.awt.EventDispatchThread.run(EventDispatchThread.java:121)

In other words, our 'leaky' instances are here:

org.netbeans.modules.progress.ui.StatusLineComponent.createBar

org.netbeans.modules.progress.ui.ListComponent

What I still hadn't figured out is what's causing the animator to continue being called. This is where I resorted to good old Google search and typed "apple.laf.CUIAquaProgressBar$Animator". It's a very uncommon request since I just got 7 items, and the 4th one was an IDEA bugreport. They were complaining about the same thing! And one of the posters there found a workaround... just uninstall the UI.

progress.getUI().uninstallUI(progress) seems to be the magic line.

With this new knowledge, I looked into the two targeted classes, to find out where the ProgressBar is released. Sure enough, one of them has a discardBar method, while the other will need an additional method. I patch the methods, change the btrace script to double-check those methods too, and rebuild NetBeans IDE.

NOTE: This is the only downside until now. While investigating this was done directly on the IDE binaries, patching it required the source code.

That was it. Running the btrace script with the patched classes showed that the OSX animator class isn't called anymore! While this wasn't a bug per-se in the IDE, more like an OSX JDK issue, the workaround did reduce my CPU usage!

After cleaning up the patch, I'm ready to submit it to NetBeans for inclusion. In a surprisingly fast fashion, my bug report was accepted and included in about 1 hour 30 minutes. I guess marking it as a P2 priority sped things up a little.

If you found this article interesting and appreciate your better battery this patch brought into your life, feel free to send your spare battery my way... it will be put to good (ab)use.

{{ tag }}, {{tag}},

{{ parent.title || parent.header.title}}

{{ parent.tldr }}

{{ parent.urlSource.name }}
{{ parent.authors[0].realName || parent.author}}

{{ parent.authors[0].tagline || parent.tagline }}

{{ parent.views }} ViewsClicks
Tweet

{{parent.nComments}}