JDK-5049261 : Performance degrades when a method has many try finally blocks
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 1.4.2
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: windows_nt
  • CPU: x86
  • Submitted: 2004-05-18
  • Updated: 2005-08-09
  • Resolved: 2005-08-09
Related Reports
Duplicate :  
Relates :  
Description
Name: tb29552			Date: 05/18/2004


FULL PRODUCT VERSION :
java version "1.4.2_02"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2_02-b03)
Java HotSpot(TM) Client VM (build 1.4.2_02-b03, mixed mode)

ADDITIONAL OS VERSION INFORMATION :
Windows NT Version 4.0

A DESCRIPTION OF THE PROBLEM :
We recently faced a peculiar perf prob at a customer site.  The jsp application of the customer was responding very slowly. It would sometimes take 10-12secods to respond for a page with a table showing data.

After a trying all the standard methods of analysing perf, we tried doing verbosegc. The output showed that times when the server took longer to respond, it was doing GC mostly. Tuning the GC params didnt help much. Trying the server mode didnt help much. We finally tried with IBM JDK and it worked fine.

Later by commenting code line by line, we realized that the problem was because of the try-finally blocks int eh generated servlet. The jsp compiler was generating lot of try finally block in the jspService method. Some how this is affecting the GC performance. And some how IBM jdk seems to handle this situation well.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Below are two classes SimpleFinally and  Finally. Both do same operation and same number of times. However SimpleFinally takes forever to complete. Note the GC output. SimpleFinally takes 20ms while Finally takes 2s. Also running the same test on IBM JDK shows not significant diff between the two classes.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
The response time for SimpleFinally and Finally should have been same.
ACTUAL -
The response time for Finally was orders of magnitude higher that that of SimpleFinally.

REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
------
import java.util.*;

public class SimpleFinally
{
    public static void main(String argv[])
	throws Exception
    {
	long t = System.currentTimeMillis();
	List l = new ArrayList();
	for(int i=0; i<600*1000; i++){
	    	try{
		    l.add("Test"+i);
		}finally{
		    l.clear();
		}
	}
	System.out.println("Time taken: "+(System.currentTimeMillis()-t));
    }
}
------


   Class Finally.java is too large to fit in the Description
   of a bug report.  Refer to attached file Finally.java.Z.

   The abbreviated version looks like this:

import java.util.*;

public class Finally
{
    public static void main(String argv[])
	throws Exception
    {
	long t = System.currentTimeMillis();
	List l = new ArrayList();
	for(int i=0; i<1000; i++){
	    try{
		    l.add("Test"+i);
	    }finally{
		    l.clear();
	    }
	    try{
		    l.add("Test"+i);
	    }finally{
		    l.clear();
	    }

	    [ ... 598 more try ... finally ... blocks deleted ...]

	}
	System.out.println("Time taken: "+(System.currentTimeMillis()-t));
    }
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
Keep the number of try-finallies in a method to the minimum. The prob seems to be related to only TryFinally blocks. Replacing the Try-Finally with regular block seems to work fine.
(Incident Review ID: 269858) 
======================================================================

Comments
EVALUATION Looking into this bug This bug is in fact a duplicate of 4734748, the root cause is the same. Thanks for the test case and analysis. The fix to bug 4734748 is the implementation of a new hotspot switch -XX:+TaggedStackInterpreter which reduces the GC times for interpreted methods, particularly ones with lots of exception blocks. From the test submitted, it reduces GC times as below: philli% java -server -verbose:gc Finally [GC 9216K->120K(35328K), 0.0923382 secs] [GC 9336K->128K(44544K), 0.1000194 secs] [GC 18560K->128K(47616K), 0.0840838 secs] [GC 21632K->128K(64000K), 0.1011757 secs] Time taken: 1137 philli% java -server -verbose:gc -XX:+TaggedStackInterpreter Finally [GC 9216K->136K(35328K), 0.0037265 secs] [GC 9352K->136K(35328K), 0.0009884 secs] [GC 9352K->120K(35328K), 0.0011601 secs] [GC 9336K->136K(35328K), 0.0009739 secs] [GC 9352K->136K(35264K), 0.0009928 secs] [GC 9288K->136K(33856K), 0.0008641 secs] [GC 9224K->104K(36672K), 0.0062753 secs] Time taken: 796 With -XX:+TaggedStackInterpreter it also reduced the GC times in Finally to essentially match the SimpleFinally case. See bug 4734748 for more information.
06-08-2004

PUBLIC COMMENTS .
06-08-2004