Thread blocking when using AsyncManager with database

Communities ColdBox HMVC
1

I am doing some testing with the new AsyncManager in Coldbox 6 with ACF 2016. When trying to execute a process that acesses the database I noticed that the performance was worse. When I did a thread dump, I see that the threads are blocking each other then trying to get a database connection. Below is the code I am using to test this.

I am guessing it may have something to do with sharing database connections accross threads but am not really sure. Any ideas are appreciated. I also tested in ACF 2018 with the same results. It seems to run fine using the runAsync() in ACF 2018.

var myExecutor = asyncManager.getExecutor("my-executor");
var futures = [
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor ),
    asyncManager.newFuture( function() { return getData(); }, myExecutor )
];

var myFuture = asyncManager.all( futures );

var results = myFuture.get();

Here is the getData() function. It does a basic select statement and has some logging to debug execution time.

private query function getData() {
    var timer1 = getTickCount();
    var result = queryExecute("select 1");
    var execTime = (getTickCount() - timer1) * 0.001;
    logger.debug("Executed getData() in #execTime# seconds");
    return result;
}

Here is my debug log.


"Information","pool-10-thread-5","01/29/21","07:47:47","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 1.12 seconds ExtraInfo: "

"Information","pool-10-thread-16","01/29/21","07:47:48","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 1.644 seconds ExtraInfo: "

"Information","pool-10-thread-15","01/29/21","07:47:49","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 2.282 seconds ExtraInfo: "

"Information","pool-10-thread-14","01/29/21","07:47:49","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 2.922 seconds ExtraInfo: "

"Information","pool-10-thread-13","01/29/21","07:47:50","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 3.577 seconds ExtraInfo: "

"Information","pool-10-thread-12","01/29/21","07:47:50","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 4.234 seconds ExtraInfo: "

"Information","pool-10-thread-11","01/29/21","07:47:51","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 4.866 seconds ExtraInfo: "

"Information","pool-10-thread-10","01/29/21","07:47:52","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 5.502 seconds ExtraInfo: "

"Information","pool-10-thread-9","01/29/21","07:47:52","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 6.126 seconds ExtraInfo: "

"Information","pool-10-thread-8","01/29/21","07:47:53","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 6.782 seconds ExtraInfo: "

"Information","pool-10-thread-7","01/29/21","07:47:54","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 7.429 seconds ExtraInfo: "

"Information","pool-10-thread-6","01/29/21","07:47:54","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 8.052 seconds ExtraInfo: "

"Information","pool-10-thread-2","01/29/21","07:47:55","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 8.716 seconds ExtraInfo: "

"Information","pool-10-thread-1","01/29/21","07:47:56","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 9.356 seconds ExtraInfo: "

"Information","pool-10-thread-3","01/29/21","07:47:56","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 9.999 seconds ExtraInfo: "

"Information","pool-10-thread-4","01/29/21","07:47:57","8CD941044A9B03648817E9FBE62AABA2","handlers.TestAsyncManager Executed getData() in 10.643 seconds ExtraInfo: "

And finally when doing a thread dump, I see a bunch of entries like this one.

