Upgrade to Lucee 5.2.3.35 results in GC overhead limit crashes


#1

After upgrading Lucee to latest, I keep getting Lucee crashes with GC overhead limit exceeded. Haven’t changed my app so wondering if there’s a memory leak in Lucee causing this? Unfortunately, there aren’t any errors in Lucee logs except for above and what’s shown below for application.log. Catalina log is also included.

Anyone else encountering issues? Any thoughts on how to debug?
Thanks.

Version	Lucee 5.2.3.35
Version Name	Velvet
Release date	Sep 1, 2017
ColdFusion® compatibility version	2016.0.03.300357
Configuration File	/opt/lucee/tomcat/lucee-server/context/lucee-server.xml
OS	Linux (3.2.0-4-amd64) 64bit
Remote IP	134.174.91.51
Host Name	orrms2.bwhanesthesia.org
Servlet Container	Apache Tomcat/8.5.6
Java	1.8.0_112 (Oracle Corporation) 64bit
Architecture	64bit

application.log

"ERROR","http-nio-8888-exec-15","09/14/2017","17:14:26","",";"
"ERROR","http-nio-8888-exec-16","09/14/2017","17:14:31","",";"
"ERROR","http-nio-8888-exec-16","09/14/2017","17:15:08","",";"
"ERROR","http-nio-8888-exec-8","09/14/2017","17:15:11","",";"
"ERROR","http-nio-8888-exec-20","09/14/2017","17:15:13","",";"
"ERROR","http-nio-8888-exec-5","09/14/2017","17:15:54","",";"
"ERROR","http-nio-8888-exec-12","09/14/2017","17:16:02","",";"
"ERROR","http-nio-8888-exec-12","09/14/2017","17:16:02","",";"
"ERROR","http-nio-8888-exec-18","09/14/2017","17:21:44","",";"
"ERROR","http-nio-8888-exec-9","09/14/2017","17:22:24","",";"
"ERROR","http-nio-8888-exec-7","09/14/2017","17:22:27","",";"
"ERROR","http-nio-8888-exec-20","09/14/2017","17:22:29","",";"

catalina.log

13-Sep-2017 10:20:22.205 WARNING [127.0.0.1-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have st
arted a thread named [FelixFrameworkWiring] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 java.lang.Object.wait(Object.java:502)
 org.apache.felix.framework.FrameworkWiringImpl.run(FrameworkWiringImpl.java:172)
 java.lang.Thread.run(Thread.java:745)
13-Sep-2017 10:20:22.206 WARNING [127.0.0.1-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [ROOT] appears to have st
arted a thread named [FelixStartLevel] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 java.lang.Object.wait(Object.java:502)
 org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:283)
 java.lang.Thread.run(Thread.java:745)
13-Sep-2017 10:20:22.220 INFO [main] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-8888"]
13-Sep-2017 10:20:22.397 SEVERE [http-nio-8888-exec-59] org.apache.coyote.http11.Http11Processor.service Error processing request
 java.lang.NullPointerException
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:389)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:784)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

13-Sep-2017 10:20:22.400 SEVERE [http-nio-8888-exec-59] org.apache.coyote.http11.Http11Processor.endRequest Error finishing response
 java.lang.NullPointerException
	at org.apache.coyote.http11.Http11OutputBuffer.flushBuffer(Http11OutputBuffer.java:514)
	at org.apache.coyote.http11.Http11OutputBuffer.finishResponse(Http11OutputBuffer.java:301)
	at org.apache.coyote.http11.Http11Processor.endRequest(Http11Processor.java:1459)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:824)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

13-Sep-2017 10:20:27.229 WARNING [main] org.apache.tomcat.util.net.AbstractEndpoint.shutdownExecutor The executor associated with thread pool [http-nio-8888] has not fully sh
utdown. Some application threads may still be running.

Lucee 5.2.x Java Heap Issues
Cfthread
Lucee 5.2.x Java Heap Issues
#2

Hey Cage, here are a couple of questions for you:

  1. How are you calling your cfthreads?

  2. Are you calling a CFHTTP within them? If you are calling a CFHTTP, are you setting a timeout?

  3. Are you using CFTHREAD with type JOIN at the end of your script to close out the threads?

I dealt with a ton of stuff when we built out our multi-thread HTTP system. Happy to help anyway that I can!


#3
  1. Using thread in cfscript to create named threads and then joining them at the end of the request.
  2. Yes, using cfhttp within them. Not setting an explicit timeout for the http.
  3. See #1

