CFThread "ElapsedTime" Is Not "Processor Time" In Lucee CFML 5.3.8.201
This morning, as I was trying to perform some follow-up exploration on SERIALIZABLE transactions in MySQL, I noticed something strange about the metadata exposed by the CFThread tag in Lucee CFML. Whereas Adobe ColdFusion (ACF) documents the ElapsedTime property as being "The amount of processor time that was spent handling the thread", this property looks to mean something different in Lucee CFML. It appears to be the amount of time that has elapsed since the CFThread tag was spawned; but, has nothing to do with when it ended; or, how much time it took to execute.
Testing this is quite simple with a few sleep() commands. In the following code, I'm going to spawn three CFThread tags, each performing a different amount of sleeping internally. Then, I'm going to wait for all the threads to complete and check their metadata:
<cfscript>
thread name = "one" {
sleep( 500 );
thread.lastLineAt = now().timeFormat( "hh:nn:ss" );
}
thread name = "two" {
sleep( 2500 );
thread.lastLineAt = now().timeFormat( "hh:nn:ss" );
}
thread name = "three" {
sleep( 4500 );
thread.lastLineAt = now().timeFormat( "hh:nn:ss" );
}
// Wait for all threads to complete and then check status.
thread action = "join";
dump( var = cfthread.one, show = "Name,ElapsedTime,StartTime,LastLineAt" );
dump( var = cfthread.two, show = "Name,ElapsedTime,StartTime,LastLineAt" );
dump( var = cfthread.three, show = "Name,ElapsedTime,StartTime,LastLineAt" );
// Sleep another few seconds and the re-check the status.
sleep( 2000 );
echo( "<hr />" );
dump( var = cfthread.one, show = "Name,ElapsedTime,StartTime,LastLineAt" );
dump( var = cfthread.two, show = "Name,ElapsedTime,StartTime,LastLineAt" );
dump( var = cfthread.three, show = "Name,ElapsedTime,StartTime,LastLineAt" );
</cfscript>
As you can see, the sleep() duration for each subsequent tag increments by 2-seconds. Then, we output the status of each thread after they've rejoined. And then finally, we sleep the parent thread for 2 more seconds and recheck the already-completed thread metadata.
When we run this Lucee CFML code, we get the following output:
As you can see, the ElapsedTime for each thread is roughly the same. And, it continues to increase even after the threads have finished executing. Clearly, the ElapsedTime is the time since the thread was spawned and not the time it took for the thread to actually execute.
Out of curiosity, I wanted to see how this same code behaved in Adobe ColdFusion (ACF) 2021. I had to make a few syntactic tweaks since ACF doesn't provide echo() or dump() functions:
<cfscript>
thread name = "one" {
sleep( 500 );
thread.lastLineAt = now().timeFormat( "hh:nn:ss" );
}
thread name = "two" {
sleep( 2500 );
thread.lastLineAt = now().timeFormat( "hh:nn:ss" );
}
thread name = "three" {
sleep( 4500 );
thread.lastLineAt = now().timeFormat( "hh:nn:ss" );
}
// Wait for all threads to complete and then check status.
thread action = "join";
cfdump( var = cfthread.one, show = "Name,ElapsedTime,StartTime,LastLineAt" );
cfdump( var = cfthread.two, show = "Name,ElapsedTime,StartTime,LastLineAt" );
cfdump( var = cfthread.three, show = "Name,ElapsedTime,StartTime,LastLineAt" );
// Sleep another few seconds and the re-check the status.
sleep( 2000 );
writeOutput( "<hr />" );
cfdump( var = cfthread.one, show = "Name,ElapsedTime,StartTime,LastLineAt" );
cfdump( var = cfthread.two, show = "Name,ElapsedTime,StartTime,LastLineAt" );
cfdump( var = cfthread.three, show = "Name,ElapsedTime,StartTime,LastLineAt" );
</cfscript>
Now, when we run this code in Adobe ColdFusion 2021, we get the following output:
As you can see, the ElapsedTime property is different for each CFThread tag; and, it remains consistent even after we sleep() the parent request for an additional 2-seconds. In Adobe ColdFusion, the ElapsedTime property is clearly the "processor time", as per their documentation.
From a compatibility standpoint, clearly there is a difference between Lucee CFML and Adobe ColdFusion. However, I cannot find any documentation on the CFThread tag metadata on the Lucee CFML site. As such, it's a bit hard to determine if this is a bug or not. The name of the property leaves a lot of room for interpretation. It would be reasonable for the "Elapsed" time to be the "time elapsed since spawning" - essentially the (now() - StartTime) difference.
ASIDE: To be clear, I believe Adobe ColdFusion's implementation is more helpful regardless of whether or not it is more "correct".
Regardless, it's good to know how the CFThread metadata works in Lucee CFML - and that I won't be able to use this particular value for to test for thread duration. I'll just have to come up with a different approach.
Want to use code from this post? Check out the license.
Reader Comments
@Ben:
This definitely seems like a Lucee bug to me, but I believe Lucee states that all compatibility differences should be considered a bug so I'd recommend filing this bug w/Lucee:
https://luceeserver.atlassian.net/
@Dan,
Will do 👍
I've filed a Compatibility bug: https://luceeserver.atlassian.net/browse/LDEV-3719