"pool-10-thread-1"
	java.lang.Thread.State: BLOCKED
		at coldfusion.server.j2ee.sql.pool.JDBCPool.checkOut(JDBCPool.java:380)
		at coldfusion.server.j2ee.sql.pool.JDBCPool.requestConnection(JDBCPool.java:866)
		at coldfusion.server.j2ee.sql.pool.JDBCManager.requestConnection(JDBCManager.java:125)
		at coldfusion.server.j2ee.sql.JRunDataSource.getConnection(JRunDataSource.java:137)
		at coldfusion.sql.CFDataSource.getConnection(CFDataSource.java:44)
		at coldfusion.sql.DataSrcImpl.getCachedConnection(DataSrcImpl.java:156)
		at coldfusion.sql.DataSrcImpl.getConnection(DataSrcImpl.java:110)
		at coldfusion.sql.SqlImpl.execute(SqlImpl.java:363)
		at coldfusion.tagext.sql.QueryTag.executeQuery(QueryTag.java:1181)
		at coldfusion.tagext.sql.QueryTag.startQueryExecution(QueryTag.java:815)
		at coldfusion.tagext.sql.QueryUtils.executeQuery(QueryUtils.java:72)
		at coldfusion.runtime.CFPage.QueryExecute(CFPage.java:10165)
		at cfTestAsyncManager2ecfc1373059746$funcGETDATA.runFunction(C:\dev\MyApp\handlers\TestAsyncManager.cfc:13)
		at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:493)
		at coldfusion.runtime.UDFMethod$ReturnTypeFilter.invoke(UDFMethod.java:426)
		at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:389)
		at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
		at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:340)
		at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:235)
		at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:3697)
		at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:3677)
		at cfTestAsyncManager2ecfc1373059746$func_CF_ANONYMOUSCLOSURE_0.runFunction(C:\dev\MyApp\handlers\TestAsyncManager.cfc:27)
		at coldfusion.runtime.Closure.invoke(Closure.java:109)
		at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:389)
		at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
		at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:340)
		at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:235)
		at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:3697)
		at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:3677)
		at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3267)
		at coldfusion.runtime.CfJspPage._invoke(CfJspPage.java:3224)
		at cfSupplier2ecfc867635558$funcGET.runFunction(C:\dev\MyApp\coldbox\system\async\proxies\Supplier.cfc:35)
		at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:493)
		at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:389)
		at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95)
		at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:340)
		at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:235)
		at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:654)
		at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:443)
		at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:413)
		at coldfusion.runtime.java.CFCDynamicProxy.invoke(CFCDynamicProxy.java:157)
		at com.sun.proxy.$Proxy37.get(Unknown Source)
		at java.base@11.0.4/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700)
		at java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
		at java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
		at java.base@11.0.4/java.lang.Thread.run(Thread.java:834)
2

The code that is blocking is part of acf’s db connection pooling, so closed source and difficult to debug. I wonder if cloning the page context is causing cf to want to use the same db connection since it thinks all the threads are the same. Can you set the load context to false and see if it changes the behavior?

https://coldbox.ortusbooks.com/digging-deeper/promises-async-programming/async-pipelines-and-futures#coldfusion-cfml-app-context

1 Like
3

Changing the loadAppContext did not seem to make a difference. However, when testing that I noticed I was running my tests using fwreinit=1 in the URL. Once I removed that my first 2 requests were slow but all subsequent requests were fast. So I think the issue is only occuring the Executor creates a new thread.

I may not be uderstanding how it works under the hood. My executor has 20 threads. My test was running 16 processes asyncronously so I was seeing the blocking on the first 2 runs but not on subsequent requests. This is a step forward but the issue causes my application integration tests take much longer to run than when not using the Async processes. I am guessing maybe just an issue within ACF.

I appreciate the help and thanks for your work on these tools.

4

Hmm, having fwreinit can make things slower, but to be clear-- I wouldn’t’ expect that to have any bearing whatsoever on the locking semantics of Adobe CF under the hood so it feels like more of a red herring.

Interesting to hear that turning off the loadAppContext setting didn’t seem to make a difference. To be clear, are you saying than when that was turned off, the stack traces showed exactly like the OP-- blocked while acquiring a connection from the DB pool.

It’s normal to have some locking at the java level around the DB connection pool, but it should only affect “checking out” and “checking in” a connection. And assuming you are allowing more than one DB connection, this should not be a long operation. My assuption from your first post was that each subsequent thread was blocked until the prior thread had fully completed its query and returned the connection to the pool. Actually, if you can monitor how many connections exist for that datasoruce, that may help determine if they’re all using the same one. Lucee has debugging for this in the admin, but I’m not sure about Adobe CF. If this is SQL Server, you can run a trace on the DB and check which SPID each query came from and also confirm if they were serial or parallel.

Also, can you show what your code looks like with the loadAppContext setting so @lmajano can confirm if it’s being used correctly.

5

Also, if you can provide the full thread dump from the entire JVM while you’re seeing blocked threads, that will provide a lot more information about the threads doing the blocking and what they are processing at the moment. The JDBCPool.checkOut() method appears to be synchronized, which means that the blocking wouldn’t be specific to any part of a request, but just global to the pool if the method itself is what’s doing the blocking.

6

I was seeing the loadAppContext parameter in multiple places so I did a couple different things.

My executor definition n Colbox.cfc is this.

