Hey Guys,
I have an odd problem that has me stumped. In my app.cfc Caching is true for handlers and event, handlerindexautoreload is false. I’m only logging exceptions.
I’m running Fusion Reactor to troubleshoot this issue.
When i start the APP - a call to my main handler once the user is auth’d takes about 30MS - it renders a simple “select topic” screen. With a light load of users - gradually the call to that same page can go up to 3 seconds after about 24hrs. All other calls are via remoting - and none of those degrade over time, it’s just the call to my main handler…??
I’ve ruled that out a var scope issue.
Today, I discovered that I didn’t need to restart the APP, I simply needed to run ?fwreinit - and bam, the page goes back to 30MS. Then progressively becomes slower again.
Do any light bulbs go off for anyone - has anyone encountered anything like this before?
Sounds interesting. What does FR show the request is doing if you pull a stack trace during its execution? Since 3 seconds is still fairly short to get a stack trace before it ends, you can set up a simple JMeter script to just keep hitting it (or use the trusty F5 test) to see what is the slow part.
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Thank you such a quick reply Brad!
It looks like this:
java.io.WinNTFileSystem.getBooleanAttributes(null:???)[Native Method]
java.io.File.exists(null:???)
lucee.commons.io.res.type.file.FileResource.exists(FileResource.java:503)
lucee.commons.io.res.util.ResourceUtil.exists(ResourceUtil.java:744)
lucee.runtime.PageSourceImpl.physcalExists(PageSourceImpl.java:687)
lucee.runtime.PageSourceImpl.exists(PageSourceImpl.java:681)
lucee.runtime.functions.system.ExpandPath.call(ExpandPath.java:70)
coldbox.system.frameworksupertype_cfc$cf.udfCall3(D:\inetpub\wwwroot\app\coldbox\system\FrameworkSupertype.cfc:403)
…
…
…
After tracing it back, it seems I had this in the app.cfc:
applicationHelper = “includes/helpers/ApplicationHelper.cfm”
(btw, just taking this app over in the last couple of weeks - didn’t think anything of this include!!)
This helper.cfm was empty… so I think what was happening was fileExiists(null) is somehow keeping a reference to the thread - and not letting go - hence the degrade over time?? Although there seems to be an even number of active threads - around 80 - throughout the day. Around 4000 actually started in a given day,
I have to wait till after hours to restart the service and see what happens when I remove this applicationHelper reference.
Or should a ?fwreinit – load the ColdBox settings completely?
That’s interesting. If you take several stack traces in a row, are they all running that fileExists() check?
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Yes, they most certainly are… All of the slow running active threads hang at this point… After removing the applicationHelper reference it appears the slow down has stopped. The page is now consistently taking between 30ms and 60ms. I’ll confirm whether or not this was in fact the culprit after users hit the app tomorrow.
Cheers!
I’m quite curious to find out. Excessive file system IO can always be a drag, but I wouldn’t expect it to change over time and get slower. Do you notice any particular jump in memory or CPU when the site slows down?
I also noticed the includeUDF() method in the frameworksupertype doesn’t do any caching, so it potentially runs 6 fileExists() checks every time. I can imagine some scenarios in which an application helper might be dynamic but it seems we should cache the lookup for those.
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Yes, as the time per request increases, the CPU jumps. The longer the delay the higher - around 3.5 seconds, the CPU is @ 100%.
So, the slow down is still happening - it’s gone from 30MS to now 150MS. The includeUDF is no longer being called but hear you on caching, makes sense.
I’ll do as you suggested originally, and write a JMeter script at work tomorrow morning, so I can capture stack traces. I wonder what it is! 
Yep, performance issues can be like whack-a-mole. You find the slowest thing, remove it, and see what else pops up.
If the next thing is also file IO I would would check the disk subsystem so see what the IO latencies are.
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
I hear you. Go figure, no users today - CS have the day off - so pulled off to work on other things. Will get back to this asap and report back. Disk IO, good idea. Many Thanks!
Ok, so capturing the thread, even though the applicationHelper reference is now empty in my app.cfc, somehow the includeUdf() method is still being called? I’m commenting out the call to the method on FrameworkSupertype.cfc;450
I’ll report back tomorrow evening to see if this prevents the slow down. Is there anything else I might be missing that’s looks suspect in the dump below?
lucee.runtime.component.MemberSupport.getAccess(MemberSupport.java:44)
lucee.runtime.ComponentImpl.isAccessible(ComponentImpl.java:842)
lucee.runtime.ComponentImpl.getMember(ComponentImpl.java:835)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:521)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.frameworksupertype_cfc$cf.udfCall3(D:\inetpub\wwwroot\app\coldbox\system\FrameworkSupertype.cfc:402)
coldbox.system.frameworksupertype_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\FrameworkSupertype.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.type.scope.UndefinedImpl.call(UndefinedImpl.java:766)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.frameworksupertype_cfc$cf.udfCall3(D:\inetpub\wwwroot\app\coldbox\system\FrameworkSupertype.cfc:450)
coldbox.system.frameworksupertype_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\FrameworkSupertype.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.type.scope.UndefinedImpl.call(UndefinedImpl.java:766)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.web.renderer_cfc$cf.udfCall1(D:\inetpub\wwwroot\app\coldbox\system\web\Renderer.cfc:102)
coldbox.system.web.renderer_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\web\Renderer.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:216)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:642)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1773)
lucee.runtime.tag.Invoke.doComponent(Invoke.java:221)
lucee.runtime.tag.Invoke.doEndTag(Invoke.java:194)
coldbox.system.ioc.builder_cfc$cf.udfCall1(D:\inetpub\wwwroot\app\coldbox\system\ioc\Builder.cfc:127)
coldbox.system.ioc.builder_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\ioc\Builder.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:641)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.ioc.injector_cfc$cf.udfCall1(D:\inetpub\wwwroot\app\coldbox\system\ioc\Injector.cfc:288)
coldbox.system.ioc.injector_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\ioc\Injector.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:641)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.ioc.scopes.noscope_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\ioc\scopes\NoScope.cfc:31)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:641)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.ioc.injector_cfc$cf.udfCall1(D:\inetpub\wwwroot\app\coldbox\system\ioc\Injector.cfc:261)
coldbox.system.ioc.injector_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\ioc\Injector.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:641)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.web.controller_cfc$cf.udfCall1(D:\inetpub\wwwroot\app\coldbox\system\web\Controller.cfc:124)
coldbox.system.web.controller_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\web\Controller.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:641)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.bootstrap_cfc$cf.udfCall1(D:\inetpub\wwwroot\app\coldbox\system\Bootstrap.cfc:216)
coldbox.system.bootstrap_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\Bootstrap.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.type.scope.UndefinedImpl.call(UndefinedImpl.java:766)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
coldbox.system.bootstrap_cfc$cf.udfCall1(D:\inetpub\wwwroot\app\coldbox\system\Bootstrap.cfc:353)
coldbox.system.bootstrap_cfc$cf.udfCall(D:\inetpub\wwwroot\app\coldbox\system\Bootstrap.cfc:???)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:641)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:742)
lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1586)
application_cfc$cf.udfCall(D:\inetpub\wwwroot\app\Application.cfc:47)
lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:111)
lucee.runtime.type.UDFImpl._call(UDFImpl.java:328)
lucee.runtime.type.UDFImpl.call(UDFImpl.java:229)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:641)
lucee.runtime.ComponentImpl._call(ComponentImpl.java:524)
lucee.runtime.ComponentImpl.call(ComponentImpl.java:1760)
lucee.runtime.listener.ModernAppListener.call(ModernAppListener.java:405)
lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:131)
lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:35)
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2254)
lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2221)
lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:456)
lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:47)
javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
sun.reflect.GeneratedMethodAccessor36.invoke(null:???)
sun.reflect.DelegatingMethodAccessorImpl.invoke(null:???)
java.lang.reflect.Method.invoke(null:???)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:97)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doNext(FusionReactorRequestHandler.java:472)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doHttpServletRequest(FusionReactorRequestHandler.java:312)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.doFusionRequest(FusionReactorRequestHandler.java:192)
com.intergral.fusionreactor.j2ee.filter.FusionReactorRequestHandler.handle(FusionReactorRequestHandler.java:507)
com.intergral.fusionreactor.j2ee.filter.FusionReactorCoreFilter.doFilter(FusionReactorCoreFilter.java:36)
sun.reflect.GeneratedMethodAccessor37.invoke(null:???)
sun.reflect.DelegatingMethodAccessorImpl.invoke(null:???)
java.lang.reflect.Method.invoke(null:???)
com.intergral.fusionreactor.j2ee.filterchain.WrappedFilterChain.doFilter(WrappedFilterChain.java:79)
sun.reflect.GeneratedMethodAccessor40.invoke(null:???)
sun.reflect.DelegatingMethodAccessorImpl.invoke(null:???)
java.lang.reflect.Method.invoke(null:???)
com.intergral.fusionreactor.agent.filter.FusionReactorStaticFilter.doFilter(FusionReactorStaticFilter.java:53)
com.intergral.fusionreactor.agent.pointcuts.NewFilterChainPointCut$1.invoke(NewFilterChainPointCut.java:41)
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:???)
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)
org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:188)
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.doRun(AprEndpoint.java:2466)
org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run(AprEndpoint.java:2455)
- locked <0x5960a535> (a org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper)
java.util.concurrent.ThreadPoolExecutor.runWorker(null:???)
java.util.concurrent.ThreadPoolExecutor$Worker.run(null:???)
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
java.lang.Thread.run(null:???)
Locked ownable synchronizers:
- java.util.concurrent.ThreadPoolExecutor$Worker@1d77398
Can you dump out controller.getSetting( “applicationHelper” ) and see what the setting is?
Also check you don’t have modules set to auto-reload.
It just occurred to me that it’s possible your modules are reloading a lot and they keep adding their mix helper over and over again to the array and there is a huge list of (duplicate) files being included. That would definitely cause a slowdown over time that a reinit would fix!
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Ok, so I’ve confirmed that the slow down is no longer happening - page load is now steady between 30ms and 60ms after commenting out the call to includeUdf(). I have one of the QA machines running without the update - I’ll dump out the appHelper in the morning - though Module reload is set to false… I’m interested to see what it looks like. Your theory sounds very plausible - an ever growing array… Thank you!
Yes, let us know if that is the culprit so we can create a ticket to enhance includeUDF()
Luis Majano
CEO
Ortus Solutions, Corp
www.ortussolutions.com
P/F: 1-888-557-8057
Direct: (909) 248-3408
ColdBox Platform: http://www.coldbox.org
ContentBox Platform: http://www.gocontentbox.org
Linked In: http://www.linkedin.com/pub/3/731/483
Social: twitter.com/ortussolutions | twitter.com/coldbox | twitter.com/lmajano | twitter.com/gocontentbox
Apologies for the delay - I was out for the past few days. Ok, so Brad was right - I have over 6000 entries and climbing with each page load - the entries are:
/modules/cbcompat/includes/mixins.cfm
See attached snap.
Cheers!
Ouch, it looks like I fixed that 5 months ago, but never updated the zip file download. Please run “update cbcompat” from CommandBox to get the latest version.
Now, that being said-- you shouldn’t have been getting the module’s configure method running that many times unless you have module auto-reload enabled. Can you check the setting in config/ColdBox.cfc for that? It really can slow down each request and cause issues if you have a lot of modules and they’re being reloaded every single request.
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
This is most likely on my side (although I did try from two different locations) - thought I’d mention just in case - I’m seeing a connection failure running the update:
875:
876: // Verify in ForgeBox
877: var fbData = forgebox.getEntry( arguments.slug );
878: // Verify if we are outdated, internally isNew() parses the incoming strings
879: var isOutdated = semanticVersion.isNew( current=value.version, target=fbData.version );
Syntax Error, invalid Expression [Connection Failure]
at railo.runtime.interpreter.CFMLExpressionInterpreter.interpret(CFMLExpressionInterpreter.java:201):201
Ah, yes, autoReload is set to true for Modules - ok - no winder this hasn’t been more of an issue for others.
Our servers were offline earlier which rendered ForgeBox inaccessible. Please try again if you haven’t already.
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Yes, everything looks good. Thank you for your time Brad!
