The Mystery of the Slow First Run

The causes for performance issues can be found in the strangest places. This simple fact was proven again recently, when we analyzed an issue, a customer had reported to us. A servlet using our formatting processor PDFreactor was running fine in their Bea Oracle Weblogic 10.0 servers except for the fact that the first run after deploying took multiple minutes, which was slower than expected by a factor of 60 (“sixty”). Later runs performed normally, taking only split seconds.

We immediately were able to reproduce the issue in a newly installed Weblogic server. Switching from Bea Oracle JRockit to Sun Oracle Hotspot made no difference. Curiously the logs showed that it was not just a certain part of the conversion process hanging, but many separate steps performing exceptionally slow. So we set up an environment for profiling PDFreactor running inside the servlet in Weblogic using JProfiler. However, when we ran the profiling session the performance issue did no longer occur. So we disabled the profiler to make sure it doesn’t influence the Java VM in a way that somehow solves the issue. But the first run still finished in seconds. We were not able to reproduce the issue anymore. So instead of profiling we had to do some detective work to solve this mystery.

Now, as it turned out, there was one little difference between our first tests and the profiling session. At first we used the release version of PDFreactor, then we switched to a special version for debugging and profiling which is different in one important way: It is not obfuscated.

An analysis of both jar-files as well as the settings of the obfuscator we use - yGuard - pointed us into the right direction. digestsIt turned out that, by default yGuard writes both MD5 and SHA-1-digests of all classes into the manifest, even though the jar is not signed. Its documentation does not explain exactly why it is doing this. In fact, it only mentions it in the description of the settings that we had to modify to disable this behavior. Coincidently Weblogic also has a behavior that we were not aware of. When digests are present in the manifest, it uses them to validate each class it loads from the jar. Considering PDFreactor consists of 10.000+ classes, this explained the huge overhead on the first run. And indeed, removing the digests from the manifest solved the issue completely, reducing the time required for the first run to about 4 seconds.

I guess the morale of the story is, that by far not all performance issues are caused by inefficient code or badly configured environments. It can also be the result of the interplay between two seemingly unrelated components like the yGuard obfuscator and the Weblogic application server.

  • Facebook
  • Twitter
  • Delicious
  • Digg
  • StumbleUpon
  • Add to favorites
  • Email
  • RSS

1 comment on this post.
  1. Tweets that mention The Mystery of the Slow First Run « RealObjects Blog -- Topsy.com:

    [...] This post was mentioned on Twitter by Sebastian Giffhorn, RealObjects. RealObjects said: Solved: "The Mystery of the Slow First Run" – http://www.realobjects.com/blog/?p=34 #BEA #Oracle #Weblogic #yGuard #PDFreactor #Java [...]