Lucee Appears To Incur Request-Cloning Overhead When Spawning CFThread Tags In Lucee CFML 5.3.3.62
Yesterday, we installed FusionReactor on some of our Lucee CFML servers in order to investigate curious JVM performance patterns. I'm still trying to understand what I'm seeing; but, I did notice something bizarre happening in some of the stack-traces. It looked as if the incoming HTTP Request Object was being re-processed whenever I spawned an asynchronous CFThread tag. In order to better understand the implications of this, I tried to break this out into an isolated use-case in Lucee CFML 5.3.3.62.
First, here's a portion of the stack-trace that I was seeing - I believe this represents the CFThread tag generation:
lucee.runtime.tag.ThreadTag.register(ThreadTag.java)
lucee.runtime.thread.ChildThreadImpl.<init>(ChildThreadImpl.java)
lucee.runtime.thread.ThreadUtil.clonePageContext(ThreadUtil.java)
lucee.runtime.thread.ThreadUtil.cloneHttpServletRequest(ThreadUtil.java)
lucee.runtime.net.http.HttpServletRequestDummy.clone(HttpServletRequestDummy.java)
lucee.runtime.net.http.HttpUtil.cloneParameters(HttpUtil.java)
lucee.runtime.net.http.HTTPServletRequestWrap.getParameterNames(HTTPServletRequestWrap.java)
lucee.runtime.net.http.HTTPServletRequestWrap.getParameterMap(HTTPServletRequestWrap.java)
lucee.runtime.type.scope.util.ScopeUtil.getParameterMap(ScopeUtil.java)
lucee.commons.net.URLDecoder.decode(URLDecoder.java)
As part of this, you can see that ChildThreadImpl involves something called cloneHttpServletRequest(); which, in turn, appears to be doing some URL Decoding. I believe what's going on here is that Lucee is actually re-processing the incoming HTTP Request object as part of that CFThread processing.
This jumped out at me because, according to Fusion Reactor, this lucee.commons.net.URLDecoder.decode() method call was taking hundreds of seconds. If this is true, it completely defeats the purpose of spawning an asynchronous thread if the very act of spawning the thread completely blocks the parent request for hundreds of seconds.
To try and re-create this, I setup a simple Lucee CFML page that does nothing but spawn a few CFThread tag bodies and logs the time it took for each thread to start running, and for the overall request to finish:
<cfscript>
// The long value will be coming through in a single value.
param name = "form.a" type = "string" default = "";
dump( getHttpRequestData().headers );
// ------------------------------------------------------------------------------- //
// ------------------------------------------------------------------------------- //
startedAt = getTickCount();
systemOutput( " . . . . . . . . . . . . . . . . . . . . . . .", true );
systemOutput( "Responding to FORM post - #delta( startedAt )#", true );
systemOutput( "Field length: #numberFormat( form.a.len() )#", true );
// Here, we are just looking to see how long it takes to SPAWN the following threads
// as a function of the incoming HTTP request size.
thread action = "run" {
systemOutput( "Inside 1st thread - #delta( startedAt )#", true );
}
thread action = "run" {
systemOutput( "Inside 2nd thread - #delta( startedAt )#", true );
}
thread action = "run" {
systemOutput( "Inside 3rd thread - #delta( startedAt )#", true );
}
systemOutput( "Done spawning threads - #delta( startedAt )#", true );
// ------------------------------------------------------------------------------- //
// ------------------------------------------------------------------------------- //
public string function delta( required numeric tickCount ) {
return( numberFormat( ( getTickCount() - tickCount ) ) );
}
</cfscript>
As you can see, this page does nothing more than spawn three threads and then log the time it takes to execute the overall page.
Now, you'll notice that I'm accepting a form field, form.a. I'm populating this form field using Postman and a pre-request script. The idea is to post increasingly large values in this form field to see how the Lucee CFML page responds.
The form.a field is powered by a Postman global variable which is generated using simple Array concatenation:
pm.globals.set(
"long_field_value",
new Array( 10000 ).join( "This is a long field value. " )
);
... which I am then posting to the Lucee CFML Server using the variable placeholder, {{long_field_value}}. In my experiment, I used the following increasing Array() initialization value for subsequent HTTP POST operations:
- 10,000
- 20,000
- 30,000
- 40,000
- 50,000
Now, if we look at the Lucee CFML server logs, this is what we see in terms of performance:
As you can clearly see, as the size of the form.a value increase, so does the time it takes to spawn each CFThread body. By the time I am posting a payload that is around 1.4MB in size, each CFThread takes about 30-seconds just to spawn! And, as you can see from the overall output, spawning 3 threads at that payload size blocks the parent request for over 90-seconds.
Again, this is just my theory as to what is going on; but, it seems that as the size of the incoming request increases, you reach a point where spawning a CFThread actually slows down the overall request processing. I mean, at 30-seconds to spawn a thread, it would almost certainly be faster just to inline whatever the CFThread tag body was trying to do in the first place.
Maybe someone with a better understanding of low-level Java / Lucee processing can help me understand what is happening here (and possible work-arounds).
I Can Replicate With Postman, Not With CFHTTP
One strange thing that I noticed during this investigation was that I could only replicate this behavior when posting the form with Postman. At first, I tried create the test using a Lucee CFML script and CFHTTP:
<cfscript>
param name = "url.size" type = "numeric" default = 100;
// ------------------------------------------------------------------------------- //
// ------------------------------------------------------------------------------- //
post = new Http(
method = "post",
url = "http://127.0.0.1:56232/thread-form/test.cfm"
);
post.addParam(
type = "formfield",
name = "a",
value = repeatString( "This is a long field value. ", url.size )
);
echo( post.send().getPrefix().fileContent );
</cfscript>
However, when I ran this, even with a size of 50,000 the script runs instantly. And, the server logs confirm the fact that spawning the CFThread bodies only took a few hundred milliseconds. I'm not sure why this approach is substantively different than the Postman approach; but, for whatever reason, it was fast.
I Can Replicate With CFHTTP Across Different ColdFusion Instances
Quick update to that last section: if I spin up a second instance of a ColdFusion server, and then perform the CFHTTP request across instances (ex, calling from Adobe ColdFusion to Lucee CFML), I can replicate the behavior. So, apparently, making a loop-back HTTP request from within a single Lucee CFML server has some additional performance benefits that I don't really understand.
Want to use code from this post? Check out the license.
Reader Comments
@All,
Some of this is being discussed in the Lucee Dev forum:
https://dev.lucee.org/t/urldecoder-timeout-for-very-large-post-requests/2023/10
... in which Zac Spitzer points to this Lucee Ticket:
https://luceeserver.atlassian.net/browse/LDEV-2559
... that also discusses the cost of duplicating the page context when doing async array iteration.
@All,
Based on the conversations in the Lucee CFML Dev Forum, I tested two different approaches to getting around this large Form Field issue:
www.bennadel.com/blog/3758-using-a-file-upload-or-the-request-body-to-overcome-the-slow-processing-of-a-large-form-post-in-lucee-cfml-5-3-3-62.htm
You can either:
In either approach, the processing time goes from 10s-of-seconds (with the Form Field approach) to 10s-of-milliseconds. The change is drastic and awesome!
@ben, have you ever seen response for http request getting mixed when using threads? We are doing some heavy processing in threads and inside the thread we have an external http call. once in a while we will see that response from http request is getting mixed across threads because of concurrency.
@Sumit,
Hmmmm, I don't think I have seen that. Are you thinking that the
cfhttpresponse object is getting saved to the wrong place? Maybe try throwing alocal.in front of thecfhttpproperty?@ben no literally the http request originate in thread-1 is but the response is going to thread-2. It's crazy. We are working on using java http to see if that resolves the issue. I'm thinking it's related to how lucee is handling http.
@Sumit,
That's some crazy stuff! I hope you find a work-around. I have no idea how you even figured out what the heck was going on. That would have driven me nuts.
@All,
I just stumbled-upon what I'm going to consider another "twist" in this request-cloning that happens with
CFThreadtags. It seems that if the parent request is handling a file upload, the.uploadtemporary file associated with that upload is duplicated and persisted indefinitely if the parent request spawns some asynchronous processing:www.bennadel.com/blog/3889-temporary-upload-files-are-duplicated-and-persisted-when-a-request-uses-cfthread-in-lucee-cfml-5-3-6-61.htm
In fact, it will duplicate another file for every
CFThreadtag that is spawned. Which, in our case, could be for image thumbnailing, analytics logging, and all sorts of other background features.