Josh On Design

AKA: a Teachable Moment in Performance Tests, Profilers, and Debugging statements.

The other night I couldn't sleep, so I started to write some code. Most great programming insights begin like this. I added some new CSS selector types to the Amino skinning parser, then went to bed. A couple of days later I noticed Leonardo, the drawing program built on Amino, was running visibly slower. Clearly I had screwed something up with my recent changes. Time to put on the work boots and dig in.

It has been said: the only way to make your code faster is to never let it get slower. And the only way to do that is to create performance tests that you can run on both the old and new versions of your code. Fortunately I started adding configurable tests a month ago, letting me run a layout test on any revision I choose and compare it to any other revision. By running the test on the last several versions I could narrow down exactly which commit had caused the problem. Easy enough. Now I can fix the problem. Or so I thought...

Once isolated, I quickly deduced my CSS evaluator was doing extra work looking for parent nodes that don't matter in most cases. I simply commented out the extra function, then ran the performance test again. Hmm. It's still slow! But I turned off all of the functional changes, right?

After analyzing this code for two hours I gave up doing it by hand and pulled out a real profiler. Never guess where you think code is slow. Use a real tool. Fortunately the VisualVM tools, built on the excellent NetBeans RCP, is easy to use and built into all modern Sun derived JVMs. I launched it with jvisualvm on my Mac, installed the VisualVM-Sampler plugin to get NB style per method profiling, then was off to the races. It seems that 90% of the time was being spent in string concatenation from a couple of debugging lines inside of nested loops. Here's an example:

p("current match is " + match);

The odd thing is that p() is a no-op! It looks like this:

public static void p(String s) { if(DEBUG) System.out.println(s);}

and DEBUG was set to false. How could this code be causing the problem?

I commented out the p() lines and confirmed that they were the root cause, but why were they slow when they didn't do anything? After a bit of puzzling I finally figured it out.

The key is the '+ match' part. The compiler turns + match into + match.toString(). I had recently modified match to dump a ton of debugging information in it's toString() method. Even though p() wouldn't do anything with this info, the toString() method is still called. Only commenting out the lines completely removed the excess work and the performance problem was solved.

The lesson? First: always profile your code to find the real hot spots, using something like VisualVM. And second: have flexible performance tests to find regressions. Without a test I could run on any Mercurial revision it would have taken far longer to find the bad commit.

The upshot of this exercise is that Amino and Leonardo are now visibly at least twice as fast as before! Go Java Tools!