#4

I’m afraid I can’t offer much in the way of insight, but just to report that we have also had trouble with Lucee 5.2.3.35 after attempting to upgrade via a clean install from 4.5

It ran for a few hours ok, but suddenly incoming requests started getting stuck and never completing or timing out, until the server eventually became unresponsive.

We saw various org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads errors similar to yours, e.g.

04-Sep-2017 16:35:43.749 WARNING [host-startStop-2] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [xxx] appears to have started a thread named [FelixDispatchQueue] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.lang.Object.wait(Native Method)
 java.lang.Object.wait(Object.java:502)
 org.apache.felix.framework.util.EventDispatcher.run(EventDispatcher.java:1118)
 org.apache.felix.framework.util.EventDispatcher.access$000(EventDispatcher.java:55)
 org.apache.felix.framework.util.EventDispatcher$1.run(EventDispatcher.java:102)
 java.lang.Thread.run(Thread.java:748)

We also saw a lot of these:

04-Sep-2017 16:22:19.879 SEVERE [ajp-nio-8009-exec-178] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [CFMLServlet] in context with path [] threw exception [null] with root cause
 java.lang.ThreadDeath
	at java.lang.Thread.stop(Thread.java:853)
	at lucee.commons.io.StopThread.run(SystemUtil.java:1502)

and these:

04-Sep-2017 16:27:25.516 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadDetected Thread [ajp-nio-8009-exec-105] (id=[996834]) has been active for [607,056] milliseconds (since [9/4/17 4:17 PM]) to serve the same request for [URL_REDACTED] and may be stuck (configured threshold for this StuckThreadDetectionValve is [600] seconds). There is/are [63] thread(s) in total that are monitored by this Valve and may be stuck.

We tried restarting Lucee a few times but the same thing kept happening, so we rolled back to Lucee 4.5 and the problems went away.

We performed the same upgrade on another installation with the same environment/config, and there have been no issues, but this particular server has much higher load and a more diverse set of code running on it.


Application.log ERROR http-nio-8888-exec-XX & ajp-nio-8009-exec-XX
#5

I am also seeing the same errors since upgrading to Lucee 5.2.3.35. Have downgraded back to 5.2.2.71 until I have time to look into this. Any additional info would be greatly appreciated.


#6

I downgraded to 5.2.1.9 and that seems to be working okay for me.

You may want to see topic Cfthread which may be the issue at hand for an update.


#7

I’ve been seeing the same problems today with 5.2.3.35…

do you have any debugging templates enabled?

I’'m seeing memory usage climb by 20-30mb each time I reinit my application

with debugging enabled there’s nothing showing up in the various scopes size wise


#8

also @psarin you are running quite an old jdk, latest is 144


#9

it appears that the problem is a memory leak in lucee 5.2.3.35?


#10

I’m having same issues here. Tried latest stable version 5.2.6.60 and 5.2.7.56

After 1 hour sever went down and see these lines in my errorlog

Till the moment the server was not responding anymore i see lot of these messages:
05-Apr-2018 00:23:45.804 SEVERE [ajp-nio-8009-exec-2] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [CFMLServlet] in context with path threw exception [null] with root cause
java.lang.ThreadDeath
at java.lang.Thread.stop(Thread.java:853)
at lucee.commons.io.StopThread.run(SystemUtil.java:1524)

