Coldbox Performance times

Carlos · December 3, 2010, 6:51pm

Hello,
We just started looking into Coldbox and have worked through the
samples and trying to build a simple application to start. Right now
it's just a simple Hello World. We noticed using the samples it takes
about 1-2 seconds for each page request. Our simple Hello World takes
the same amount of time. We refreshed a few times and see the same
time.

We code our non-Coldbox Applications with an MVC pattern, but no
framework. We have a highly database driven website and the average
load time for these pages is about 500ms.

We were wondering if this 1-2 second overhead from Coldbox is normal?
I looked through some threads here and saw the mention of setting
these variables to false, but this had no effect:
    <Setting name="DebugMode" value="false"/>
    <Setting name="HandlersIndexAutoReload" value="false"/>
    <Setting name="ConfigAutoReload" value="false"/>

We are running Coldfusion v9 on Redhat ES5.

The top execution times we are seeing are below:
1856 ms 1856 ms 1 CFC[ /XXX/sitemap_advanced/Application.cfc |
onRequestStart(/sitemap_advanced/index.cfm) ] from /XXX/
sitemap_advanced/Application.cfc
647 ms 324 ms 2 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
services/HandlerService.cfc | getHandler(CFC:
coldbox.system.beans.EventHandlerBean, CFC:
coldbox.system.web.context.RequestContext) ] from /XXX/coldbox/
coldbox_3.0.0.RC1/system/web/services/HandlerService.cfc
416 ms 416 ms 1 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
Controller.cfc | runEvent(default = true) ] from /XXX/coldbox/
coldbox_3.0.0.RC1/system/web/Controller.cfc
400 ms 400 ms 1 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
services/ModuleService.cfc | reloadAll() ] from /XXX/coldbox/
coldbox_3.0.0.RC1/system/web/services/ModuleService.cfc
395 ms 395 ms 1 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
Controller.cfc | runEvent(Main.onRequestStart, true) ] from /XXX/
coldbox/coldbox_3.0.0.RC1/system/web/Controller.cfc
290 ms 145 ms 2 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/core/util/
Util.cfc | convertToColdBox(argumentCollection = [complex value]) ]
from /XXX/coldbox/coldbox_3.0.0.RC1/system/core/util/Util.cfc
169 ms 169 ms 1 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
Controller.cfc | getPlugin(Renderer) ] from /XXX/coldbox/
coldbox_3.0.0.RC1/system/web/Controller.cfc
167 ms 167 ms 1 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
services/PluginService.cfc | get(Renderer, false, , true) ] from /XXX/
coldbox/coldbox_3.0.0.RC1/system/web/services/PluginService.cfc
160 ms 53 ms 3 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
Controller.cfc | getPlugin(BeanFactory) ] from /XXX/coldbox/
coldbox_3.0.0.RC1/system/web/Controller.cfc
150 ms 50 ms 3 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/services/
PluginService.cfc | get(BeanFactory, false, , true) ] from /XXX/
coldbox/coldbox_3.0.0.RC1/system/web/services/PluginService.cfc
117 ms 117 ms 1 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/plugins/
Renderer.cfc | renderLayout() ] from /XXX/coldbox/coldbox_3.0.0.RC1/
system/plugins/Renderer.cfc
112 ms 112 ms 1 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/
services/RequestService.cfc | requestCapture() ] from /XXX/coldbox/
coldbox_3.0.0.RC1/system/web/services/RequestService.cfc
110 ms 28 ms 4 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/beans/
InterceptorState.cfc | process(CFC:
coldbox.system.web.context.RequestContext, [complex value]) ] from /
XXX/coldbox/coldbox_3.0.0.RC1/system/beans/InterceptorState.cfc
108 ms 54 ms 2 CFC[ /XXX/coldbox/coldbox_3.0.0.RC1/system/web/services/
InterceptorService.cfc | processState(afterHandlerCreation, [complex
value]) ] from /XXX/coldbox/coldbox_3.0.0.RC1/system/web/services/
InterceptorService.cfc

Thanks,
Carlos

Mark_Mandel · December 6, 2010, 12:01pm

Turn off Request Execution times.

Turning that on for any CFC heavy system will slow it to a crawl.

Mark

Chris_Carey · December 6, 2010, 12:04pm

If you're using coldbox autowiring, are you caching things like
gateways/service objects as singletons? If not you'll be recreating
them over and over which might be a bit slow. If you're not already
doing so you'll see a big performance boost from doing that.

Check out the cachebox debug panel and see what the memory is doing.
If it's very low on free memory then you may find that it's thrashing
the cache. If necessary allocate some more memory to the JVM. If you
haven't already, set the JVM args Xmx and Xms to the same value.

If you're running in a dev environment, do you have logging enabled?
If so check the levels -- things like the console appender can really
bog it down if you have it set to debug level. (I got a little
enthusiastic with logging and found this out the hard way after much
head scratching).

In terms of expected execution times, if of course depends on what
you're doing, but just by way of example the app I'm working on
currently manages this sort of request times in general use:

To generate a list of records from the database (via a service/
gateway):
600ms to reinit the framework (?fwreinit=1)
250ms for a view which isn't cached
60ms for a cached view

I did start off with longer delays but because I'm running in dev I
didn't have a whole lot of memory allocated to the JVM and that made a
big difference.

Carlos · December 6, 2010, 10:22pm

This helped greatly. The exact wording was Report Execution Times in
the CF admin in Debug Output Settings under Custom Debugging Output.
It decreased the time from 1-2 seconds to under 100ms. Thanks for the
quick responses!

lmajano · December 6, 2010, 10:25pm

Like Mark said, having request execution times is a big one, turn that off first. Then have the following settings to test production environment settings:

coldbox = {
debugmode=false,
configAutoReload = false,
HandlersIndexAutoReload = false,
HandlerCaching = true
};

modules = { autoReload = false };

Also, make sure that you disable the DEBUG level for logbox’s root logger.

I ran a similar test with a normal hello world and I get an average of: totalrequesttime=16ms

This is running on my Mac OS X, Apache, CF 9.0.1 with only 384mb assigned to heap.

Luis F. Majano
President
Ortus Solutions, Corp

ColdBox Platform: http://www.coldbox.org
Linked In: http://www.linkedin.com/pub/3/731/483
Blog: http://www.luismajano.com
IECFUG Manager: http://www.iecfug.com