The JIT that was too smart...

I spent quite a few hours this week tracking down a subtle performance drop that happened when I rewrote some code. This code is just a wrapper around the real code, yet I was seeing a 10-20% performance drop! I popped up the profiler and took a peek. I then scratched my head, looked at the code. Repeat a few dozen times.

The code basically looked like this:

main() {
  driver.setTest(test);
  run-a-few-seconds {
    driver.warmup();
  }
  run-a-bit-longer {
    driver.run();
  }
}

class Driver {
  Test _test;

  public void warmup() { warmup(_test); }
  public void run() { run(_test); }

  public abstract void warmup(Test test);
  public abstract void run(Test test);
}

class MyDriver extends Driver {
  public void warmup(Test test) { run(test); }
  public void run(Test test) { do-something-hard(); }
}

You want to know what change regained that 10-20%? The above code is really all that matters... Let me tell you what the profiler showed me first.

I ran a profiler over both the old code and the new code and compared the results. The only noticable change was that warmup() was called dramatically less times on the old code, and took up more of the profile. Everything else was just noise. I've looked at a lot of profile traces and this one baffled me. Lucky for me, I only figuratively 'scratch my head' when pondering such problems, or else this one would have seriously left my poor noggin rather raw. I've never seen anything like this. The code was almost identical!

So I started iterating over all the ways that the code was different. There was also lots of setup code and other framework code that I don't show above (because it turns out not to matter).

After thinking about it out loud (lucky for me Rich was willing to sit and listen to me rant about this a few times) I came to the conclusion that the issue was the JIT. The setup was Java code and Sun's latest 1.5 jvm. To test this, I removed the warmup look, and sure enough, the older, faster times, fell back to the new, slower levels! So what could possibly be different between the two code bases to account for this?

class MyDriver extends Driver {
  public void warmup(Test test) { run(test); }
  public void run(Test test) { do-something-hard(); }
}

replace that with the below and that 10-20% regression went away.

  public void warmup(Test test) { run(); }

I'll admit that I tried that change in a fit of despiration. A minor change like that couldn't have that kind of impact, could it? But it did.

My theory? The main loop, and the Driver class are in one jar, while MyDriver is from a different jar (that was loaded by a custom class loader). It might be that because of inlining the call to do-something-hard() seemed to occur in a different context, which forced a reJIT.

Either way, fancy HotSpot(tm) JIT 'intelligence' cost me a few hours for something that just doesn't seem like it should matter. It makes me miss good old-fashion compilers.