Is report execution times turned off under debugging in the administrator?
Happy Connecting. Sent from my Sprint Samsung Galaxy S® 5
Nope, it’s turned on.
Turn it off and leave it off 
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Tried that, didn’t make any difference
I tried CFWheels and their startup time isn’t that much better (~35 secs).
I think it’s just my machine not having enough grunt, as the cpu is Core 2 Duo, which is ancient.
Use Fusion Reactor and pull some stack traces while it’s loading to pinpoint what the JVM
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Before I try to delve further into this, can you please give me an idea of how far off the mark is a startup time of 50 seconds on my machine comparing to a typical CB set up on machines with similar spec (Core2Duo, Windows 7 Pro)?
Note that the 50-second is only for the very first time (after a CF server restart) the app loads up. All subsequent page loads (without fwreinit) are quick (< 2 seconds).
Thanks.
I have a quad core I5. When I spin up a CommandBox server and a new app skeleton the initial load take around 3 seconds and every request after is pretty much instant.
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Damn, that’s too big a difference to be put down to the cpu spec. I’ll do some more digging and report back what I find.
Brad, are you using Railo?
I’ve just tried Railo and I’m getting similar startup time as you (< 5 seconds).
I guess the gap between Railo and ColdFusion just got bigger in terms of performance? I don’t remember it being this bad.
I used the Lucee server built into CommandBox. (Just CD into the web root and type “start” ).
Adobe CF still shouldn’t be that slow.Have you installed Fusion reactor to see what it’s doing?
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 the execution times from CF’s debug output:
Total Time Avg Time Count Template
32599 ms 32599 ms 1 CFC[ C:/test/Application.cfc | onApplicationStart() ] from C:/test/Application.cfc
28419 ms 28419 ms 1 CFC[ C:/test/coldbox/system/Bootstrap.cfc | loadColdbox() ] from C:/test/coldbox/system/Bootstrap.cfc
13303 ms 13303 ms 1 CFC[ C:/test/coldbox/system/web/Controller.cfc | INIT(C:/test/, cbController) ] from C:/test/coldbox/system/web/Controller.cfc
11986 ms 11986 ms 1 CFC[ C:/test/coldbox/system/web/services/LoaderService.cfc | loadApplication() ] from C:/test/coldbox/system/web/services/LoaderService.cfc
8302 ms 8302 ms 1 CFC[ C:/test/Application.cfc | onRequestStart(/index.cfm) ] from C:/test/Application.cfc
8301 ms 8301 ms 1 CFC[ C:/test/coldbox/system/Bootstrap.cfc | onRequestStart(/index.cfm) ] from C:/test/coldbox/system/Bootstrap.cfc
5355 ms 1785 ms 3 CFC[ C:/test/coldbox/system/ioc/config/Mapping.cfc | process(binder = CFC: coldbox.system.ioc.config.DefaultBinder, injector = CFC: coldbox.system.ioc.Injector) ] from C:/test/coldbox/system/ioc/config/Mapping.cfc
4916 ms 4916 ms 1 CFC[ C:/test/coldbox/system/web/Controller.cfc | getRenderer() ] from C:/test/coldbox/system/web/Controller.cfc
4915 ms 4915 ms 1 CFC[ C:/test/coldbox/system/ioc/Injector.cfc | getInstance(Renderer@coldbox) ] from C:/test/coldbox/system/ioc/Injector.cfc
4479 ms 4479 ms 1 CFC[ C:/test/coldbox/system/ioc/Injector.cfc | init([complex value], CFC: coldbox.system.web.Controller) ] from C:/test/coldbox/system/ioc/Injector.cfc
4159 ms 2080 ms 2 CFC[ C:/test/coldbox/system/ioc/scopes/NoScope.cfc | getFromScope(CFC: coldbox.system.ioc.config.Mapping, [complex value]) ] from C:/test/coldbox/system/ioc/scopes/NoScope.cfc
3971 ms 3971 ms 1 CFC[ C:/test/coldbox/system/ioc/Injector.cfc | autowire(target = CFC: coldbox.system.web.Renderer, mapping = CFC: coldbox.system.ioc.config.Mapping) ] from C:/test/coldbox/system/ioc/Injector.cfc
3932 ms 1966 ms 2 CFC[ C:/test/coldbox/system/ioc/Builder.cfc | buildDSLDependency(definition = [complex value], targetID = Renderer@coldbox, targetObject = CFC: coldbox.system.web.Renderer) ] from C:/test/coldbox/system/ioc/Builder.cfc
3920 ms 3920 ms 1 CFC[ C:/test/coldbox/system/ioc/Injector.cfc | getInstance(HTMLHelper@coldbox) ] from C:/test/coldbox/system/ioc/Injector.cfc
3826 ms 3826 ms 1 CFC[ C:/test/coldbox/system/web/services/LoaderService.cfc | createDefaultLogBox() ] from C:/test/coldbox/system/web/services/LoaderService.cfc
3607 ms 3607 ms 1 CFC[ C:/test/coldbox/system/core/util/Util.cfc | getInheritedMetaData(coldbox.system.core.dynamic.HTMLHelper, [complex value]) ] from C:/test/coldbox/system/core/util/Util.cfc
3464 ms 3464 ms 1 CFC[ C:/test/coldbox/system/cache/CacheFactory.cfc | init(CFC: coldbox.system.cache.config.CacheBoxConfig, CFC: coldbox.system.web.Controller) ] from C:/test/coldbox/system/cache/CacheFactory.cfc
1677 ms 1677 ms 1 CFC[ C:/test/coldbox/system/logging/LogBox.cfc | INIT(CFC: coldbox.system.logging.config.LogBoxConfig, CFC: coldbox.system.web.Controller) ] from C:/test/coldbox/system/logging/LogBox.cfc
1617 ms 1617 ms 1 CFC[ C:/test/coldbox/system/web/Controller.cfc | runEvent(defaultEvent = true) ] from C:/test/coldbox/system/web/Controller.cfc
1499 ms 1499 ms 1 CFC[ C:/test/coldbox/system/web/services/HandlerService.cfc | getHandler(CFC: coldbox.system.web.context.EventHandlerBean, CFC: coldbox.system.web.context.RequestContext) ] from C:/test/coldbox/system/web/services/HandlerService.cfc
1315 ms 1315 ms 1 CFC[ C:/test/coldbox/system/ioc/config/DefaultBinder.cfc | map(HTMLHelper@coldbox) ] from C:/test/coldbox/system/ioc/config/DefaultBinder.cfc
1104 ms 1104 ms 1 CFC[ C:/test/coldbox/system/web/services/RequestService.cfc | requestCapture() ] from C:/test/coldbox/system/web/services/RequestService.cfc
1053 ms 527 ms 2 CFC[ C:/test/coldbox/system/cache/providers/CacheBoxColdBoxProvider.cfc | configure() ] from C:/test/coldbox/system/cache/providers/CacheBoxColdBoxProvider.cfc
1032 ms 1032 ms 1 CFC[ C:/test/coldbox/system/web/services/RequestService.cfc | onConfigurationLoad() ] from C:/test/coldbox/system/web/services/RequestService.cfc
989 ms 989 ms 1 CFC[ C:/test/coldbox/system/ioc/Injector.cfc | getInstance(handlers.Main) ] from C:/test/coldbox/system/ioc/Injector.cfc
851 ms 851 ms 1 CFC[ C:/test/coldbox/system/core/util/Util.cfc | getInheritedMetaData(coldbox.system.web.Renderer, [complex value]) ] from C:/test/coldbox/system/core/util/Util.cfc
838 ms 838 ms 1 CFC[ C:/test/coldbox/system/core/util/Util.cfc | getInheritedMetaData(handlers.Main, [complex value]) ] from C:/test/coldbox/system/core/util/Util.cfc
781 ms 781 ms 1 CFC[ C:/test/coldbox/system/ioc/Builder.cfc | init(CFC: coldbox.system.ioc.Injector) ] from C:/test/coldbox/system/ioc/Builder.cfc
607 ms 607 ms 1 CFC[ C:/test/coldbox/system/web/Renderer.cfc | renderLayout(module = , viewModule = ) ] from C:/test/coldbox/system/web/Renderer.cfc
595 ms 595 ms 1 CFC[ C:/test/coldbox/system/logging/config/LogBoxConfig.cfc | INIT(CFCConfigPath = coldbox.system.web.config.LogBox) ] from C:/test/coldbox/system/logging/config/LogBoxConfig.cfc
522 ms 75 ms 7 CFC[ C:/test/coldbox/system/core/util/Util.cfc | getMixerUtil() ] from C:/test/coldbox/system/core/util/Util.cfc
434 ms 434 ms 1 CFC[ C:/test/coldbox/system/web/services/InterceptorService.cfc | registerInterceptionPoint(HandlerService, afterInstanceAutowire, CFC: coldbox.system.web.services.HandlerService) ] from C:/test/coldbox/system/web/services/InterceptorService.cfc
360 ms 360 ms 1 CFC[ C:/test/coldbox/system/web/services/InterceptorService.cfc | INIT(CFC: coldbox.system.web.Controller) ] from C:/test/coldbox/system/web/services/InterceptorService.cfc
335 ms 112 ms 3 CFC[ C:/test/coldbox/system/ioc/Injector.cfc | buildInstance(CFC: coldbox.system.ioc.config.Mapping, [complex value]) ] from C:/test/coldbox/system/ioc/Injector.cfc
303 ms 303 ms 1 C:/test/layouts/Main.cfm
264 ms 264 ms 1 CFC[ C:/test/coldbox/system/ioc/scopes/Singleton.cfc | getFromScope(CFC: coldbox.system.ioc.config.Mapping, [complex value]) ] from C:/test/coldbox/system/ioc/scopes/Singleton.cfc
256 ms 256 ms 1 CFC[ C:/test/coldbox/system/logging/LogBox.cfc | getLogger(CFC: coldbox.system.cache.CacheFactory) ] from C:/test/coldbox/system/logging/LogBox.cfc
231 ms 116 ms 2 CFC[ C:/test/coldbox/system/cache/providers/CacheBoxColdBoxProvider.cfc | init() ] from C:/test/coldbox/system/cache/providers/CacheBoxColdBoxProvider.cfc
231 ms 231 ms 1 CFC[ C:/test/coldbox/system/ioc/config/DefaultBinder.cfc | loadDataDSL() ] from C:/test/coldbox/system/ioc/config/DefaultBinder.cfc
146 ms 146 ms 1 CFC[ C:/test/coldbox/system/web/services/HandlerService.cfc | onConfigurationLoad() ] from C:/test/coldbox/system/web/services/HandlerService.cfc
125 ms 63 ms 2 CFC[ C:/test/coldbox/system/cache/policies/LRU.cfc | init(CFC: coldbox.system.cache.providers.CacheBoxColdBoxProvider) ] from C:/test/coldbox/system/cache/policies/LRU.cfc
121 ms 121 ms 1 CFC[ C:/test/coldbox/system/web/config/ApplicationLoader.cfc | loadConfiguration() ] from C:/test/coldbox/system/web/config/ApplicationLoader.cfc
116 ms 39 ms 3 CFC[ C:/test/coldbox/system/ioc/Builder.cfc | buildCFC(CFC: coldbox.system.ioc.config.Mapping, [complex value]) ] from C:/test/coldbox/system/ioc/Builder.cfc
114 ms 57 ms 2 CFC[ C:/test/coldbox/system/logging/LogBox.cfc | getLogger(CFC: coldbox.system.cache.policies.LRU) ] from C:/test/coldbox/system/logging/LogBox.cfc
113 ms 113 ms 1 CFC[ C:/test/coldbox/system/cache/store/ConcurrentStore.cfc | init(CFC: coldbox.system.cache.providers.CacheBoxColdBoxProvider) ] from C:/test/coldbox/system/cache/store/ConcurrentStore.cfc
93 ms 93 ms 1 CFC[ C:/test/coldbox/system/web/services/HandlerService.cfc | getRegisteredHandler(main.index) ] from C:/test/coldbox/system/web/services/HandlerService.cfc
I can’t see much from FusionReactor other than total time, memory used etc. Do I need to turn anything on to get it to give me more info?
First I would suggest turning off “Report Execution Times”. It is a performance killer.
[Note: Typo assistance courtesy of iPhone]
I suggested that in my first reply Jon but he said it didn’t make any difference. I don’t really believe it though-- report execution times is always a horrible performance killer and I would always recommend turning it off.
Sadly, I put in a ticket for Adobe to improve the performance of that setting but they couldn’t reproduce it.
https://bugbase.adobe.com/index.cfm?event=bug&id=3822982
Hmm, upon examining the ticket again, i see there was an additional reply and a “speculative fix”. I guess we’ll find out when CF12 ships
Nick, you need to use Fusion Reactor to pull some stack traces of the thread while it’s running to see what it’s doing.
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com
Actually, it may not have made a difference if the server wasn’t cycled after the setting was changed.
When you start up an app with execution times enabled, the CFC class files are compiled to byte code with the timers in them (or at least they were with CF9).
The only way to blow those out completely is to either cycle CF and let it recompile or manually wipe them out in CFAdmin.
I can absolutely confirm that unchecking “Report Execution Times” made no difference. I even tried unchecking all boxes in the “Debug Output Settings” page, cleared all caches, restarted CF server. Same result.
When I try to do stack tracing in FusionReactor, the stacks completely changes every time I refresh (about once every second), which means no single line of code as the smoking gun? Is there a way to dump the entire stack trace in FS?
Yes, you can do all threads under the “resources” section. Even though the stack may be different, look for patterns. For instance, is it always on a query, or on file system access, etc.
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 I tried my best to grab the stack traces for the request, but I’m not really sure what to look for.
I’ve attached the file (stacktrace.log).
stacktrace.log (310 KB)
Almost every single one of those threads was compiling CFML. What are you template caching settings set to? Is this a VM? What’s the CPU load during this time?
It’s as though CF isn’t caching any of the templates. Did you take these stacks immediately after clearing the template cache?
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 the first request after a CF restart, i.e. the first time the app loads up. I did mention this in one of my earlier replies
No it’s not a VM. The CPU loading is around 50% for the entire request.
is the site just as slow on subsequent requests? Are you saving templates to disk?
Thanks!
~Brad
ColdBox Platform Evangelist
Ortus Solutions, Corp
E-mail: brad@coldbox.org
ColdBox Platform: http://www.coldbox.org
Blog: http://www.codersrevolution.com