glassfish
  1. glassfish
  2. GLASSFISH-17379

[perf] excessive lock contention in class loading during jsf benchmark

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.1.1_b12
    • Fix Version/s: 3.1.2
    • Component/s: classloader, jsf
    • Labels:
      None

      Description

      Note: This issue is very much likely to be present in 3.1.2, could not run it through 3.1.2 build due to login problem to glassfish admin console.

      Very recently issues with JSF scrumtoys application has been fixed and we started benchmarking JSF performance using this app. During the performance runs even with very few users (around 4) we noticed contention in classloading and only one application thread proceeds at a time while all others are blocked. Here is a sample thread-dump showing the contention,

      "http-thread-pool-8080(5)" daemon prio=10 tid=0x09d6a400 nid=0xc9a6 waiting for monitor entry [0x22dbc000]
      java.lang.Thread.State: BLOCKED (on object monitor)
      at java.lang.ClassLoader.loadClass(ClassLoader.java:291)

      • waiting to lock <0x389b3220> (a org.glassfish.internal.api.DelegatingClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
        at org.glassfish.web.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1466)
        at org.glassfish.web.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1369)
        at com.sun.faces.util.Util.loadClass(Util.java:281)
        at com.sun.faces.application.ApplicationImpl.newThing(ApplicationImpl.java:1686)
        at com.sun.faces.application.ApplicationImpl.createComponentApplyAnnotations(ApplicationImpl.java:1865)
        at com.sun.faces.application.ApplicationImpl.createComponent(ApplicationImpl.java:1152)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.createComponent(ComponentTagHandlerDelegateImpl.java:499)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:157)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.tag.composite.ImplementationHandler.apply(ImplementationHandler.java:81)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:152)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyCompositeComponent(CompositeComponentTagHandler.java:348)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyNextHandler(CompositeComponentTagHandler.java:190)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at com.sun.faces.facelets.tag.composite.ImplementationHandler.apply(ImplementationHandler.java:81)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:152)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyCompositeComponent(CompositeComponentTagHandler.java:348)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyNextHandler(CompositeComponentTagHandler.java:190)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:308)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:367)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:346)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:199)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:155)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:152)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.buildView(FaceletViewHandlingStrategy.java:769)
        at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:100)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
        at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:594)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1539)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:281)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
        at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:655)
        at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:595)
        at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:98)
        at com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:91)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:162)
        at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:330)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:174)
        at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:828)
        at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:725)
        at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1019)
        at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:225)
        at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
        at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
        at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
        at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
        at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
        at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
        at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
        at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
        at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
        at java.lang.Thread.run(Thread.java:662)

      "http-thread-pool-8080(3)" daemon prio=10 tid=0x09d69800 nid=0xc9a4 waiting for monitor entry [0x22d7b000]
      java.lang.Thread.State: BLOCKED (on object monitor)
      at java.lang.ClassLoader.loadClass(ClassLoader.java:291)

      • locked <0x389b3220> (a org.glassfish.internal.api.DelegatingClassLoader)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
        at org.glassfish.web.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1466)
        at org.glassfish.web.loader.WebappClassLoader.loadClass(WebappClassLoader.java:1369)
        at com.sun.faces.util.Util.loadClass(Util.java:281)
        at com.sun.faces.application.ApplicationImpl.newThing(ApplicationImpl.java:1686)
        at com.sun.faces.application.ApplicationImpl.createComponentApplyAnnotations(ApplicationImpl.java:1865)
        at com.sun.faces.application.ApplicationImpl.createComponent(ApplicationImpl.java:1152)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.createComponent(ComponentTagHandlerDelegateImpl.java:499)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:157)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.tag.composite.ImplementationHandler.apply(ImplementationHandler.java:81)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:152)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyCompositeComponent(CompositeComponentTagHandler.java:348)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyNextHandler(CompositeComponentTagHandler.java:190)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyNextHandler(CompositeComponentTagHandler.java:187)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at com.sun.faces.facelets.tag.composite.ImplementationHandler.apply(ImplementationHandler.java:81)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:152)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyCompositeComponent(CompositeComponentTagHandler.java:348)
        at com.sun.faces.facelets.tag.jsf.CompositeComponentTagHandler.applyNextHandler(CompositeComponentTagHandler.java:190)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.applyNextHandler(DelegatingMetaTagHandler.java:137)
        at com.sun.faces.facelets.tag.jsf.ComponentTagHandlerDelegateImpl.apply(ComponentTagHandlerDelegateImpl.java:184)
        at javax.faces.view.facelets.DelegatingMetaTagHandler.apply(DelegatingMetaTagHandler.java:120)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at javax.faces.view.facelets.CompositeFaceletHandler.apply(CompositeFaceletHandler.java:98)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:308)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:367)
        at com.sun.faces.facelets.impl.DefaultFacelet.include(DefaultFacelet.java:346)
        at com.sun.faces.facelets.impl.DefaultFaceletContext.includeFacelet(DefaultFaceletContext.java:199)
        at com.sun.faces.facelets.tag.ui.CompositionHandler.apply(CompositionHandler.java:155)
        at com.sun.faces.facelets.compiler.NamespaceHandler.apply(NamespaceHandler.java:93)
        at com.sun.faces.facelets.compiler.EncodingHandler.apply(EncodingHandler.java:86)
        at com.sun.faces.facelets.impl.DefaultFacelet.apply(DefaultFacelet.java:152)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.buildView(FaceletViewHandlingStrategy.java:769)
        at com.sun.faces.lifecycle.RenderResponsePhase.execute(RenderResponsePhase.java:100)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
        at com.sun.faces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:139)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:594)
        at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1539)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:281)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
        at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:655)
        at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:595)
        at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:98)
        at com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:91)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:162)
        at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:330)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:231)
        at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:174)
        at com.sun.grizzly.http.ProcessorTask.invokeAdapter(ProcessorTask.java:828)
        at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:725)
        at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1019)
        at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:225)
        at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
        at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
        at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
        at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
        at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
        at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
        at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
        at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
        at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
        at java.lang.Thread.run(Thread.java:662)
      1. patch.tar
        10 kB
        Sanjeeb Sahoo
      2. patch2.tar
        10 kB
        Sanjeeb Sahoo
      3. patch3.tar
        10 kB
        Sanjeeb Sahoo
      4. server.log_2011-11-07
        1.91 MB
        amitagarwal

        Activity

        Hide
        amitagarwal added a comment -

        Please see the attached server.log_2011-11-07 file.

        Show
        amitagarwal added a comment - Please see the attached server.log_2011-11-07 file.
        Hide
        Sanjeeb Sahoo added a comment -

        Amit,

        I have looked at the attached server.log and I do see the patch taking effect. I see initially classes getting added to notFoundClasses cache and later on DelegatingClassLoader is quickly throwing ClassNotFoundException when it sees a class in the aforementioned cache. This means we should not see the kind of contention you had initially reported. Are you still seeing contention? Are you allowing the system to warm up sufficiently before proceeding to measure the numbers?

        Thanks,
        Sahoo

        Show
        Sanjeeb Sahoo added a comment - Amit, I have looked at the attached server.log and I do see the patch taking effect. I see initially classes getting added to notFoundClasses cache and later on DelegatingClassLoader is quickly throwing ClassNotFoundException when it sees a class in the aforementioned cache. This means we should not see the kind of contention you had initially reported. Are you still seeing contention? Are you allowing the system to warm up sufficiently before proceeding to measure the numbers? Thanks, Sahoo
        Hide
        amitagarwal added a comment -

        I am still seeing this contention. Yes, I did allow the system to warm-up for about 10 minutes and then collected metrics in steady state.

        Show
        amitagarwal added a comment - I am still seeing this contention. Yes, I did allow the system to warm-up for about 10 minutes and then collected metrics in steady state.
        Hide
        Sanjeeb Sahoo added a comment -

        Will look at this bug post 3.1.2.

        Show
        Sanjeeb Sahoo added a comment - Will look at this bug post 3.1.2.
        Hide
        amitagarwal added a comment -

        Setting javax.faces.PROJECT_STAGE to Production in web.xml resolved the reported contention. Hence closing the bug.

        Show
        amitagarwal added a comment - Setting javax.faces.PROJECT_STAGE to Production in web.xml resolved the reported contention. Hence closing the bug.

          People

          • Assignee:
            Sanjeeb Sahoo
            Reporter:
            amitagarwal
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: