Skip to main content
Ben Nadel
On User Experience (UX) Design, JavaScript, ColdFusion, Node.js, Life, and Love.

Lucee Appears To Incur Request-Cloning Overhead When Spawning CFThread Tags In Lucee CFML 5.3.3.62

By Ben Nadel on
Tags: ColdFusion

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:

CFThread spawn time takes longer as the size of the incoming HTTP request increases in Lucee CFML 5.3.3.62.

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.



Reader Comments

@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:

  • Upload the large value as a File.
  • Post the large value as the HTTP Request Body.

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!

Reply to this Comment

@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.

Reply to this Comment

@Sumit,

Hmmmm, I don't think I have seen that. Are you thinking that the cfhttp response object is getting saved to the wrong place? Maybe try throwing a local. in front of the cfhttp property?

Reply to this Comment

@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.

Reply to this Comment

@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.

Reply to this Comment

Post A Comment

You — Get Out Of My Dreams, Get Into My Blog
Live in the Now
Oops!
NEW: Some basic markdown formatting is now supported: bold, italic, blockquotes, lists, fenced code-blocks. Read more about markdown syntax »
Comment Etiquette: Please do not post spam. Please keep the comments on-topic. Please do not post unrelated questions or large chunks of code. And, above all, please be nice to each other - we're trying to have a good conversation here.