ICEfaces
  1. ICEfaces
  2. ICE-8352

Request latency steadily increases across submits with Mojarra 2.1.10+ (was: Request latency steadily increases for all ace showcase examples)

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.1.0.RC1
    • Fix Version/s: 3.2
    • Component/s: Sample Apps
    • Labels:
      None
    • Environment:
      Icefaces 3 from trunk, revision 29857 / apache-tomcat-7.0.29 / jdk1.6.0_33
    • Assignee Priority:
      P1

      Description

      Originally noticed by a client when comparing the ice:DataTable vs ace:DataTable examples across showcases, each subsequent request of a particular feature grows in average latency. However I've confirmed that this is not unique the DataTable and appear to affect all ace components.

        Activity

        Krashan Brahmanjara created issue -
        Hide
        Krashan Brahmanjara added a comment -

        Screens with problem

        Show
        Krashan Brahmanjara added a comment - Screens with problem
        Krashan Brahmanjara made changes -
        Field Original Value New Value
        Attachment tomcat7-component_showcase_1_8-rowselection.PNG [ 14679 ]
        Attachment tomcat7-component_showcase_3_0-rowselection.PNG [ 14680 ]
        Attachment tomcat7-showcase_3_0-rowselection-ice.PNG [ 14681 ]
        Krashan Brahmanjara made changes -
        Hide
        Ken Fyten added a comment - - edited

        I've tested the scenarios described in the description with latest icefaces3/trunk, rvn#30887 and see no issues with the compat/component-showcase ice:dataTable demo.

        However, using the showcase demo w/ Tomcat and FF I do see fairly slow performance when using the row selector demo. Also, clicking through many subsequent selections does result in continually increasing response times.

        This needs priority evaluation.

        Show
        Ken Fyten added a comment - - edited I've tested the scenarios described in the description with latest icefaces3/trunk, rvn#30887 and see no issues with the compat/component-showcase ice:dataTable demo. However, using the showcase demo w/ Tomcat and FF I do see fairly slow performance when using the row selector demo. Also, clicking through many subsequent selections does result in continually increasing response times. This needs priority evaluation.
        Hide
        Ken Fyten added a comment - - edited

        Assigned to Ted for analysis.

        Show
        Ken Fyten added a comment - - edited Assigned to Ted for analysis.
        Hide
        Nils Lundquist added a comment - - edited

        Original Reported Description:

        Tomcat tested with three apps:

        • component-showcase with current Icefaces 1.8.3 from trunk
        • component-showcase with current Icefaces 3.1.0-RC1 from trunk
        • showcase with current Icefaces 3.1.0-RC1 from trunk

        In datatable / row selector view from Ice 1.8.3 switching between rows seems to 4-10 time faster than the same in Ice 3.0 ?!

        Additionaliy each next request is slower, and slower ...visualvm doesn't show any memory leak or processor overhead.

        Firebug screens attached.

        was:
        Tomcat tested with three apps:

        • component-showcase with current Icefaces 1.8.3 from trunk
        • component-showcase with current Icefaces 3.1.0-RC1 from trunk
        • showcase with current Icefaces 3.1.0-RC1 from trunk

        In datatable / row selector view from Ice 1.8.3 switching between rows seems to 4-10 time faster than the same in Ice 3.0 ?!

        Additionaliy each next request is slower, and slower ...visualvm doesn't show any memory leak or processor overhead.

        Firebug screens attached.

        Clearly some server side process is growing noticeably with each request. This is consistent with the reporters claim that there was no growing client processor overhead or memory leak.

        Perhaps it is some odd app level leak in showcase?

        Assigning to Mircea for investigation as per Kens request.

        Show
        Nils Lundquist added a comment - - edited Original Reported Description: Tomcat tested with three apps: component-showcase with current Icefaces 1.8.3 from trunk component-showcase with current Icefaces 3.1.0-RC1 from trunk showcase with current Icefaces 3.1.0-RC1 from trunk In datatable / row selector view from Ice 1.8.3 switching between rows seems to 4-10 time faster than the same in Ice 3.0 ?! Additionaliy each next request is slower, and slower ...visualvm doesn't show any memory leak or processor overhead. Firebug screens attached. was: Tomcat tested with three apps: component-showcase with current Icefaces 1.8.3 from trunk component-showcase with current Icefaces 3.1.0-RC1 from trunk showcase with current Icefaces 3.1.0-RC1 from trunk In datatable / row selector view from Ice 1.8.3 switching between rows seems to 4-10 time faster than the same in Ice 3.0 ?! Additionaliy each next request is slower, and slower ...visualvm doesn't show any memory leak or processor overhead. Firebug screens attached. Clearly some server side process is growing noticeably with each request. This is consistent with the reporters claim that there was no growing client processor overhead or memory leak. Perhaps it is some odd app level leak in showcase? Assigning to Mircea for investigation as per Kens request.
        Hide
        Nils Lundquist added a comment - - edited

        Out of curiosity I've confirmed that this effects the ice:DataTable as well. This appears to be application specific or ICEfaces wide.

        Show
        Nils Lundquist added a comment - - edited Out of curiosity I've confirmed that this effects the ice:DataTable as well. This appears to be application specific or ICEfaces wide.
        Hide
        Nils Lundquist added a comment - - edited

        I am attaching profiling output for a series of requests made via the ace:confirmationPanel.
        As you can see a slow increase to the average latency of a request is taking place. This is common to all the components/features I've reviewed on showcase. There appears to be a larger increase for the more complicated components.

        Show
        Nils Lundquist added a comment - - edited I am attaching profiling output for a series of requests made via the ace:confirmationPanel. As you can see a slow increase to the average latency of a request is taking place. This is common to all the components/features I've reviewed on showcase. There appears to be a larger increase for the more complicated components.
        Hide
        Ted Goddard added a comment - - edited

        Confirmed that showcase checkbox demo increases by 10 ms for each click. Response from the server does not change. Also, auction demo shows no such symptoms.

        Show
        Ted Goddard added a comment - - edited Confirmed that showcase checkbox demo increases by 10 ms for each click. Response from the server does not change. Also, auction demo shows no such symptoms.
        Hide
        Ken Fyten added a comment - - edited

        Note that this issue does not affect the 3.1 or EE 3.0.0.GA_P01 official releases as they both ship with Mojarra JSF 2.1.6, which doesn't exhibit the issue.

        Show
        Ken Fyten added a comment - - edited Note that this issue does not affect the 3.1 or EE 3.0.0.GA_P01 official releases as they both ship with Mojarra JSF 2.1.6, which doesn't exhibit the issue.
        Hide
        Ted Goddard added a comment - - edited

        org.icefaces.autoid setting does not affect the ADD/REMOVE accumulation in basic.

        Show
        Ted Goddard added a comment - - edited org.icefaces.autoid setting does not affect the ADD/REMOVE accumulation in basic.
        Hide
        Mark Collette added a comment - - edited

        Could we make MandatoryResourcesSetup initially add the components in the sequence that ResourceOrdering prefers, so that we won't be moving them later?

        Show
        Mark Collette added a comment - - edited Could we make MandatoryResourcesSetup initially add the components in the sequence that ResourceOrdering prefers, so that we won't be moving them later?
        Repository Revision Date User Message
        ICEsoft Public SVN Repository #31825 Mon Oct 29 16:08:40 MDT 2012 mircea.toma ICE-8352 Make resource containers temporarely transient so that the removal and addition of resource is not track by the JSF state saving.
        Files Changed
        Commit graph MODIFY /icefaces3/trunk/icefaces/core/src/main/java/org/icefaces/impl/event/ResourceOrdering.java
        Commit graph MODIFY /icefaces3/trunk/icefaces/core/src/main/java/org/icefaces/impl/event/MandatoryResourcesSetup.java
        Repository Revision Date User Message
        ICEsoft Public SVN Repository #31833 Mon Oct 29 18:00:20 MDT 2012 mircea.toma ICE-8352 Mark the parents of re-ordered components as not in view to avoid having fired component addition or removal. The result is that JSF state saving will not react to the modifications done by our system event listeners.
        Files Changed
        Commit graph MODIFY /icefaces3/trunk/icefaces/core/src/main/java/org/icefaces/impl/event/ResourceOrdering.java
        Commit graph MODIFY /icefaces3/trunk/icefaces/core/src/main/java/org/icefaces/impl/event/MandatoryResourcesSetup.java
        Hide
        Mircea Toma added a comment - - edited

        It looks like Mojarra 2.1.3 has a similar behaviour where the component tree grows continually with each AJAX postpack due to re-arranging of the resources done by MandatoryResourceSetup and ResourceOrdering system event listeners.

        Show
        Mircea Toma added a comment - - edited It looks like Mojarra 2.1.3 has a similar behaviour where the component tree grows continually with each AJAX postpack due to re-arranging of the resources done by MandatoryResourceSetup and ResourceOrdering system event listeners.
        Hide
        Mircea Toma added a comment - - edited

        The fix that works both for 2.1.3 and >2.1.10 is to mark the parents of re-ordered components as not in view, avoiding thus the firing of component addition or removal. The result is that JSF state saving will not react (by trying to restore component addition or removal) to the modifications done by our system event listeners.

        Show
        Mircea Toma added a comment - - edited The fix that works both for 2.1.3 and >2.1.10 is to mark the parents of re-ordered components as not in view, avoiding thus the firing of component addition or removal. The result is that JSF state saving will not react (by trying to restore component addition or removal) to the modifications done by our system event listeners.
        Hide
        Deryk Sinotte added a comment - - edited

        Re-opening the case. As reported in ICE-8717, yesterday's changes related to this case (r31825 and r31833) are now causing the following exception when running the component-showcase example:
        java.lang.NullPointerException
        at com.sun.faces.application.view.StateManagementStrategyImpl$4.visit(StateManagementStrategyImpl.java:331)
        at com.sun.faces.component.visit.FullVisitContext.invokeVisitCallback(FullVisitContext.java:151)
        at javax.faces.component.UIComponent.visitTree(UIComponent.java:1590)
        at javax.faces.component.UIComponent.visitTree(UIComponent.java:1601)
        at com.sun.faces.application.view.StateManagementStrategyImpl.restoreView(StateManagementStrategyImpl.java:326)
        at com.sun.faces.application.StateManagerImpl.restoreView(StateManagerImpl.java:188)
        at com.sun.faces.application.view.ViewHandlingStrategy.restoreView(ViewHandlingStrategy.java:123)
        at com.sun.faces.application.view.FaceletViewHandlingStrategy.restoreView(FaceletViewHandlingStrategy.java:453)
        at com.sun.faces.application.view.MultiViewHandler.restoreView(MultiViewHandler.java:148)
        at com.sun.faces.lifecycle.RestoreViewPhase.execute(RestoreViewPhase.java:192)
        at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101)
        at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:116)
        at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118)
        at javax.faces.webapp.FacesServlet.service(FacesServlet.java:593)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:225)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:927)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1001)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:585)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:680)
        I verified these changes as the cause by reverting them and re-running the component-showcase example.

        Show
        Deryk Sinotte added a comment - - edited Re-opening the case. As reported in ICE-8717, yesterday's changes related to this case (r31825 and r31833) are now causing the following exception when running the component-showcase example: java.lang.NullPointerException at com.sun.faces.application.view.StateManagementStrategyImpl$4.visit(StateManagementStrategyImpl.java:331) at com.sun.faces.component.visit.FullVisitContext.invokeVisitCallback(FullVisitContext.java:151) at javax.faces.component.UIComponent.visitTree(UIComponent.java:1590) at javax.faces.component.UIComponent.visitTree(UIComponent.java:1601) at com.sun.faces.application.view.StateManagementStrategyImpl.restoreView(StateManagementStrategyImpl.java:326) at com.sun.faces.application.StateManagerImpl.restoreView(StateManagerImpl.java:188) at com.sun.faces.application.view.ViewHandlingStrategy.restoreView(ViewHandlingStrategy.java:123) at com.sun.faces.application.view.FaceletViewHandlingStrategy.restoreView(FaceletViewHandlingStrategy.java:453) at com.sun.faces.application.view.MultiViewHandler.restoreView(MultiViewHandler.java:148) at com.sun.faces.lifecycle.RestoreViewPhase.execute(RestoreViewPhase.java:192) at com.sun.faces.lifecycle.Phase.doPhase(Phase.java:101) at com.sun.faces.lifecycle.RestoreViewPhase.doPhase(RestoreViewPhase.java:116) at com.sun.faces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:118) at javax.faces.webapp.FacesServlet.service(FacesServlet.java:593) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:225) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:927) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1001) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:585) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:680) I verified these changes as the cause by reverting them and re-running the component-showcase example.
        Hide
        Deryk Sinotte added a comment - - edited

        There doesn't seem to be a problem with showcase app, either in the ACE or ICE sections. Using the debugger, I can see that the code that is throwing the NPE is never hit when running the current showcase - only when running component-showcase:

        From StateManagementStrategyImpl.restoreView()
                        Object restoredAddList[] = (Object[]) state.get(CLIENTIDS_TO_ADD_NAME);
                        if (restoredAddList != null && restoredAddList.length > 0) {
                            // Restore the list of added components
                            List<ComponentStruct> addList = new ArrayList<ComponentStruct>
        ...
        (restoredAddList.length);
        

        As it's trying to restore the list of added components, it looks like the one or more of the state entries is "corrupted" or at least in a format that the code doesn't like.

        Show
        Deryk Sinotte added a comment - - edited There doesn't seem to be a problem with showcase app, either in the ACE or ICE sections. Using the debugger, I can see that the code that is throwing the NPE is never hit when running the current showcase - only when running component-showcase: From StateManagementStrategyImpl.restoreView() Object restoredAddList[] = ( Object []) state.get(CLIENTIDS_TO_ADD_NAME); if (restoredAddList != null && restoredAddList.length > 0) { // Restore the list of added components List<ComponentStruct> addList = new ArrayList<ComponentStruct> ... (restoredAddList.length); As it's trying to restore the list of added components, it looks like the one or more of the state entries is "corrupted" or at least in a format that the code doesn't like.
        Repository Revision Date User Message
        ICEsoft Public SVN Repository #31882 Wed Oct 31 17:10:04 MDT 2012 mircea.toma ICE-8352 Make replaced resources transient so that state saving doesn't get confused when the same resource is added during each lifecycle by MandatoryResourceSetup.
        Files Changed
        Commit graph MODIFY /icefaces3/trunk/icefaces/core/src/main/java/org/icefaces/impl/event/MandatoryResourcesSetup.java
        Migration made changes -
        Summary Showcase for Icefaces 3.1.0-RC1-SNAPSHOT is very slow. ace:dataTable -> Row Selection demo in Showcase degrades rapidly (was: Showcase for Icefaces 3.1.0-RC1-SNAPSHOT is very slow.)
        Assignee Nils Lundquist [ nils.lundquist ]
        Fix Version/s 3.2 [ 10338 ]
        Assignee Priority P1 [ 10010 ]
        Migration made changes -
        Assignee Nils Lundquist [ nils.lundquist ] Ted Goddard [ ted.goddard ]
        Migration made changes -
        Fix Version/s 3.2.BETA1 [ 10360 ]
        Fix Version/s 3.2 [ 10338 ]
        Migration made changes -
        Summary ace:dataTable -> Row Selection demo in Showcase degrades rapidly (was: Showcase for Icefaces 3.1.0-RC1-SNAPSHOT is very slow.) Request latency steadily increases for all ace showcase examples (was: ace:dataTable -> Row Selection demo in Showcase degrades rapidly)
        Description Tomcat tested with three apps:
        - component-showcase with current Icefaces 1.8.3 from trunk
        - component-showcase with current Icefaces 3.1.0-RC1 from trunk
        - showcase with current Icefaces 3.1.0-RC1 from trunk

        In datatable / row selector view from Ice 1.8.3 switching between rows seems to 4-10 time faster than the same in Ice 3.0 ?!

        Additionaliy each next request is slower, and slower ...visualvm doesn't show any memory leak or processor overhead.

        Firebug screens attached.
        Originally noticed by a client when comparing the ice:DataTable vs ace:DataTable examples across showcases, each subsequent request of a particular feature grows in average latency. However I've confirmed that this is not unique the DataTable and appear to affect all ace components.
        Migration made changes -
        Summary Request latency steadily increases for all ace showcase examples (was: ace:dataTable -> Row Selection demo in Showcase degrades rapidly) Request latency steadily increases across submits with Mojarra 2.1.10+ (was: Request latency steadily increases for all ace showcase examples)
        Migration made changes -
        Assignee Ted Goddard [ ted.goddard ] Mircea Toma [ mircea.toma ]
        Migration made changes -
        Fix Version/s EE-3.2.0.GA [ 10332 ]
        Fix Version/s 3.2.BETA1 [ 10360 ]
        Migration made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Migration made changes -
        Resolution Fixed [ 1 ]
        Status Resolved [ 5 ] Reopened [ 4 ]
        Hide
        Migration added a comment -

        I've tested the scenarios described in the description with latest icefaces3/trunk, rvn#30887 and see no issues with the compat/component-showcase ice:dataTable demo.

        However, using the showcase demo w/ Tomcat and FF I do see fairly slow performance when using the row selector demo. Also, clicking through many subsequent selections does result in continually increasing response times.

        This needs priority evaluation.

        Show
        Migration added a comment - I've tested the scenarios described in the description with latest icefaces3/trunk, rvn#30887 and see no issues with the compat/component-showcase ice:dataTable demo. However, using the showcase demo w/ Tomcat and FF I do see fairly slow performance when using the row selector demo. Also, clicking through many subsequent selections does result in continually increasing response times. This needs priority evaluation.
        Migration made changes -
        Fix Version/s 3.2 [ 10338 ]
        Fix Version/s EE-3.2.0.GA [ 10332 ]
        Migration made changes -
        Fix Version/s 3.2.BETA1 [ 10360 ]
        Fix Version/s 3.2 [ 10338 ]
        Migration made changes -
        Fix Version/s EE-3.2.0.GA [ 10332 ]
        Fix Version/s 3.2.BETA1 [ 10360 ]
        Migration made changes -
        Mircea Toma made changes -
        Status Reopened [ 4 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Ken Fyten made changes -
        Fix Version/s 3.2 [ 10338 ]
        Fix Version/s EE-3.2.0.GA [ 10332 ]
        Ken Fyten made changes -
        Status Resolved [ 5 ] Closed [ 6 ]

          People

          • Assignee:
            Mircea Toma
            Reporter:
            Krashan Brahmanjara
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: