CFML: runAsync doesn't seem very asynchronous on Lucee (5.3.10.120)

G'day:

I was wanting to compare how other languages dealt with the promise-style async processing, as I was not completely convinced by what I was seeing when investigating spatie/async in the previous article: "PHP: looking at spatie/async". It seems solid, just doesn't behave how I'd expect in some situations. More on that in another article. I checked what JS does, and it was fine, and then I recalled in the back of my mind that CFML added something new to do with async processing a while ago. CF2018 as it turns out. runAsync. And this was also added to Lucee at some point too (their docs don't say when something was added).

I knocked together a quick repro of what I was looking at in spatie/async and JS as a baseline; and then wtote an equivalent in CFML. But when I ran it on Lucee it didn't seem to be behaving how I'd expect, but in a different way from what I was trying to compare to in the other languages. When I ran the same code on ColdFusion though, it seemed to behave the way I expected. It seemed I have found a Lucee rabbit hole to go down.

I ended up with this repro that demonstrates what I'm seeing. There's a chunk of code, but it's a bunch of largely the same operations repeated a few times so as to provide usable telemetry. I'll go through it piecemeal though.

This is all being run on Lucee 5.3.10.120.

start = getTickCount()
writeLog(file="runAsync", text="Begin @ #getTickCount() - start#")

I'll time things as I go.

writeLog(file="runAsync", text="f1 before define @ #getTickCount() - start#")
f1 = runAsync(() => {
    writeLog(file="runAsync", text="f1 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f1 after define @ #getTickCount() - start#")

• I create a future
• And it has a main task, and two then handlers.
• Each of these do exactly the same thing:
  • Call a proc in the DB. See below for the implementation code, but you can probably tell it's a proc specifically designed to take time to execute. It's basically a DB-borne sleep call.
  • And log the current run time before and after the proc call.
• Oh and I log the timing either side of the whole oepration too.

Here's the proc:

DROP PROCEDURE IF EXISTS sleep_and_return;
DELIMITER //
CREATE PROCEDURE sleep_and_return(IN seconds INT)
BEGIN
    DO SLEEP(seconds);
    SELECT seconds;
END //
DELIMITER ;

It just sleeps for the specified time and then returns the value it was passed.

Then I do exactly the same thing I did with f1 for f2 and f3 as well. Three identical sets of runAsync / then / then with the logging and the DB call.

After that, I sit back and get each of them, timing around each get:

writeLog(file="runAsync", text="f1 before get @ #getTickCount() - start#")
f1.get()
writeLog(file="runAsync", text="f1 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f2 before get @ #getTickCount() - start#")
f2.get()
writeLog(file="runAsync", text="f2 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f3 before get @ #getTickCount() - start#")
f3.get()
writeLog(file="runAsync", text="f3 after get @ #getTickCount() - start#")

And one final entry in the log at the end:

writeLog(file="runAsync", text="End @ #getTickCount() - start#")

All the code together looks like this:

start = getTickCount()
writeLog(file="runAsync", text="Begin @ #getTickCount() - start#")


writeLog(file="runAsync", text="f1 before define @ #getTickCount() - start#")
f1 = runAsync(() => {
    writeLog(file="runAsync", text="f1 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f1 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f1 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f1 after define @ #getTickCount() - start#")


writeLog(file="runAsync", text="f2 before define @ #getTickCount() - start#")
f2 = runAsync(() => {
    writeLog(file="runAsync", text="f2 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f2 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f2 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f2 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f2 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f2 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f2 after define @ #getTickCount() - start#")


writeLog(file="runAsync", text="f3 before define @ #getTickCount() - start#")
f3 = runAsync(() => {
    writeLog(file="runAsync", text="f3 main before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f3 main after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f3 then1 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f3 then1 after query @ #getTickCount() - start#")
}).then(() => {
    writeLog(file="runAsync", text="f3 then2 before query @ #getTickCount() - start#")
    queryExecute("CALL sleep_and_return(1)", [], {datasource="test"});
    writeLog(file="runAsync", text="f3 then2 after query @ #getTickCount() - start#")
})
writeLog(file="runAsync", text="f3 after define @ #getTickCount() - start#")


writeLog(file="runAsync", text="f1 before get @ #getTickCount() - start#")
f1.get()
writeLog(file="runAsync", text="f1 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f2 before get @ #getTickCount() - start#")
f2.get()
writeLog(file="runAsync", text="f2 after get @ #getTickCount() - start#")

writeLog(file="runAsync", text="f3 before get @ #getTickCount() - start#")
f3.get()
writeLog(file="runAsync", text="f3 after get @ #getTickCount() - start#")


writeLog(file="runAsync", text="End @ #getTickCount() - start#")

When I run this on CF2021, I get exactly what I'd expect:

Begin @ 0
f1 before define @ 1
f1 main before query @ 2
f1 after define @ 3
f2 before define @ 4
f2 main before query @ 6
f2 after define @ 8
f3 before define @ 10
f3 after define @ 12
f3 main before query @ 12
f1 before get @ 13
f1 main after query @ 1006
f1 then1 before query @ 1008
f2 main after query @ 1011
f2 then1 before query @ 1012
f3 main after query @ 1015
f3 then1 before query @ 1016
f1 then1 after query @ 2010
f1 then2 before query @ 2012
f2 then1 after query @ 2014
f2 then2 before query @ 2016
f3 then1 after query @ 2023
f3 then2 before query @ 2024
f1 then2 after query @ 3014
f1 after get @ 3016
f2 before get @ 3017
f2 then2 after query @ 3018
f2 after get @ 3020
f3 before get @ 3021
f3 then2 after query @ 3026
f3 after get @ 3028
End @ 3029

Each of the f1, f3, f3 operations are being executed in a "first come, first served", and independently of each other (ie: asynchronously). And it's all over and done with at about the time it takes the slowest one to finish (allowing for intrinsic overhead).

It's a different story when I run this on Lucee:

Begin @ 1
f1 before define @ 19
f1 main before query @ 24
f1 main after query @ 1244
f1 then1 before query @ 1247
f1 then1 after query @ 2252
f1 after define @ 2255
f1 then2 before query @ 2255
f2 before define @ 2255
f2 main before query @ 2258
f1 then2 after query @ 3258
f2 main after query @ 3263
f2 then1 before query @ 3266
f2 then1 after query @ 4270
f2 after define @ 4272
f3 before define @ 4273
f2 then2 before query @ 4274
f3 main before query @ 4276
f2 then2 after query @ 5277
f3 main after query @ 5278
f3 then1 before query @ 5281
f3 then1 after query @ 6284
f3 after define @ 6286
f3 then2 before query @ 6286
f1 before get @ 6286
f1 after get @ 6287
f2 before get @ 6288
f2 after get @ 6289
f3 before get @ 6290
f3 then2 after query @ 7288
f3 after get @ 7289
End @ 7290

Here f1 gets underway, but it really seems to mostly block until [f1 then2 before query] until f2 even gets a look-in. This is two seconds of synchronous execution before Lucee even finds out there's something else asynchronous to be cracking on with. Then f2 blocks for second before f3 gets a chance to be looked at. Then there's a mess of stopping and starting, sucking up even more time, for an end result of ~7sec for an "asynchronous" operation that would take ~9sec if it was synchronous. Not great.

I also hasten to add that this was not a case of bad luck how the "async-ness" happened to run this time. I've run this code dozens of times, and it's always around the same. I also have run it with just CFML's own sleep instead of the DB call, and it's still the same. It's not the work the tasks are doing, it's how Lucee is implementing the asynchronous thread management, I think.

Also if ColdFusion's handling of the same code was similar to Lucee's, I'd just chalk it up to "sometimes asynchronous code doesn't even up seeming that asynchronous". But given ColdFusion nails it, I really think there's something up with Lucee. Pity: I had a good use case for this stuff in our app. But now I'm thinking I need to go back to our simple <cfthread> implementations and check exactly how asynchronous that code is…

Full disclosure: I also found what seems to be a bug with how ColdFusion handles enclosed variable references asynchronously, but I can't work out what's going on with that yet, and I was half way through this bit of code, so I wanted to finish this first. I might come back to the ColdFusion thing "tomorrow".

The code here is reasonably portable (one just needs to create that proc, and a DSN), so I'd be dead keen to hear from other people if they can run it in their own Lucee environments, if you can be arsed, that is.

Or am I missing something? Entirely possible. Let me know.

Righto.

--
Adam