This is related to LDEV-3710 https://luceeserver.atlassian.net/browse/LDEV-3710
I’m trying to determine if another ticket should be raised for the issue, beyond that ticket
Don’t forget to tell us about your stack!
OS: Oracle Linux
Java Version: OpenJDK 11.0.7
Tomcat Version: Tomcat 9.0.52
Lucee Version: Lucee 5.3.8.x (both perform same), and 5.3.7.47 doesn’t show this consistent issue
application environment
webroot serves a few thousand domains through a couple of applications.
webroot contains several applications, the majority of the traffics sessions are from the root, standard sessions (essentially holding one session variable), in memory with a 2hr 1min timeout.
The admin application uses db storage for sessions, with a 2hr 1min timeout, 4,000 or fewer records at any time.
problem
Getting requests blocked every minute. this appears after running under load for several hours to several days.
current state
running ok under 5.3.7.47, cannot keep 5.3.8.x under load for an extended period of time
To help diagonose, after items are built up, I adjust load:
Load Balancer is turned on (to send health checks, of which Cloudflare sends quite a few)
Load Balancer is set to 0 (so normal traffic isn’t routed to me)
Getting requests blocked every minute. (the minute does appear to shift, depending on how long the block lasts or if a thread dump occurs)
These requests should run sub 20ms, but during this time, they can regularly exceed 1s.
Originally I thought was somehow related to too many sessions being cleaned up, as fusion reactor showing destroying sessions was a consistent indicator of when it would occur, however I was able to repro, while only showing 20 active sessions in fusion reactor, and still seeing the issue (session count had been high during testing the night before).
following a restart, while under load for 3 hours, all servers are showing 119 - 120,000 active sessions.
If I set a 5.3.7.x server to 0 traffic and a 5.3.8.x to 0, so both are just receiving frequent health checks; the health checks on 7.x stay below 20, while the 8.x stays below 20 until it has a spike each minute where they exceed 100ms, and this spike remains consistent with the timing of session cleanup.
If I switch scope logging from error to info, or vise versa, it appears to clear up for a period of time (for a shorter amount of time than the original buildup).
If I catch it in profile
thread cpu time is around 2ms
total query time under 10ms
relations has a WEbRequest is a full blue line with a very small jdbcrequest block at the far right.
100.0% - 347ms java.lang.Thread.run(Thread.java)
51 Collapsed Methods (show)
100.0% - 347ms Waiting on lock <0x613b4d0b> (a lucee.runtime.PageSourcePool)
The longer the server runs, the larger the spikes get, while active sessions stays fairly steady. If we leave the 5.3.8.x in load, we would have to restart within 2 days as the spikes will get into several seconds delay. While we only have had to restart 5.3.7.x for scheduled maintenance.
If I turn runtime protection on and down to where I can get a full thread dump, they consistently contain the items below.
(quantity of blocked requests varies each time, but always same place)
"ajp-nio-0:0:0:0:0:0:0:1-8009-exec-235" Id=1713944 BLOCKED on lucee.runtime.PageSourcePool@2aa69129 owned by "Thread-1650386" Id=1720538
State: BLOCKED
Deamon: true
Blocked: 8/00:00:06.492
Waiting: 60/00:23:52.592
CPU: 00:00:00.129
User: 00:00:00.100
Memory: (22,959,656 B)
lucee.runtime.MappingImpl.getPageSource(MappingImpl.java:399)
- waiting on <0x2aa69129> (a lucee.runtime.PageSourcePool held by thread 1720538, Thread-1650386)
lucee.runtime.MappingImpl.getPageSource(MappingImpl.java:394)
lucee.runtime.config.ConfigImpl.getPageSources(ConfigImpl.java:984)
lucee.runtime.config.ConfigImpl.getPageSources(ConfigImpl.java:891)
lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2448)
lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2421)
lucee.runtime.engine.Request.exe(Request.java:45)
lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1179)
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1125)
lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97)
lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
jdk.internal.reflect.GeneratedMethodAccessor82.invoke(Unknown Source)
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:566)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:134)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:772)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:344)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:207)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:809)
com.intergral.fusionreactor.j2ee.filter.FusionReactorCoreFilter.doFilter(FusionReactorCoreFilter.java:36)
jdk.internal.reflect.GeneratedMethodAccessor81.invoke(Unknown Source)
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:566)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:71)
jdk.internal.reflect.GeneratedMethodAccessor80.invoke(Unknown Source)
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:566)
com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:54)
com.intergral.fusionreactor.agent.pointcuts.NewFilterChainPointCut$1.invoke(NewFilterChainPointCut.java:42)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:433)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1726)
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked <0x149fad43> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.lang.Thread.run(Thread.java:834)
"Thread-1650386" Id=1720538 RUNNABLE
State: RUNNABLE
Deamon: true
Blocked: 0/00:00:00.000
Waiting: 0/00:00:00.000
CPU: 00:00:01.211
User: 00:00:01.200
Memory: (89,112,272 B)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:52)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:53)
lucee.commons.collection.LongKeyList.add(LongKeyList.java:42)
lucee.runtime.PageSourcePool.clearUnused(PageSourcePool.java:169)
lucee.runtime.MappingImpl.clearUnused(MappingImpl.java:300)
- locked <0x2aa69129> (a lucee.runtime.PageSourcePool)
lucee.runtime.functions.system.PagePoolClear.clear(PagePoolClear.java:93)
lucee.runtime.functions.system.PagePoolClear.clear(PagePoolClear.java:85)
lucee.runtime.functions.system.PagePoolClear.clear(PagePoolClear.java:65)
lucee.runtime.engine.Controler.doClearPagePools(Controler.java:447)
lucee.runtime.engine.Controler.control(Controler.java:362)
lucee.runtime.engine.Controler.control(Controler.java:244)
lucee.runtime.engine.Controler.access$000(Controler.java:58)
lucee.runtime.engine.Controler$ControlerThread.run(Controler.java:113)