tracker issue | What iT iS dESign studios

Title:

Debug consumes memory even when showdebugoutput="false"

| View in Tracker

Status/Resolution/Reason: Closed/Fixed/Fixed

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 / 2020,0,01,314612

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 A.

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.

Comment by Piyush K.

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.

Comment by Piyush K.

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 G.

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 G.

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 G.

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 ?

Comment by Piyush K.

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. 

Comment by Piyush K.

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

Comment by Piyush K.

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 A.

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 G.

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.

Comment by Piyush K.

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 G.

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 N.

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 G.

29688 | September 11, 2018 08:55:21 PM GMT

I noticed the status changed to "Alpha"; what's that mean?
Ken

Comment by Kenneth G.

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.

Comment by Piyush K.

29796 | October 17, 2018 10:44:51 AM GMT

verified with b. 2020,0,01,314612
The functionality seems to be intact w/ the change.
page debugging info is displayed at the end of the page as expected w/ the showdebugoutput tag setting provided it is enabled in the server.  
same behavior w/ 2018,0,03,314033

test code:
<cfset applicationStop()>
<cfsetting showdebugoutput="false">
<cfoutput>#server.coldfusion.productversion#</cfoutput>

closing this since I was not able to reproduce the performance issue reported with this bug earlier.

Ken,
maybe you can try and see if this fixes your issue. Let me know if you'd like a patch with the changes. you can write to me at pnayak@adobe.com

Comment by Piyush K.

30952 | June 25, 2019 02:21:11 PM GMT

Wow, an oldie but a goodie, Piyush. Thanks for reviving it.

So first, what is it that you are asking Ken to "try"? Do you mean adding the showdebugoutput=false? He has said from the beginning that it IS in his code, but again he was still seeing impact from debugging. And I had confirmed that in my first comment last Feb (after I proposed he open the ticket) when I wrote, "Our surprise was that even with showdebugoutput off, it was having the impact".

Or do you mean the patch you refer to at the end? If so, Ken can certainly try that, but since you say you were "not able to reproduce the performance issue reported with this bug earlier", then I'm not clear on what the patch is supposed to "fix". 

You refer at the top of your comment to how "page debugging info is displayed at the end of the page as expected w/ the showdebugoutput tag setting provided it is enabled in the server." That is indeed normal behavior.

But that's not the point of this bug report. Instead, it was that Ken was seeing a memory impact of debugging being on (page would crash with oom error, with the stack trace referring to CF debug output classes), even though he HAD disabled it with CFSETTING. When he disabled the debug output (in the admin), the impact went away (page ran).

As I review all this again, it still seems there's confusion on the problem, let alone any solution. Let's revisit some key points, for those reading who care to follow along.

First, Aaron makes an interesting point: since the CFSETTING is a request-level runtime directive, it may be that the debugging we saw was from BEFORE that tag was hit. More on that in a moment. 

And Piyush, as for your saying you couldn't recreate the problem, well, maybe the nature of requests and load you're generating is simply not the same as Ken's.  Note he says "Run something that has lots of loops and calling CFCs to do some calculations millions of times." 

Of course, that's a bit vague in terms of repeatability. But Piyush you said, "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."  That said, I know you later asked him to share the code. I don't know if he did.

Then you asked him to share a stack trace, and he did. As I look more closely at it (above, from Sep 8 2018), I notice that the request that DOES show the debug classes being referred to while code is running at line 322 of D:\ColdFusion2016\cfusion\wwwroot\Kibbage\PokerStats\PokerStatsCFC.cfc, which was itself called as a method from line 954 of D:\ColdFusion2016\cfusion\wwwroot\Kibbage\PokerStats\PokerStatsCFC.cfc, which was invoked as a CFC from line 98 of D:\ColdFusion2016\cfusion\wwwroot\Kibbage\PokerStats\PokerWins.cfm. 

So, first (and getting back to Aaron's comment), where exactly is the cfsetting that is doing showdebugoutput=false? If it's above that line 90 of pokerwins.cfm (which calls the CFC), then we'd seem to now know it SHOULD not be gathering debugging info after that point, right?

And can you confirm, Ken, that there is no OTHER occurrence of that cfsetting which may be turning debugging ON, unexpectedly? that would certainly change everything about this ticket.

But if he confirms that it IS there, above that code, and there is no other that's turning it on, then we are back to teh original question: why would the debugging be happening when its set for the request to be off?

I notice also that there is no indication of that stack trace of any parent application.cfc or cfm, so it would seem that's not another source for confusion.

Hope this helps someone. Since it has indeed been a long-standing problem that SOME users DID seem to suffer impact when debug output was enabled, even when disabling it by code or not being in the IP list, this seems worth getting to the bottom of.

Comment by Charlie A.

30953 | June 25, 2019 03:53:06 PM GMT

tracker issue : CF-4201076

Debug consumes memory even when showdebugoutput="false"