QoQ Thread Lock

[Rory]

Hello,

I'm experiencing a locking issue under load with query of queries that I'm hoping someone may have some insight on. I am able to reproduce the lock on queries that contain a group by or a count clause (there may be other scenarios, but these I can reliably reproduce). Below are two thread dump excerpts, the first from the thread doing the locking, and the second from the locked thread. I'm running 3.3.4.003 final. I'm not quite sure where to go from here. This is hard to reproduce but while under production load. Thank you for your help!

"ajp-bio-8009-exec-415" - Thread t@4176

   java.lang.Thread.State: RUNNABLE

at java.lang.Integer.intValue(Unknown Source)

at railo.runtime.op.Caster.toIntValue(Caster.java:680)

at railo.runtime.db.HSQLDBHandler.addTable(HSQLDBHandler.java:134)

at railo.runtime.db.HSQLDBHandler.__execute(HSQLDBHandler.java:345)

- locked <34d9efea> (a railo.commons.lang.SerializableObject)

at railo.runtime.db.HSQLDBHandler._execute(HSQLDBHandler.java:310)

at railo.runtime.db.HSQLDBHandler.execute(HSQLDBHandler.java:299)

at railo.runtime.tag.Query.executeQoQ(Query.java:607)

at railo.runtime.tag.Query.doEndTag(Query.java:445)

at core.controllers.main_cfc$cf._call000038(/var/www/affiliates/public/core/controllers/main.cfc:631)

at core.controllers.main_cfc$cf.udfCall(/var/www/affiliates/public/core/controllers/main.cfc:613)

at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:215)

at railo.runtime.type.UDFImpl._call(UDFImpl.java:434)

at railo.runtime.type.UDFImpl.callWithNamedValues(UDFImpl.java:377)

at railo.runtime.ComponentImpl._call(ComponentImpl.java:581)

at railo.runtime.ComponentImpl._call(ComponentImpl.java:502)

at railo.runtime.ComponentImpl.callWithNamedValues(ComponentImpl.java:1830)

at railo.runtime.util.VariableUtilImpl.callFunctionWithNamedValues(VariableUtilImpl.java:755)

at railo.runtime.util.VariableUtilImpl.callFunction(VariableUtilImpl.java:705)

at railo.runtime.interpreter.ref.func.UDFCall.getValue(UDFCall.java:52)

at railo.runtime.interpreter.CFMLExpressionInterpreter.interpret(CFMLExpressionInterpreter.java:187)

at railo.runtime.functions.dynamicEvaluation.Evaluate._call(Evaluate.java:76)

at railo.runtime.functions.dynamicEvaluation.Evaluate.call(Evaluate.java:69)

at railo.runtime.functions.dynamicEvaluation.Evaluate.call(Evaluate.java:22)

at corfield.framework_cfc$cf._6(/var/www/fw1/org/corfield/framework.cfc:1110)

at corfield.framework_cfc$cf.udfCall(/var/www/fw1/org/corfield/framework.cfc)

at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:215)

at railo.runtime.type.UDFImpl._call(UDFImpl.java:434)

at railo.runtime.type.UDFImpl.call(UDFImpl.java:384)

at railo.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:738)

at railo.runtime.PageContextImpl.getFunction(PageContextImpl.java:1480)

at corfield.framework_cfc$cf._4(/var/www/fw1/org/corfield/framework.cfc:623)

at corfield.framework_cfc$cf.udfCall(/var/www/fw1/org/corfield/framework.cfc)

at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:215)

at railo.runtime.type.UDFImpl._call(UDFImpl.java:434)

at railo.runtime.type.UDFImpl.call(UDFImpl.java:384)

at railo.runtime.ComponentImpl._call(ComponentImpl.java:580)

at railo.runtime.ComponentImpl._call(ComponentImpl.java:502)

at railo.runtime.ComponentImpl.call(ComponentImpl.java:1815)

at railo.runtime.listener.ModernAppListener.call(ModernAppListener.java:349)

at railo.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:174)

at railo.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:23)

at railo.runtime.PageContextImpl.execute(PageContextImpl.java:2035)

at railo.runtime.PageContextImpl.execute(PageContextImpl.java:2002)

at railo.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:297)

at railo.loader.servlet.CFMLServlet.service(CFMLServlet.java:32)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:225)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)

at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)

at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:927)

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)

at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:200)

at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:565)

at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:307)

- locked <4aae8a9d> (a org.apache.tomcat.util.net.SocketWrapper)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

   Locked ownable synchronizers:

- locked <90e6fb9> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

"ajp-bio-8009-exec-429" - Thread t@4237

   java.lang.Thread.State: BLOCKED

at railo.runtime.db.HSQLDBHandler.__execute(HSQLDBHandler.java:322)

- waiting to lock <34d9efea> (a railo.commons.lang.SerializableObject) owned by "ajp-bio-8009-exec-415" t@4176

at railo.runtime.db.HSQLDBHandler._execute(HSQLDBHandler.java:310)

at railo.runtime.db.HSQLDBHandler.execute(HSQLDBHandler.java:299)

at railo.runtime.tag.Query.executeQoQ(Query.java:607)

at railo.runtime.tag.Query.doEndTag(Query.java:445)

at core.views.main.apptest_cfm$cf.call(/var/www/affiliates/public/core/views/main/apptest.cfm:17)

at railo.runtime.PageContextImpl.doInclude(PageContextImpl.java:771)

at railo.runtime.PageContextImpl.doInclude(PageContextImpl.java:746)

at corfield.framework_cfc$cf._7(/var/www/fw1/org/corfield/framework.cfc:1368)

at corfield.framework_cfc$cf.udfCall(/var/www/fw1/org/corfield/framework.cfc)

at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:215)

at railo.runtime.type.UDFImpl._call(UDFImpl.java:434)

at railo.runtime.type.UDFImpl.call(UDFImpl.java:384)

at railo.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:738)

at railo.runtime.PageContextImpl.getFunction(PageContextImpl.java:1480)

at corfield.framework_cfc$cf._4(/var/www/fw1/org/corfield/framework.cfc:665)

at corfield.framework_cfc$cf.udfCall(/var/www/fw1/org/corfield/framework.cfc)

at railo.runtime.type.UDFImpl.implementation(UDFImpl.java:215)

at railo.runtime.type.UDFImpl._call(UDFImpl.java:434)

at railo.runtime.type.UDFImpl.call(UDFImpl.java:384)

at railo.runtime.ComponentImpl._call(ComponentImpl.java:580)

at railo.runtime.ComponentImpl._call(ComponentImpl.java:502)

at railo.runtime.ComponentImpl.call(ComponentImpl.java:1815)

at railo.runtime.listener.ModernAppListener.call(ModernAppListener.java:349)

at railo.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:174)

at railo.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:23)

at railo.runtime.PageContextImpl.execute(PageContextImpl.java:2035)

at railo.runtime.PageContextImpl.execute(PageContextImpl.java:2002)

at railo.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:297)

at railo.loader.servlet.CFMLServlet.service(CFMLServlet.java:32)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:225)

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)

at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)

at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:927)

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)

at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:200)

at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:565)

at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:307)

- locked <1f879912> (a org.apache.tomcat.util.net.SocketWrapper)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at java.lang.Thread.run(Unknown Source)

   Locked ownable synchronizers:

- locked <7f527ce9> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

[Rory]

To be more specific as to why this is a problem... completely separate scripts with different QoQ statements from difference requests appear to be single threaded at the QoQ execution stage. This is an issue on a high volume production server as all request threads are queuing. 

[Igal @ getRailo.org]

are you doing any locking yourself?

can you post a sample of the code you're running?

[Rory]

Hi Igal,

I am not locking any code within CFML, but it appears to be locking within Java. The blocking query is specifically:

