May 22 2004

Of perf degradation with try-finallies and poor VM option docs …

Tags: , Rajiv @ 2:21 am UTC

Recently we had a customer issue where the application was responding very slowly. After a lot of struggle we found out that Sun’s JDK had issues when handling methods with large number of try-finally blocks. Sachin has discussed the problem in greater detail in his post The Usual Suspects?.

To simulate the problem I wrote a sample class with a method having lot of try finally blocks.

9            long t = System.currentTimeMillis();
10           //Number of blocks = 5
11           //Number of iterations = (600/5)*1000 = 120*1000
12           for (int i = 0; i < 120* 1000; i++) {
13               //Start try-finally blocks
14               try {
15                   l.add("Test"+i);
16               } finally {
17                   l.clear();
18               }
19               try {
20                   l.add("Test"+i);
21               } finally {
22                   l.clear();
23               }
24               try {
25                   l.add("Test"+i);
26               } finally {
27                   l.clear();
28               }
29               try {
30                   l.add("Test"+i);
31               } finally {
32                   l.clear();
33               }
34               try {
35                   l.add("Test"+i);
36               } finally {
37                   l.clear();
38               }
39               //Stop try-finally blocks
40           }
41           System.out.println("Time taken: "+(System.currentTimeMillis()-t));

And some classes with regular blocks instead of try-finally blocks

9            long t = System.currentTimeMillis();
10           //Number of blocks = 5
11           //Number of iterations = (600/5)*1000 = 120*1000
12           for (int i = 0; i < 120* 1000; i++) {
13               //Start regular blocks
14               {
15                   l.add("Test"+i);
16               }{
17                   l.clear();
18               }
19               {
20                   l.add("Test"+i);
21               }{
22                   l.clear();
23               }
24               {
25                   l.add("Test"+i);
26               }{
27                   l.clear();
28               }
29               {
30                   l.add("Test"+i);
31               }{
32                   l.clear();
33               }
34               {
35                   l.add("Test"+i);
36               }{
37                   l.clear();
38               }
39               //Stop regular blocks
40           }
41           System.out.println("Time taken: "+(System.currentTimeMillis()-t));

Keeping the number of java operations constant [by making number of iterations = 600,000/numBlockPerMethod], you would expect a constant reponse time as you increase the number of blocks per method. However, the graph looks like this [click for full size image]:

Plot of perf degradation with increasing number of try finally blocks in a method. [Click for enlarged plot]

In case of Sun JDK the performance degrades so much that I had to plot the y-axis in logarithmic scale! [Talking about logarithmic scale ... for a long time I never realized that yahoo stock quotes show prices in logarithmic scale ... thanks to the .com bubble!] IBM JDK, on the other hand seems to handle this situation much better. It shows a much lower degradation in the response time. You actually don’t need the log scale in its case!

This issue is being tracked as Bug: 5049261 at the Sun’s JDK bug database. [You will need to create an account if you don't already have one]. This bug has been marked as being related to Bug: 4493074. Interestingly, the related bug’s description mentions a whole lot of flags which I have never heard before: -XX:-Inline -XX:+PrintOptoBailouts -XX:+TraceOptoParse -XX:+TraceDeoptimization -XX:CompileThreshold -Xcomp -XX:CompileOnly. The only flag I could relate to here was the -XX:+PrintCompilation. It is another thing that I have no clue how to interpret the output of this flag either! I vaguely remember reading about this in some javaOne presentation. The presenter had mentioned that it prints the methods which could not be compiled and the user can list the methods which he doesn’t want to be compiled in a .hotspot_compiler file. I really wish Sun had documented these flags and their output better, instead of just mentioning “traces methods as compiled” in the VM Options document.

Share:
  • email
  • del.icio.us
  • DZone
  • Technorati
  • Reddit
  • Ma.gnolia
  • Google Bookmarks
  • YahooMyWeb
  • SphereIt
  • StumbleUpon
  • Digg
  • Mixx
  • TwitThis
  • Furl
  • Simpy

No trackbacks

4 comments

  1. Moazam


    On the topic of PrintCompilation, I’ve tried to answer some of your questions here.
    -Moazam

  2. Anonymous


    We had a very similar issue a while ago.

    We had an application that worked fine on WebLogic. When we tried it with Websphere we found it was very slow indeed.

    After much investigation we noticed it was because of a difference in the way WebSphere handled custom tag invocations in the generated servlet code (generated from a JSP).

    WebLogic put all the custom tag invocations inside a single try/catch. Websphere instead put all the invocations in their own try/catch. I cannot remember the exact details but within a single method, there is a lookup table that is used to find some offset. The structure to hold these offsets can only hold something like 64 at a time. This is normally absolutely fine for a single method but in a servlet with the custom tags, Websphere was going above this limit.

    The result was that it thrashed trying to move these offsets into the structure (you have to look at the VM code to see the precise reason for the thrashing and I cannot quite remember any longer).

    Could this be what you are seeing?


  3. rajiv


    The websphere/weblogic problem sounds very similar. However, it is interesting to know that you noticed the problem in Websphere. I thought Websphere uses IBM JDK and we had noticed that IBM JDK handles lot of try-finally blocks much better!

    I guess that is because, though IBM JDK handles too many blocks better than Sun JDK … it is still not as good as not having so many try-finally blocks. [Which is true if you look at the response time chart].

    The diff between try-finally and a regular block is probably because of the “lookup table trashing” you are mentioning. But in case of Sun JDK, most of the time was spent doing GC. Atleast the verbose:gc showed that!

    I guess we will get to know more when the Sun Engineers close the bug [hopefully they will post some details].

  4. Anonymous


    The graph is rubbish, although it shows that too many try/final blocks are very bad for performance the test doe snot take warmup-time into account, which can be clearly seen by the strange result produced by hotpot-server.

Leave a Reply

Subscribe to comments on this post

Allowed tags: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>