Delay in Ajax Request Hitting Server
ncuneo Sep 14, 2010 9:14 PMArchitecture: Tivoli Access Manager for security
4 node load balanced Weblogic 10.3.0 cluster
Seam 2.2.0
RichFaces 3.3.1
After releasing our ajax heavy app to production we are noticing a behaviour where clients will use the app fine for 95% of the time, but then a random ajax request will just show the loading graphic on the client browser and spin for 5mins and then the request eventually comes back.
Examining the server logs we can see that the client request didnt actually hit the server until the end of the 5min wait and we serviced the request almost instantly.
Just shooting in the dark at the moment, but we do have the global queue enabled. Don't think this would have anything to do with it though.
<context-param>
<param-name>org.richfaces.queue.global.enabled</param-name>
<param-value>true</param-value>
</context-param>
And here is an example of a link which generated an ajax request we know took a long time to process:
<a:commandLink id="modelHistoryCancel" action="#{modelHistory.close()}" ajaxSingle="true" immediate="true" oncomplete="#{closeMe}" styleClass="sml-scndry-button" status="waitPanelStatus">
Here is a snapshot of the request we know took 5mins on the client side, but only 488ms to process on the server side.
14-Sep 15:13:16,810 [19] [26715466] DEBUG [ManagedInvestmentSearch] Executing managed investment search using criteria [U]...
14-Sep 15:13:16,811 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] Finding managed investments that meet criteria [U]...
14-Sep 15:13:16,812 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] returning cached allowable funds for bv MPM / dealer 0001
14-Sep 15:13:16,812 [19] [26715466] DEBUG [SecuritiesManager] dealerRestrictions size: 1
14-Sep 15:13:16,812 [19] [26715466] DEBUG [SecuritiesManager] found 0 restrictions in cache with key BVDealerKey [bv=MPM, dealer=0001]
14-Sep 15:13:16,812 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] adding 0 restricted dealer securities for model owner 0001
14-Sep 15:13:16,812 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] no restrictions, gonna use cache
14-Sep 15:13:16,813 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] returning cached entity restrictions for entity type V / entity BSPT
14-Sep 15:13:16,813 [19] [26715466] DEBUG [SecuritiesManager] found entity restrictions in cache for key EntityKey [entityCode=BSPT, entityType=V] now going to filter
14-Sep 15:13:16,813 [19] [26715466] DEBUG [SecuritiesManager] Using queryString: U
14-Sep 15:13:16,813 [19] [26715466] DEBUG [SecuritiesManager] returning 0 matches
14-Sep 15:13:16,813 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] retain 0 filtered restricted funds for model owner BSPT entity type V
14-Sep 15:13:16,813 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] added 0 filtered restricted funds
14-Sep 15:13:16,813 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] Executing additional filtering on [17] managed investment securities...
14-Sep 15:13:16,813 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] Existing instrument filter removed [0] managed investment securities.
14-Sep 15:13:16,815 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] Model managed investment filter removed [4] managed investment securities.
14-Sep 15:13:16,815 [19] [26715466] DEBUG [ModelPortfolioServiceFacadeImpl] Found [13] managed investments.
14-Sep 15:13:16,815 [19] [26715466] DEBUG [ManagedInvestmentSearch] Found [13] managed investments.
14-Sep 15:13:17,266 [19] [26715466] INFO [HttpRequestDebugFilter] END [1284440651295|ba2d1439-172b-4cb1-b59a-c8664a9d3bf2][488ms]-----------------------------------
Any suggestions appreciated.