tracker issue : CF-4201076

select a category, or use search below
(searches all categories and all time range)
Title:

Debug consumes memory even when showdebugoutput="false"

| View in Tracker

Status/Resolution/Reason: To Fix/Withdrawn/Investigate

Reporter/Name(from Bugbase): Kenneth Gladden / Kenneth Gladden ()

Created: 02/08/2018

Components: Debugging, General, Performance

Versions: 2016

Failure Type: Crash

Found In Build/Fixed In Build: 2016.0.05.303689 /

Priority/Frequency: Normal / All users will encounter

Locale/System: English / Windows 10 64 bit

Vote Count: 1

Problem Description: 
Eventually all available memory is consumed and the app fails with "GC overhead limit exceeded".

Steps to Reproduce: 
Have debug turned on in the server. Use <cfsetting showdebugoutput="false" >. Run something that has lots of loops and calling CFCs to do some calculations millions of times.

Actual Result:
Runs out of memory.

Expected Result:
Debug should not be running and consuming memory when you aren't going to show debug output. Program performs all calculations.

Any Workarounds:
Fall back to ColdFusion 11 or turn off debugging in the server.

Attachments:

Comments:

I'll add that I was working with Ken to resolve his "high heap use" problems, when we found this. I noticed in a stack trace that the long-running request was involved in calls to the Java classes involved in generating the CF debug output. We confirmed that he had showdebugoutput disabled. I had him disable it, and the request could now run to completion. Since he was working on a local dev machine, we opted for that. We since also confirmed that it only happens if the IP of the person making the request IS in the debugging IP address list (configured in the CF Admin). Of course, with showdebugoutput enabled, one could reasonably expect that this would not only prevent the debugging output from being "shown" but also from being captured/calculated, having this heavy impact. So sure, another "workaround" would be to ensure that the IP of someone experiencing the problem was NOT in the debugging IP list. But as many know, if there is NO IP in the debugging IP list, then EVERYONE running requests against the CF instance could experience this impact, assuming debugging is on. Naturally, one would not expect anyone to leave that on in prod. But again he was doing this in dev, where it's reasonable to have it on. Our surprise was that even with showdebugoutput off, it was having the impact. (And I do recall seeing this in the past but thought it had been addressed previously.)
Comment by Charlie Arehart
116 | February 09, 2018 05:40:50 PM GMT
Ken/Charlie, Can you pls. share some specifics. What is the max, min and metaspace size of your JVM heap. How long does it take for you to run into a "GC limit exceeded" error? What classes involved in collecting debugging did you see in the thread dump (pls share the fully qualified class name(s)) I tried to simulate the issue by hitting some simple CFMLs (involving some CF data structures and CFCs) with multiple concurrent user threads with jMeter, with xmx set to 512, for about 25 mins, but did not see any memory leaks. This was on CF2016u6, without any page level debug setting and request debugging enabled. Can you also share a little more info the nature of the application you are using, apart from the fact that it is using lots for loops and components.
27532 | April 16, 2018 06:23:29 PM GMT
Ken/Charlie, can you pls. check out my last comment. We need those details to narrow things down.
29462 | August 10, 2018 10:17:45 AM GMT
I am traveling this week and will be home on Monday the 13th. I will send you the requested information then. Thank you very much! Ken
Comment by Kenneth Gladden
29467 | August 10, 2018 05:48:40 PM GMT
Server Java memory: Minimum JVM Heap Size (in MB) 1024, Maximum JVM Heap Size (in MB) 4096. JVM Arguments: -XX:MaxMetaspaceSize=1024m -XX:+UseParallelOldGC -Xbatch Program begins with: <cfsetting showdebugoutput="false" > Start At: 5:16:45 PM PDT. Aug 13, 2018 18:28:26 PM Error [http-nio-8500-exec-5] - GC overhead limit exceeded The specific sequence of files included or processed is: D:\ColdFusion2016\cfusion\wwwroot\Kibbage\PokerStats\PokerWins.cfm'' Crashed after 1 hour and 12 minutes. Then unchecked: Enable Request Debugging Output on server. Reran and it ran to completion. Start At: 7:40:07 PM PDT, End At: 8:18:34 PM PDT, took 38 minutes Expectation is that using showdebugoutput="false" would be the same as not setting Enable Request Debugging Output on server.
Comment by Kenneth Gladden
29489 | August 14, 2018 03:41:30 AM GMT
What does PRNeedInfo mean? Do you need more information? If so what do you need?
Comment by Kenneth Gladden
29518 | August 16, 2018 05:19:20 PM GMT
Ken, I'm not able to force the memory outage even with showdebugoutput set to true... and I left the server on load for close to 24 hours. My debugger was configured with the local IP Address. Are you hitting your's from a remote client? Could you share the test application with which you can reproduce the memory outage, or perhaps some additional details on what it is doing in that application so that I can try and simulate the same at my end. As there anything besides that differential, that tells you that the debugging info is still being collected.. like memory profile logs ?
29532 | August 17, 2018 07:27:31 AM GMT
Ken, haven't heard back from you. can you check my last comment for the information I need. 
29647 | August 30, 2018 07:35:25 AM GMT
  closing this for the lack of further input. Ken, if you can share the stack trace that contains the long-running request was involved in calls to the Java classes involved in generating the CF debug output, we can revisit this. You can share that here or mail that to me at pnayak@adobe.com
