United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-6682459 Lock contention due to debug print
JDK-6682459 : Lock contention due to debug print

Details
Type:
Bug
Submit Date:
2008-04-01
Status:
Closed
Updated Date:
2012-04-25
Project Name:
JDK
Resolved Date:
2008-05-14
Component:
xml
OS:
solaris_10
Sub-Component:
javax.xml.transform
CPU:
sparc
Priority:
P3
Resolution:
Fixed
Affected Versions:
6u6
Fixed Versions:
1.4.0 (1.4)

Related Reports
Backport:
Backport:

Sub Tasks

Description
During one of the JCAPS benchmark testing I ran into the following lock contention issue. The thread dump of the contention point is given below -

"p: thread-pool-1; w: 3" daemon prio=3 tid=0x090d7800 nid=0x37 waiting for monitor entry [0x31518000..0x31518c70]
  java.lang.Thread.State: BLOCKED (on object monitor)
       at java.util.Collections$SynchronizedCollection.toString(Collections.java:1599)
       - waiting to lock <0x3fe503b0> (a java.util.Collections$SynchronizedRandomAccessList)
       at java.lang.String.valueOf(String.java:2827)
       at java.lang.StringBuilder.append(StringBuilder.java:115)
       at com.sun.enterprise.loader.EJBClassLoader.toString(EJBClassLoader.java:786)
       at java.lang.String.valueOf(String.java:2827)
       at java.lang.StringBuilder.append(StringBuilder.java:115)
       at com.sun.org.apache.xalan.internal.xsltc.dom.ObjectFactory.lookUpFactoryClass(ObjectFactory.java:220)
       at com.sun.org.apache.xalan.internal.xsltc.dom.XSLTCDTMManager.getDTMManagerClass(XSLTCDTMManager.java:101)

The associated code at com.sun.org.apache.xalan.internal.xsltc.dom.ObjectFactory.lookUpFactoryClass is

       debugPrintln("created new instance of " + providerClass +
                  " using ClassLoader: " + cl);

Even though the debug is not turned on, the entire String is required to be created before the debugPrintln method can be called. It is during the process of this String creating the lock is contented. A simple fix for this is to call the debugPrintln method only if DEBUG is enabled. I ran some experiments with that modification and got a 24% improvement in our microbenchmark.
During one of the JCAPS benchmark testing I ran into the following lock contention issue. The thread dump of the contention point is given below -

"p: thread-pool-1; w: 3" daemon prio=3 tid=0x090d7800 nid=0x37 waiting for monitor entry [0x31518000..0x31518c70]
  java.lang.Thread.State: BLOCKED (on object monitor)
       at java.util.Collections$SynchronizedCollection.toString(Collections.java:1599)
       - waiting to lock <0x3fe503b0> (a java.util.Collections$SynchronizedRandomAccessList)
       at java.lang.String.valueOf(String.java:2827)
       at java.lang.StringBuilder.append(StringBuilder.java:115)
       at com.sun.enterprise.loader.EJBClassLoader.toString(EJBClassLoader.java:786)
       at java.lang.String.valueOf(String.java:2827)
       at java.lang.StringBuilder.append(StringBuilder.java:115)
       at com.sun.org.apache.xalan.internal.xsltc.dom.ObjectFactory.lookUpFactoryClass(ObjectFactory.java:220)
       at com.sun.org.apache.xalan.internal.xsltc.dom.XSLTCDTMManager.getDTMManagerClass(XSLTCDTMManager.java:101)

The associated code at com.sun.org.apache.xalan.internal.xsltc.dom.ObjectFactory.lookUpFactoryClass is

       debugPrintln("created new instance of " + providerClass +
                  " using ClassLoader: " + cl);

Even though the debug is not turned on, the entire String is required to be created before the debugPrintln method can be called. It is during the process of this String creating the lock is contented. A simple fix for this is to call the debugPrintln method only if DEBUG is enabled. I ran some experiments with that modification and got a 24% improvement in our microbenchmark.
During one of the JCAPS benchmark testing I ran into the following lock contention issue. The thread dump of the contention point is given below -

"p: thread-pool-1; w: 3" daemon prio=3 tid=0x090d7800 nid=0x37 waiting for monitor entry [0x31518000..0x31518c70]
  java.lang.Thread.State: BLOCKED (on object monitor)
       at java.util.Collections$SynchronizedCollection.toString(Collections.java:1599)
       - waiting to lock <0x3fe503b0> (a java.util.Collections$SynchronizedRandomAccessList)
       at java.lang.String.valueOf(String.java:2827)
       at java.lang.StringBuilder.append(StringBuilder.java:115)
       at com.sun.enterprise.loader.EJBClassLoader.toString(EJBClassLoader.java:786)
       at java.lang.String.valueOf(String.java:2827)
       at java.lang.StringBuilder.append(StringBuilder.java:115)
       at com.sun.org.apache.xalan.internal.xsltc.dom.ObjectFactory.lookUpFactoryClass(ObjectFactory.java:220)
       at com.sun.org.apache.xalan.internal.xsltc.dom.XSLTCDTMManager.getDTMManagerClass(XSLTCDTMManager.java:101)

The associated code at com.sun.org.apache.xalan.internal.xsltc.dom.ObjectFactory.lookUpFactoryClass is

       debugPrintln("created new instance of " + providerClass +
                  " using ClassLoader: " + cl);

Even though the debug is not turned on, the entire String is required to be created before the debugPrintln method can be called. It is during the process of this String creating the lock is contented. A simple fix for this is to call the debugPrintln method only if DEBUG is enabled. I ran some experiments with that modification and got a 24% improvement in our microbenchmark.

                                    

Comments
EVALUATION

Debug message construction should be avoided.
                                     
2008-04-02
EVALUATION

The patch, along with that for 6660724 has been verified by the JCAPS performance team. It is now available in JAXP 1.4 RI. Requests will be made for JDK integration.
                                     
2008-05-14



Hardware and Software, Engineered to Work Together