executors = {
    "my-executor" : {
        "type" : "fixed",
        "threads" : 20,
        "loadAppContext" : false
    }
};

And in defining the async processes I did this.

		var myExecuter = asyncManager.getExecutor("my-executor");
		var loadAppContext = false;
		var futures = [
			asyncManager.newFuture( value = function() { return getData(); },executor =  myExecuter, loadAppContext = loadAppContext ),
			asyncManager.newFuture( value = function() { return getData(); },executor =  myExecuter, loadAppContext = loadAppContext ),
			asyncManager.newFuture( value = function() { return getData(); },executor =  myExecuter, loadAppContext = loadAppContext ),
			asyncManager.newFuture( value = function() { return getData(); },executor =  myExecuter, loadAppContext = loadAppContext ),
			asyncManager.newFuture( value = function() { return getData(); },executor =  myExecuter, loadAppContext = loadAppContext ),

Let me know if something does not look correct. I have to step away for a bit but should have some time later to debug the connections on the sql server more. I will report back what I find out there.

Another thing to note in this test is that my database is on a different network. I have heard that this can cause delays in setting up the initial db connection.

Here is a link to the entire thread dump. It was too large to include in the reply.

1 Like
7

Excellent. Your code looks fine. I too noticed some confusing bits in the docs about exactly where to set that flag, but it looks like you’ve set it correct. I can confirm however, that I don’t think the app context is related at all to this since it’s defo just the fact that the checkout() method in Java is synchronized which means only a single thread can checkout a connection at a time. Normally, this is a very fast operation, but if fresh connections are being made, this can lock the entire connection pool until the current thread is done checking out their connection. This is one of many reasons I really dislike the heavy-handed nature of synchronized methods in java. There’s really no reason two or more threads can’t be creating a fresh connection at the same time. FWIW worth, Lucee’s connection pooling has the same issue,

So in that thread dump, every thread but one is basically just waiting to get access to call the checkout() method. And the one thread who is blocking the rest is right here:

"pool-229-thread-15"
	java.lang.Thread.State: TIMED_WAITING
		at java.base@11.0.4/java.lang.Object.wait(Native Method)
		at java.base@11.0.4/java.lang.Thread.join(Thread.java:1313)
		at coldfusion.server.j2ee.sql.pool.ConnectionRunner.fetchConnection(ConnectionRunner.java:43)
		at coldfusion.server.j2ee.sql.pool.JDBCPool.create(JDBCPool.java:556)
		at coldfusion.server.j2ee.sql.pool.JDBCPool._checkOut(JDBCPool.java:481)
		at coldfusion.server.j2ee.sql.pool.JDBCPool.checkOut(JDBCPool.java:387)
		at coldfusion.server.j2ee.sql.pool.JDBCPool.requestConnection(JDBCPool.java:866)
		at coldfusion.server.j2ee.sql.pool.JDBCManager.requestConnection(JDBCManager.java:125)
		at coldfusion.server.j2ee.sql.JRunDataSource.getConnection(JRunDataSource.java:137)

You can see it’s creating a new connection. Interestingly enough, the new connection itself seems to be created inside of another thread-- possibly to allow external connection timeouts to be enforced. The actual thread doing work is here:

"Thread-537"
	java.lang.Thread.State: RUNNABLE
		at java.base@11.0.4/java.util.zip.ZipFile$Source.hashN(ZipFile.java:1324)
		at java.base@11.0.4/java.util.zip.ZipFile$Source.getEntryPos(ZipFile.java:1546)
		at java.base@11.0.4/java.util.zip.ZipFile.getEntry(ZipFile.java:349)
		at java.base@11.0.4/java.util.zip.ZipFile$1.getEntry(ZipFile.java:1121)
		at java.base@11.0.4/java.util.jar.JarFile.getEntry0(JarFile.java:576)
		at java.base@11.0.4/java.util.jar.JarFile.getEntry(JarFile.java:506)
		at java.base@11.0.4/java.util.jar.JarFile.getJarEntry(JarFile.java:468)
		at java.base@11.0.4/jdk.internal.loader.URLClassPath$JarLoader.getResource(URLClassPath.java:929)
		at java.base@11.0.4/jdk.internal.loader.URLClassPath$JarLoader.findResource(URLClassPath.java:912)
		at java.base@11.0.4/jdk.internal.loader.URLClassPath.findResource(URLClassPath.java:291)
		at java.base@11.0.4/java.net.URLClassLoader$2.run(URLClassLoader.java:655)
		at java.base@11.0.4/java.net.URLClassLoader$2.run(URLClassLoader.java:653)
		at java.base@11.0.4/java.security.AccessController.doPrivileged(Native Method)
		at java.base@11.0.4/java.net.URLClassLoader.findResource(URLClassLoader.java:652)
		at coldfusion.bootstrap.BootstrapClassLoader.getResource(BootstrapClassLoader.java:314)
		at java.base@11.0.4/java.net.URLClassLoader.getResourceAsStream(URLClassLoader.java:322)
		at java.base@11.0.4/java.lang.Class.getResourceAsStream(Class.java:2651)
		at macromedia.sqlserverutil.ddac$1.run(Unknown Source)
		at java.base@11.0.4/java.security.AccessController.doPrivileged(Native Method)
		at macromedia.sqlserverutil.ddac.b(Unknown Source)
		at macromedia.sqlserverutil.ddac.a(Unknown Source)
		at macromedia.jdbc.sqlserverbase.BaseDatabaseMetaData.a(Unknown Source)
		at macromedia.jdbc.sqlserverbase.BaseDriver.getMajorVersion(Unknown Source)
		at macromedia.jdbc.MacromediaDriver.(Unknown Source)
		at jdk.internal.reflect.GeneratedConstructorAccessor61.newInstance(Unknown Source)
		at java.base@11.0.4/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
		at java.base@11.0.4/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
		at java.base@11.0.4/java.lang.Class.newInstance(Class.java:584)
		at coldfusion.server.j2ee.sql.pool.JDBCPool.createPhysicalConnection(JDBCPool.java:589)
		at coldfusion.server.j2ee.sql.pool.ConnectionRunner$RunnableConnection.run(ConnectionRunner.java:67)
		at java.base@11.0.4/java.lang.Thread.run(Thread.java:834)

which, as you can see, is busy loading some classes-- presumably from the JDBC driver. Which is ironic since I would have bet it was waiting on a network response, but perhaps we just caught it at a bad time.

So, here’s the thing. Everything above looks legit-- annoying that the pool is locking like that, but not out of the ordinary when it comes to Java connection pooling. What I don’t understand why the checking out of connections seems to be taking so long. You’d need to capture a series of stack traces to try and look for patterns in the “blocking” thread. And what I also don’t understand is how your runAsync() example would behave any differently UNLESS it was somehow creating a new DB connection pool for each thread, which seems unlikely.

On a related note, how are you acquiring the thread dumps? I’m used to there being a lot more information in there about specifically which threads are blocking what, but I also always get my thread dumps from FusionReactor and it’s possible FR is injecting some of that very useful information.

8

I am using a component from Ben Nadel to programatically get the thread dump after 2 seconds. I could easily do one more frequently to get a better picture. I did a test using docker compose and did not see this behavior. So I am thinking it is an issue with the db server being on a different network and something to do with the connection between the two. II created a repo with my test code.

Using this configuraton I do not see this behavior.

I ran across this which seems like the same issue where it ended up being a network issue.

Also some related info in the comments of this.

I am still doing some debugging but wanted to provide a quick update.

9

I was also able to verify that there is a new db connection being established for each thread. Once I see 20 connections on the DB side then it runs fast. But once I reload the application is starts opening new connections, I assume because it is created a new thread pool. So maybe the problem because it trying establish that many connections accross the network at the exact same time.

10

Trying to establish 20 JDBC connections at the same time could certainly have some overhead (and possibly block other threads). What I’m a little curious about is your report that reloading the ColdBox application (creating a new thread pool) seems to affect this. That would imply that the threads in the executor pool are holding on to their datasource connection and not releasing it back to the pool perhaps. (since there is no “end of request” per se). Can you confirm if every time you reload the application if there are 20 NEW connections on the DB side? Do the old ones ever disconnect or does the count just keep increasing?

To circle back to something you said in your original post:

It seems to run fine using the runAsync()

Are you still seeing a different behavior between Coldbox’s AsyncManager and ColdFuson’s runAsync() function or do they behave the same?

11

So I noticed the first time I called the runAsync() test there was a delay as well. This was after a fresh restart of the server. I could see that it created a new db connection for each thread. But once the database connections existed it would reuse them and not create new ones.

I can confirm that, using AsyncManager, if I use fwreinit=1 with 20 async processes it will create 20 new connections each time so if I call it 4 times I end up with 80 database connections. I will leave it sit for awhile to see if they eventually time out.

12

@jason_steinshouer Please remember that a fwreinit is a HARD stop. It also tries to tell the executors to KILL all threads. This is not graceful and in all reality I have seen tthat the JVM and the threads do whatever they want. It is almost never ends up nicely!

In production you would never reinit and if you do it’s at your own risk. So just now that when you do that, you are trying to cancel everything running. Sometimes it works gracefully, sometimes it bombs out. The behavior you mention is exaclty what it should do, because the threads that where assigned to the running executors will be trying to kill off, new executors come online and try again and so forth.

13

@lmajano That makes sense. Thanks to you and @bdw429s for helping me to better understand how things work under the hood. I appreciate the effort.

14

Thanks to you and your detailed reports. They make a big difference. Also, note that this is our first major release surrounding futures and concurrency. We love feedback and even more we love pull requests :slight_smile:

15

From reviewing the code, I think the JVM will TRY to interrupt the threads in the executor pool when it’s shut down (which politely asks them to stop what they’re doing), but I don’t think you can guarantee it won’t give up and murder them. From my testing of our asyncmanager usage for LogBox async appenders and Cachebox reaping, I’ve seen that the threads are usually interrupted and get a chance to shutdown, depending on what they’re doing.

I am thinking there may be some extra stuff we can do when we unload the CF context to try and get it to give up any datasource connections that CF may be holding on to under the hood. Lucee is where i primarily tested this and Lucee returns a datasource to the pool immediately after it’s done with it. Holding onto a connection for the duration of request is an Adobe-specific behavior. I’d have to try and do some digging to figure out what magic calls it takes to get Adobe to let go of a datasource. And that is never easy since I can’t just look at the source code like I can with Lucee!

16

Just wanted to chime in here as I’m experiencing the same issue. I’m on ACF 10. I’m noticing that when CF code is executed by a thread created by the JCF, that CF can’t re-use that DB connection for regular http requests, or even for OTHER executors created by the same AsyncManager instance.

In addition to NOT allowing the DB connections to be re-used by other requests/threads, the connections used by JCF threads DO NOT TIME OUT. I set have my DB connection settings set to timeout and close after 3 minutes of inactivity, and have the pool check once a minute to see if there are connections that can be cleaned up. I can run a bunch of tests, then come back hours later, and the connections haven’t closed when they SHOULD have.

Here is a test case, drop the two files below into a directory and then:

Run: /RunnerServiceASM.cfc?method=runHttpCalls
After you’ll see 25 DB connections since CF by default is set to only support 25 simultaneous requests and each needs a DB conn

Again, Run: /RunnerServiceASM.cfc?method=runHttpCalls
After you’ll see the SAME 25 DB connections

Run: /RunnerServiceASM.cfc?method=runQueriesAsm
After you’ll see 30 DB connections open since we used a JCF connection pool of 30 connections and we’re not bound by CF request limits

Again, Run: /RunnerServiceASM.cfc?method=runQueriesAsm
After you’ll see the same 30 DB connections open. Yay, the executor was able to re-use the connections it created and used last.

Again, Run: /RunnerServiceASM.cfc?method=runQueriesAsm2
After you’ll see 60 DB connections open, apparently only a single executor can re-use its own connections. Bummer :frowning:

Run: /RunnerServiceASM.cfc?method=runHttpCalls
After you’ll see 85 DB connections since regular CF requests can’t use the connections that were USED or Created by the JCF threads. Mega bummer.

I was using MySQL as the DB I was testing this code against. I used the following SQL to get a quick view of how many connections were being used, and watch the SQL running

SELECT	`USER`, LEFT(`HOST`, INSTR(`HOST`, ':') -1), COUNT(*)
FROM	information_schema.processlist
GROUP BY 1,2;

SHOW FULL PROCESSLIST;

RunnerServiceASM.cfc

component {

variables.baseUrl = "http://admin";	// url to this file minus the file name and trailing slash
variables.dsn = "testDSN";	// dsn to run queries against
variables.dbUsername = "username";
variables.dbPassword = "xxxxx";


remote function getUrl(theUrl) {
	var httpService = new http(method = "GET", charset = "utf-8", url = "#arguments.theUrl#");
	return httpService.send().getPrefix();
}


remote function docreateproxy() {
	var task = createObject("component", "MethodWrapperTask").init(this, "doquery", {});
	
	var t = createDynamicProxy( task, ["java.util.concurrent.Callable"] );
	
	t.call();
	
	return "createproxy done #now()#";
}


remote function doquery() {
	var myQuery = new com.adobe.coldfusion.Query(sql="select sleep(5);", datasource=variables.dsn).execute().getResult();		
	
	return "query done #now()#";
}

remote function doqueryjdbc() {
	runJdbcQueryAgainstDSN(
		datasource=variables.dsn,
		sql="select sleep(5);",
		username=variables.dbUsername,
		password=variables.dbPassword
	);
	
	return "jdbc query done #now()#";
}


remote function runHttpCalls(required string action = "doquery") {

	initExecutor();
	
	for(var i=1; i LTE 100; i++) {
		var task = createObject("component", "MethodWrapperTask").init(
			this, "getUrl", { theUrl = "#variables.baseUrl#/RunnerServiceASM.cfc?method=#arguments.action#" }
		);
		application.asmExecutorService.submit( task, "call" );
	}
	
	// keep the request running for a while or all the tasks die!
	sleep(20000);
	
	return "runHttpCalls #arguments.action# done #now()#";
}



remote function runQueriesASM() {

	initExecutor();
	
	for(var i=1; i LTE 100; i++) {
		var task = createObject("component", "MethodWrapperTask").init(
			this, "doquery", {}
		);
		application.asmExecutorService.submit( task, "call" );
	}
	
	// keep the request running for a while or all the tasks die!
	sleep(20000);
	
	return "runQueriesASM done #now()#";
}


remote function runQueriesASM2() {

	initExecutor();
	
	for(var i=1; i LTE 100; i++) {
		var task = createObject("component", "MethodWrapperTask").init(
			this, "doquery", {}
		);
		application.asmExecutorService2.submit( task, "call" );
	}
	
	// keep the request running for a while or all the tasks die!
	sleep(20000);
	
	return "runQueriesASM2 done #now()#";
}

remote function runJdbcQueriesASM() {

	initExecutor();
	
	for(var i=1; i LTE 100; i++) {
		var task = createObject("component", "MethodWrapperTask").init(
			this, "doqueryjdbc", {}
		);
		application.asmExecutorService.submit( task, "call" );
	}
	
	// keep the request running for a while or all the tasks die!
	sleep(20000);
	
	return "runJdbcQueriesASM done #now()#";
}


remote function runJdbcQueriesASM2() {

	initExecutor();
	
	for(var i=1; i LTE 100; i++) {
		var task = createObject("component", "MethodWrapperTask").init(
			this, "doqueryjdbc", {}
		);
		application.asmExecutorService2.submit( task, "call" );
	}
	
	// keep the request running for a while or all the tasks die!
	sleep(20000);
	
	return "runJdbcQueriesASM2 done #now()#";
}



private function initExecutor() {


	if(	isDefined("application.asm")
		AND isDefined("url.destroyPriorExecutorFactory")
		AND url.destroyPriorExecutorFactory
	
	) {
		application.asm.shutdownAllExecutors();
		structDelete(application, "webExecutorFactory");
		
		if(	isDefined("url.exitAfterDestroyPriorExecutorFactory")
			AND url.exitAfterDestroyPriorExecutorFactory			
		) {
			abort;
		}
	}
	

	if(NOT isDefined("application.asm")) {
		application.asm = createObject("component", "coldbox.system.async.AsyncManager").init();

		application.asmExecutorService = application.asm.newExecutor(
			name="webExecutorServiceExample",
			type="fixed",
			threads=30,
			debug="true"
		);
		
		application.asmExecutorService2 = application.asm.newExecutor(
			name="webExecutorServiceExample2",
			type="fixed",
			threads=30,
			debug="true"
		);
	}
}

private function runJdbcQueryAgainstDSN(
	required string datasource,
	required string sql,
	array params = arrayNew(1),
	boolean returnResults = false,
	string username = "",
	string password = ""
) {
	var _ = {};
	 
	//Creating an object of servicefactory class
	_.theServiceFactory = createObject('java','coldfusion.server.ServiceFactory');
	 
	//Creating the connection object simply by passing the DSN name
	_.dsn = _.theServiceFactory.getDataSourceService().getDataSource(arguments.datasource);
	
	_.con = "";
	_.q = "";
	
	if(	len(arguments.username)
		AND len(arguments.password)
	) {
		_.con = _.dsn.getConnection(javaCast("String", arguments.username), javaCast("String", arguments.password));
		
	} else {
		_.con = _.dsn.getConnection();
		
	}

	
	_.useTransaction = false;
	
	try {
		_.stmt = _.con.prepareStatement(javaCast("String", arguments.sql));
		
		_.cnt=0;
		for(_.param IN arguments.params) {
			_.cnt++;
			
			if(len(_.param.castType)) {
				invoke(_.stmt, "set#_.param.dbType#", [javaCast("int", _.cnt), javaCast(_.param.castType, _.param.value)]);
				
			} else {
				invoke(_.stmt, "set#_.param.dbType#", [javaCast("int", _.cnt), _.param.value]);
				
			}
			//_.stmt.setInt(javaCast("int", _.cnt), javaCast("int", 5));
		}
		
		
		if(_.useTransaction) {
			_.con.setAutoCommit(javaCast("boolean", false));
		}
		
		_.q = _.stmt.executeQuery();
		
		if(_.useTransaction) {
			_.con.commit();	
		}

		if(arguments.returnResults) {
			_.cfq = createObject("java", "coldfusion.sql.QueryTable").init( _.q );
			
			return _.cfq.firstTable();
		}
	
	} catch(any e) {
		
		// Restore the connection to an auto-commit status
		if(NOT _.con.isClosed()) {
			if(_.useTransaction) {
				_.con.rollback();
			}
			
			_.con.setAutoCommit(javaCast("boolean", true));
		}
		
		throw(message=e.message, type=e.type, detail=e.detail);
		
	} finally {
		if(NOT isSimpleValue(_.q)) {
			try {
				_.q.close();
			} catch(any e) {}
		}
		
		if(NOT isSimpleValue(_.con)) {
			try {
				_.con.close();
			} catch(any e) {}
		}
	}
}
		
}

MethodWrapperTask.cfc

component {

public function init(
	required any cfcInstance,
	required string methodName,
	required any argCollection
) {
	structAppend(variables, arguments);
	
	return this;
}


public any function call() {
	var retData = {};
	retData.result = invoke(variables.cfcInstance, variables.methodName, variables.argCollection);
	
	// Convert a VOID to an empty string since CALL needs to return something always
	if(NOT structKeyExists(retData, "result")) {
		retData.result = "";
	}
	
	return retData;
}
}

Things I’ve Tried

I figure I’ll mention the things I’ve tried to get CF to release the DB connections for re-use by other threads.

I’ve updated the unloadContext method to call the following methods on various objects with no success:

fusioncontext.threadEnd()
page.release();
page.release(true);
pageContext.cleanupForCFThread();
pageContext.release()
pageContext.release(true);

I’ve also tried calling the loadContext again after the unloadContext method finished running and that didn’t do anything either.

It also did NOT matter in my tests whether the query was wrapped in a TRANSACTION block or not. Same issue.

So I found something interesting

Restart CF so you’re starting fresh… Update the variables dbUsername and dbPassword values to be different values than the DSN configured in the CFAdmin itself uses. Then run the following:

/RunnerServiceASM.cfc?method=runJdbcQueriesAsm
You’ll see 30 connections

/RunnerServiceASM.cfc?method=runJdbcQueriesAsm2
You’ll see the same 30 connections

This time the two separate executors used the same connections!!!

I just decided to give that a shot because, why not. I use that Jdbc query method every once in a while when I need to run an action with elevated privileges. That way I don’t have to re-define every aspect of the DSN, I can programmatically pass in the creds and run a SQL statement as a specific user.

Maybe some stack traces can be obtained when that method is called to see what’s getting called in the CF connection pool and that can be used in the unloadContext methods. I need to head out, but wanted to at least share everything I’ve found on this subject.

17

This really makes perfect sense when you think about it. ColdFusion only times out a thread if it’s checked into the pool and not in use. You wouldn’t want a connection timing out while a page was using it. So if these DB connections are never getting checked back into the pool, then ColdFusion is never even looking at them to time them out.

18

Definitely makes sense.

Just wanted to report some behavior I noticed.

So I created 3 executors and ran a bunch of tasks through each. The good part is that even though the DB connections do NOT get returned to the DB pool or eventually time out, they at least DO stay with the executor that FIRST USED them.

So I had 3 executors with 30 threads each.
Each executor used the same 30 connections it touched over and over again. It didn’t grab connections that any other executors used (makes sense since it doesn’t return them to the DB connection pool).

If you do blue/green deploys, you can live with this limitation. But if after deploying new code you reload the application in place by do something like an http request with ?reinit=1 in the querystring and have that call onApplicationStop/onApplicationStart, you will eventually hit the maximum connection limit for the DB user and take down your application.

The only want to kill the connections created by the executor is to shut down the CF server. Even changing the DSN settings in the CFAdmin won’t kill these connections.

19

@jason_steinshouer Kurt and I have found a workaround for Adobe CF that seems to work in getting it to release the DB connections held by the thread back to the pool.

in the base proxy CFC where it unloads the context, this code

createObject( 'java', 'coldfusion.sql.DataSrcImpl' ).clearSqlProxy()

seems to do the trick if you’d like to try it. We’ll work on getting that added to the official library soon.

20

Thanks. I tried adding this here.

coldbox\system\async\proxies\BaseProxy.cfc:138

But getting a class not found exception from ACF 2018.

java.lang.ClassNotFoundException: coldfusion.sql.DataSrcImpl 
 at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:583) 
 at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:178) 
 at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:521) 
 at coldfusion.runtime.java.JavaProxyFactory.getProxy(JavaProxyFactory.java:122) 
 at coldfusion.runtime.ProxyFactory.getProxy(ProxyFactory.java:69) 
 at coldfusion.runtime.CFPage.createObjectProxy(CFPage.java:8567) 
 at coldfusion.runtime.CFPage.CreateObject(CFPage.java:8530) 
 at coldfusion.runtime.CFPage.CreateObject(CFPage.java:8475) 
 at coldfusion.runtime.CFPage.CreateObject(CFPage.java:8403) 
 at coldfusion.runtime.CFPage.CreateObject(CFPage.java:8344) 
 at cfBaseProxy2ecfc1525831371$funcUNLOADCONTEXT.runFunction(C:\myapp\coldbox\system\async\proxies\BaseProxy.cfc:138) 
 at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:553) 
 at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:447) 
 at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95) 
 at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:398) 
 at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:371) 
 at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:287) 
 at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:4132) 
 at coldfusion.runtime.CfJspPage._invokeUDF(CfJspPage.java:4112) 
 at cfFunction2ecfc1211832965$funcAPPLY.runFunction(C:\myapp\coldbox\system\async\proxies\Function.cfc:40) 
 at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:553) 
 at coldfusion.runtime.UDFMethod$ArgumentCollectionFilter.invoke(UDFMethod.java:447) 
 at coldfusion.filter.FunctionAccessFilter.invoke(FunctionAccessFilter.java:95) 
 at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:398) 
 at coldfusion.runtime.UDFMethod.runFilterChain(UDFMethod.java:371) 
 at coldfusion.runtime.UDFMethod.invoke(UDFMethod.java:287) 
 at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:830) 
 at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:613) 
 at coldfusion.runtime.TemplateProxy.invoke(TemplateProxy.java:438) 
 at coldfusion.runtime.java.CFCDynamicProxy.invoke(CFCDynamicProxy.java:157) 
 at com.sun.proxy.$Proxy53.apply(Unknown Source) 
 at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642) 
 at java.base/java.util.concurrent.CompletableFuture$Completion.exec(CompletableFuture.java:479) 
 at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) 
 at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) 
 at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) 
 at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) 
 at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)