29660 | September 04, 2018 06:45:38 AM GMT
Hmm. This is odd. While I got emails about comments added here between Aug 10 and 16, I never got any email about the next 3 (Aug 17, 30, and Sep 4). I have just pinged Ken by email to ask if he had gotten them. If not, then I suspect that's why he never replied. It's certainly frustrating when this system fails to email us. I can say with certainty that it's not that the mail ended up in spam or anything in my email client--and again, I DID get the few before it. (Curiously, I did not get an email for the comment from Piyush in April, and again there was a long gap until our next interaction, for the same reason.)
Comment by Charlie Arehart
29669 | September 06, 2018 09:28:16 PM GMT
I am having the exact same problems with emails that Charlie is having. I did not see any emails after the 16th. I can gladly send you a zip file with all of the source code if you can tell me how to do that. Can you tell me how to send you a zip file?
Comment by Kenneth Gladden
29670 | September 06, 2018 09:55:48 PM GMT
Ken, I'd suggest you share the stack trace from the thread dump where you see the debugging info being collected first. If that gets me nowhere we can move on to your source code. You can zip up the content and share the attachment either here (at the bug tracker portal... believe there must be an option for that) or mail that to me at [pnayak@adobe.com|mailto:pnayak@adobe.com]. If you choose to send via mail, please rename the attachment extension to .txt. That should get it though the mail scanner.
29672 | September 07, 2018 11:46:41 AM GMT
Here you go: "http-nio-8500-exec-5" prio=5 tid=167 RUNNABLE at java.lang.Throwable.getStackTraceElement(Native Method) at java.lang.Throwable.getOurStackTrace(Throwable.java:827) at java.lang.Throwable.printStackTrace(Throwable.java:656) at java.lang.Throwable.printStackTrace(Throwable.java:721) at coldfusion.runtime.ExceptionInformation.<init>(ExceptionInformation.java:59) at coldfusion.debug.CFMLDebugger.template(CFMLDebugger.java:413) at coldfusion.debug.CFMLDebugger.template(CFMLDebugger.java:394) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:720) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:439) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:409) at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3097) at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3074) at cfPokerStatsCFC2ecfc1370645637$funcGETPAIRS.runFunction(D:\ColdFusion2016\cfusion\wwwroot\Kibbage\PokerStats\PokerStatsCFC.cfc:322) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:492) at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47) at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:425) at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:388) at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95) at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:339) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:234) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:650) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:439) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:409) at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3097) at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3074) at cfPokerStatsCFC2ecfc1370645637$funcGETRANK.runFunction(D:\ColdFusion2016\cfusion\wwwroot\Kibbage\PokerStats\PokerStatsCFC.cfc:954) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:492) at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47) at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:425) at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:388) at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95) at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:339) at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:234) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:650) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:439) at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:409) at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3097) at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3074) at cfPokerWins2ecfm2144874810.runPage(D:\ColdFusion2016\cfusion\wwwroot\Kibbage\PokerStats\PokerWins.cfm:98) at coldfusion.runtime.CfJspPage.invoke(CfJspPage.java:253) at coldfusion.tagext.lang.IncludeTag.handlePageInvoke(IncludeTag.java:737) at coldfusion.tagext.lang.IncludeTag.doStartTag(IncludeTag.java:573) at coldfusion.filter.CfincludeFilter.invoke(CfincludeFilter.java:65) at coldfusion.filter.IpFilter.invoke(IpFilter.java:45) at coldfusion.filter.ApplicationFilter.invoke(ApplicationFilter.java:505) at coldfusion.filter.RequestMonitorFilter.invoke(RequestMonitorFilter.java:43) at coldfusion.filter.MonitoringFilter.invoke(MonitoringFilter.java:40) at coldfusion.filter.PathFilter.invoke(PathFilter.java:153) at coldfusion.filter.LicenseFilter.invoke(LicenseFilter.java:30) at coldfusion.filter.ExceptionFilter.invoke(ExceptionFilter.java:94) at coldfusion.filter.BrowserDebugFilter.invoke(BrowserDebugFilter.java:78) at coldfusion.filter.ClientScopePersistenceFilter.invoke(ClientScopePersistenceFilter.java:28) at coldfusion.filter.BrowserFilter.invoke(BrowserFilter.java:38) at coldfusion.filter.NoCacheFilter.invoke(NoCacheFilter.java:60) at coldfusion.filter.GlobalsFilter.invoke(GlobalsFilter.java:38) at coldfusion.filter.DatasourceFilter.invoke(DatasourceFilter.java:22) at coldfusion.filter.CachingFilter.invoke(CachingFilter.java:62) at coldfusion.CfmServlet.service(CfmServlet.java:219) at coldfusion.bootstrap.BootstrapServlet.service(BootstrapServlet.java:89) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at coldfusion.monitor.event.MonitoringServletFilter.doFilter(MonitoringServletFilter.java:42) at coldfusion.bootstrap.BootstrapFilter.doFilter(BootstrapFilter.java:46) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at coldfusion.inspect.weinre.MobileDeviceDomInspectionFilter.doFilter(MobileDeviceDomInspectionFilter.java:121) at coldfusion.bootstrap.BootstrapFilter.doFilter(BootstrapFilter.java:46) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at sun.reflect.GeneratedMethodAccessor77.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:134) at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:763) at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:351) at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:214) at com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:800) at com.intergral.fusionreactor.j2ee.filter.FusionReactorCoreFilter.doFilter(FusionReactorCoreFilter.java:36) at sun.reflect.GeneratedMethodAccessor76.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:71) at sun.reflect.GeneratedMethodAccessor75.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:54) at com.intergral.fusionreactor.agent.pointcuts.NewFilterChainPointCut$1.invoke(NewFilterChainPointCut.java:41) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459) 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)
Comment by Kenneth Gladden
29675 | September 08, 2018 02:11:21 AM GMT
Hi all, IMO, current behavior is correct/expected. I just do not see a bug here.. I respectfully disagree w/: "Expectation is that using showdebugoutput="false" would be the same as not setting Enable Request Debugging Output on server." B/c CF cannot wait until mid-request (i.e. hitting a <cfsetting> tag) before deciding if it should've been _generating_ debug output for the request. Thanks!, -Aaron
Comment by Aaron Neff
29687 | September 11, 2018 08:42:30 PM GMT
Aaron, I think you're missing the point. If debugging output option is on on the server then CF should be generating the debug output. When CF sees the debug output "off" option then it needs to stop generating debug output. That is the whole point of having the option. You're welcome! Ken
Comment by Kenneth Gladden
29688 | September 11, 2018 08:55:21 PM GMT
I noticed the status changed to "Alpha"; what's that mean? Ken
Comment by Kenneth Gladden
29740 | September 26, 2018 12:09:59 AM GMT
Ken, This is under investigation. That status change was about when we intend to take up the fix in case this is found to be a bug.
29796 | October 17, 2018 10:44:51 AM GMT