Skip to main content

When Commented Out Code Attacks

Posted by joshy on November 5, 2010 at 2:56 PM PDT

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!

Related Topics >>

Comments

When Commented Out Code

Another thing to consider is SLF4J. Its logging methods have variations like:
logger.debug("result: {}", val);
logger.debug("results {} {} {}", val1, val2, val3);
logger.debug("results: color={} x={} y={} alpha={} radius={} ", vals[]);
These avoid the concatenation problem you're talking about. The SLF4J web site has the details.
-Jim

Jim, It seems that you are

Jim,

It seems that you are trading one memory allocation issue for another: methods with variable arguments list will create temporal array at call site.
And it would be just wasted memory if debug is disabled

VS

That's a great point, but

That's a great point, but thankfully the designer of SLF4J (same as Log4J IIRC) is smart. He built that api with a bunch of variants of the logging methods, none of which uses varargs.

When Commented Out Code

Thanks for the info Josh.
I think you are right overall.
I had some debug type code that executed many println statements in a loop that used a function to return a string and this messed up my program. The thing is that it returned a very simple string, nothing involved at all, just a few characters at a time. It did it many times though. The problem it caused did not result in any slowdown of the program, but caused a Swing text component to inexplicably stop displaying text results that were part of the execution involved that called the loop in the first place. At first everything was running fine, then almost randomly the program started misbehaving. Stopping and restarting the JVM had no effect after that point, even though the code had run properly for some undetermined amount of time before!
Seems that at some point all these concatenations of string objects mess up some part of the JVM in terms of memory or other resources when taken too far. Printing to the console is already a known resource hog, relatively speaking. So this is not surprising, but it is hard at first to find out why when all you are doing is spitting out a "little" text.

third, use scala and by-name

third, use scala and by-name parameter

Another lesson would be to

Another lesson would be to consider a lazy evaluated language :-) Haskell anyone?