CF 9 => CF11 Performance degradation - worker threads "Waiting on Condition"

Report · Sep 30, 2015

We are a very large ColdFusion house in Australia, we have been been supporting a ColdFusion app for the last 10 years and are having a performance issue that we have not seen before.

We upgraded from CF9 => CF 11 around a month ago and servers have around 1 week of up time before they experience this issue. We see it as very slow request times (average = around 30-60 seconds instead of <1 second).

Whilst the server is in this state, lots of threads are "Waiting on Condition", however until a traditional wait, there is nothing in the stack trace to indicate what resource is being waited for. A restart of the CF service immediately restores performance.

This graph (the orange line is avg execution time, blue is count requests) gives an idea of the severity of the problem. Also the affect of the restart (the tail of the orange line on the RHS)

GC logs indicate that it is not caused by STW gc.

Here you can see lots of workers Waiting for Condition (the purple bits). These stack traces (columns) were taken 2 seconds apart. The code that is in each frame changes, but as you can see, they almost always are Waiting for Condition.

The top of the stack traces are all similar - our CF code followed by some Java code. Nothing to indicate what the condition (object?) is that we are waiting on.

"ajp-bio-8014-exec-281" #70085 daemon prio=5 os_prio=0 tid=0x0000000074c73000 nid=0x21b0 waiting on condition [0x00000000487cb000]

java.lang.Thread.State: RUNNABLE

at cfCPStandard2ecfc1872558760$funcGETMAINCONTENTHEADER.runFunction(D:\JO3\jobOffice\sys\jo\core\de\templates\cp\CPStandard.cfc)

at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)

at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)

at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)

at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)

at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)

at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)

at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)

at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:2845)

at cfCPStandard2ecfc1872558760$funcLOADPAGEHEADER.runFunction(D:\JO3\jobOffice\sys\jo\core\de\templates\cp\CPStandard.cfc:54)

at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)

at coldfusion.filter.SilentFilter.invoke(SilentFilter.java:47)

at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)

at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)

at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)

at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)

at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)

at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)

at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)

at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)

at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)

at cfDisplayEngine2ecfc1810328208$funcPOSTPROCESS.runFunction(D:\JO3\jobOffice\sys\jo\core\m2plugin\DisplayEngine.cfc:52)

at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:487)

at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:420)

at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:383)

at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)

at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:334)

at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:231)

at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:643)

at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:432)

at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:402)

at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:2483)

at cfPluginManager2ecfc1495337580$funcPOSTPROCESS.runFunction(D:\JO3\jobOffice\MachII\framework\PluginManager.cfc:591)

When Performance is "good", we can get >4,000 requests per minute, when poor, we are lucky to get >10 requests completed per minute.

Here is a series of thread dumps when everything is good.

I'm not sure where to look from here, it appears that something in the JVM is causing Locking/Blocking/Waiting.

We are on CF11 on Windows, Java 1.8 U40.

Thanks,

dave

Report · Sep 30, 2015

Hi Dave,

That slowness could be tomcat tuning. This blog should be helpful.

http://blogs.coldfusion.com/post.cfm/coldfusion-11-iis-connector-tuning

HTH, Carl.

Report · Sep 30, 2015

We certainly see some "funkyiness" in the metrics.log for the connector - we figured this was affect and not cause - the first graph is measured in cf code - getTickCount() at the start and the end of request then the delta of those 2 values. Therefore, the requests graphed have made it through the connector and are executing in cf.

Report · Oct 01, 2015

Hi Dave,

Are there any warnings or errors in isapi_redirect.log about the time of the application slow down?

I still like the idea of tuning some tomcat settings. For what you describe with application working ok then slowing I am particularly keen on applying connection_pool_timeout in workers.properties and corresponding connectionTimeout in AJP section of server.xml.

If you do consider adjusting tomcat I have seen some folks use AJP-APR instead of AJP-BIO to good effect.

Regards, Carl.

Adobe Community

CF 9 => CF11 Performance degradation - worker threads "Waiting on Condition"