After server went “down” these error occur.
2018-04-04 22:41:45.119
lucee.runtime.exp.NativeException: lucee.runtime.util.VariableUtilImpl
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1184)
at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1548)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1509)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at java.util.HashMap.internalWriteEntries(HashMap.java:1790)
at java.util.HashMap.writeObject(HashMap.java:1363)
at sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1128)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1496)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at lucee.commons.collection.AbstractMapPro.writeExternal(AbstractMapPro.java:46)
at java.io.ObjectOutputStream.writeExternalData(ObjectOutputStream.java:1459)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1430)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1548)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1509)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at java.util.HashMap.internalWriteEntries(HashMap.java:1790)
at java.util.HashMap.writeObject(HashMap.java:1363)
at sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1128)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1496)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at lucee.commons.collection.AbstractMapPro.writeExternal(AbstractMapPro.java:46)
at java.io.ObjectOutputStream.writeExternalData(ObjectOutputStream.java:1459)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1430)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1548)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1509)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at lucee.runtime.ComponentImpl.writeExternal(ComponentImpl.java:2327)
at java.io.ObjectOutputStream.writeExternalData(ObjectOutputStream.java:1459)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1430)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at java.util.HashMap.internalWriteEntries(HashMap.java:1790)
at java.util.HashMap.writeObject(HashMap.java:1363)
at sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1128)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1496)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at lucee.commons.collection.AbstractMapPro.writeExternal(AbstractMapPro.java:46)
at java.io.ObjectOutputStream.writeExternalData(ObjectOutputStream.java:1459)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1430)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1548)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1509)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1548)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1509)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at java.util.HashMap.internalWriteEntries(HashMap.java:1790)
at java.util.HashMap.writeObject(HashMap.java:1363)
at sun.reflect.GeneratedMethodAccessor119.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:1128)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1496)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at lucee.commons.collection.AbstractMapPro.writeExternal(AbstractMapPro.java:46)
at java.io.ObjectOutputStream.writeExternalData(ObjectOutputStream.java:1459)
at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1430)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
at lucee.runtime.type.scope.storage.IKStorageValue.serialize(IKStorageValue.java:89)
at lucee.runtime.type.scope.storage.IKStorageValue.toByteRepresentation(IKStorageValue.java:40)
at lucee.runtime.type.scope.storage.IKHandlerCache.store(IKHandlerCache.java:58)
at lucee.runtime.type.scope.storage.IKStorageScopeSupport.store(IKStorageScopeSupport.java:415)
at lucee.runtime.type.scope.storage.IKStorageScopeSupport.touchAfterRequest(IKStorageScopeSupport.java:295)
at lucee.runtime.PageContextImpl.release(PageContextImpl.java:529)
at lucee.runtime.CFMLFactoryImpl.releaseLuceePageContext(CFMLFactoryImpl.java:209)
at lucee.runtime.thread.ChildThreadImpl.execute(ChildThreadImpl.java:240)
at lucee.runtime.thread.ChildThreadImpl.run(ChildThreadImpl.java:147)
Caused by: java.io.NotSerializableException: lucee.runtime.util.VariableUtilImpl
… 96 more

We are using CFthread


#11

Did anyone ever find a fix for this issue? I get similar errors continuously on dev (Luce 5.3.1.87-RC)

SEVERE [ajp-nio-8009-exec-6] org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [CFMLServlet] in context with path [] threw exception
 java.lang.IllegalThreadStateException
	at java.lang.Thread.start(Unknown Source)
	at lucee.runtime.spooler.SpoolerEngineImpl.start(SpoolerEngineImpl.java:157)
	at lucee.runtime.spooler.SpoolerEngineImpl.add(SpoolerEngineImpl.java:147)
	at lucee.runtime.CFMLFactoryImpl.releaseLuceePageContext(CFMLFactoryImpl.java:205)
	at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1060)
	at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:991)
	at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:102)
	at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:394)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:770)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Unknown Source)

#12

When I had the issue with version 5.2.3.35, nothing solved it. Upgrading to a newer version (where the cfthread bug I mentioned above was fixed) seemed to solve the problem.

I haven’t tried the latest version so I can’t comment if the bug has crept back in.

I’d recommend downgrading, version by version, until you get to a version that works properly and then filing a bug report.


#13

I think it has something to do with the AJP connector to Apache HTTPD (2.4)… if I bypass Apache and hit Tomcat (9.0.12) directly over port 8080 everything is fine. By the way, I am not using cfthread anywhere in any app this happens with, though I am using Coldbox (both 4.3 and 5.3) so perhaps it is using it under the hood.


#14

I think I have narrowed this down to being caused by - or at least made it consistently reproducible in - the Coldbox core cfdebugger module. Details here:

https://groups.google.com/forum/#!topic/coldbox/1p3k7OUlRig


#15

I actually ran into this the other night after upgrading one of our Linux boxes to latest Apache 2.4, Tomcat 9 and most recent snapshot of Lucee 5.3… Tomcat would die shortly after starting Lucee/Tomcat. In our case, we have a large FW/1 app instead of ColdBox. Restarting would fix the issue only temporarily. My workaround (so far) was to downgrade to the RC release of Lucee 5.3. I have not been able to track down the root issue for the time being.


#16

I downgraded too, but still have the issue. It’s rather unnerving as I know I just fixed a symptom when disabling the debugger on our dev boxes.


#17

Has anyone got a reproducible test case?

GC Overhead limit exceeded with debugging enabled in 5.3.1.64
https://luceeserver.atlassian.net/browse/LDEV-1990