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.