<cfquery name="rc.brandsOfCategory" dbtype="query">

SELECT DISTINCT(brands_name) AS name, brands_sefu_name AS sesname, count(brands_name) AS total, categories_name, categories_sefu_name

FROM request.AppStoreReference.storeProducts

WHERE categories_sefu_name = '#rc.filterCategorySefu#'

<cfif structKeyExists(rc,"min") AND rc.min IS NOT "" AND structKeyExists(rc,"max") AND rc.max IS NOT "">

AND products_price > #rc.min#

AND productS_price < #rc.max#

</cfif>

GROUP BY brands_name, brands_sefu_name, categories_name, categories_sefu_name

</cfquery>

I've simplified the issue to happen in a QoQ with fake data, for example:

<cfquery name="test1" dbtype="query">

select count(test)

from testq

</cfquery>

This appears to happen with any QoQ with an aggregate function or group by. The following query against the same data would work and not block:

<cfquery name="test1" dbtype="query">

select *

from testq

</cfquery>

The offending call in the stack trace is:

at railo.runtime.db.HSQLDBHandler.__execute(HSQLDBHandler.java:322)

- waiting to lock <dacf1e5> (a railo.commons.lang.SerializableObject) owned by

I can see that the Java source is creating a Java jock at line 323:

https://github.com/getrailo/railo/blob/master/railo-java/railo-core/src/railo/runtime/db/HSQLDBHandler.java

synchronized(lock) { ...

I am not sure of the significance of this, or what considerations I should be making from the CFML side. The issue only appears to happen under high load when total thread count on the server is at it's highest so I have not been able to make a test case in a dev environment. This query under normal load situations executes at or close to 0ms.

Thanks for your help.

Rory

[Igal Sapir]

If you max out the threads available then maybe you should try some other optimizations like caching, load balancing, newer hardware, or ad-hoc data structures that will be optimized to the needs of your application.

--
typos, misspels, and other weird words brought to you courtesy of my mobile device.

[Rory]

Hi Igal,

I don't believe I am maxing the threads on the server, what I am seeing is locks of a Railo runtime resource by a single thread, and all other threads thereby waiting. The lock is coming from within the scope of the underlying Java class as far as I can tell. Do you know if QoQ is single threaded or what scenarios it is single threaded under? I can reproduce the lock in some QoQ's statements and not others.

[Nick S.]

We're seeing similar behavior on large queries (~100k) records. At one point, I was seeing "INSERT" statements being generated for each and every record in the FusionReactor debugging for a simple QoQ select statement and it's killing performance at the moment.. trying to get more details to post. 

[andyjackson]

We're seeing the same problem. When observing the railo server using Fusion Reactor, on occasion we see one request blocking a number of other requests. When looking at each request's stack trace, all open requests are blocking on executeQoQ. Each request thread appears to be attempting to access a lock that is still being held by the first request thread. In our case, the first offending request is running a large QoQ that takes a significant amount of time to complete and therefore creates a backup in any further request threads that attempt to perform a QoQ.

I believe Rory is right that the issue stems from the synchronization lock call on line 324 of HSQLDBHandler.java. Would the code function properly without this lock? What shared resource is being acquired here that requires the lock? Would it be possible to implement this function in a non-blocking way?

Large ColdFusion applications require a non-blocking QoQ implementation that can handle heavy concurrent usage. Otherwise it makes the convenience of QoQ nearly useless.

[Jim Cumming]

I know this topic is old and it's unlikely to ever be addressed. But I've had this happen to me now on a pretty simple qoq

SELECT contentID, menutitle, urltitle, url, level
FROM menuData
WHERE parentid = <cfqueryparam cfsqltype="cf_sql_varchar" value="#arguments.parentid#">
ORDER BY orderNo

I'm hoping that adding a  cachedwithin="#createTimeSpan(0,0,15,0)#" to the cfquery tag will rectify things