http://coldfusion.com logo
Join Slack
Powered by
Anyone else seeing locking issues in newer version...
# lucee
d
Anyone else seeing locking issues in newer versions of Lucee (i'm testing 5.4.5.27-SNAPSHOT). I'm seeing lots of locking issues with CFHTTP, which appear to be related to using CHTTP inside a thread. I'm seeing things like:
Copy code
0.5% - 317ms Waiting on lock <0x66b35000> (a lucee.runtime.tag.Http)
0.5% - 271ms Waiting on lock <0x22be16e4> (a lucee.runtime.tag.Http)
0.3% - 203ms Waiting on lock <0x4a9542d0> (a lucee.runtime.tag.Http)
1.4% - 815ms Waiting on lock <0x797dad7f> (a lucee.runtime.tag.Http)
1.0% - 610ms Waiting on lock <0x4a9542d0> (a lucee.runtime.tag.Http)
0.7% - 405ms Waiting on lock <0x66b35000> (a lucee.runtime.tag.Http)
0.4% - 211ms Waiting on lock <0x22be16e4> (a lucee.runtime.tag.Http)
Once the locks hit, the threads just wait forever.
b
Pull a full thread dump. Find what thread is holding the lock
Keep in mind the cfhttp tag in Lucee runs the actual HTTP request in a separate thread, so it can enforce the timeout, so the main thread always waits to join back to the actual thread making the HTTP call. You could be seeing that if the actual http calls themselves aren't completing.
d
I know where in the code it's hanging, it's CFHTTP calls that are inside a threaded loop. The calls themselves are ones that generally complete within a 5-10 seconds. (We're making API calls to OpenSearch). However, there seems to be some kind of nested locking issue that happening.
The problem does not appear to be with the endpoint, but within Lucee itself.
b
What's the actual stack trace of one of these threads? What exactly are they trying to lock?
d
I'm going to try to put together a test case, that is outside of the current code stack.
The stack trace shows:
Copy code
"http-nio-8080-exec-2" Id=76 TIMED_WAITING on lucee.runtime.tag.Http@4a9542d0 
   java.lang.Thread.State: TIMED_WAITING
        at java.base@11.0.22/java.lang.Object.wait(Native Method)
        - waiting on lucee.runtime.tag.Http@4a9542d0
        at lucee.runtime.tag.Http._doEndTag(Http.java:1119)
        at lucee.runtime.tag.Http.doEndTag(Http.java:698)
        at org.lucee.cfml.helperbase_cfc$cf.udfCall1(/org/lucee/cfml/HelperBase.cfc:143)
        at org.lucee.cfml.helperbase_cfc$cf.udfCall(/org/lucee/cfml/HelperBase.cfc)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:358)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:594)
        at lucee.runtime.SuperComponent.call(SuperComponent.java:83)
        at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
        at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1776)
        at org.lucee.cfml.http_cfc$cf.udfCall(/org/lucee/cfml/Http.cfc:6)
        at lucee.runtime.type.UDFImpl.implementation(UDFImpl.java:112)
        at lucee.runtime.type.UDFImpl._call(UDFImpl.java:358)
        at lucee.runtime.type.UDFImpl.call(UDFImpl.java:223)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:698)
        at lucee.runtime.ComponentImpl._call(ComponentImpl.java:586)
        at lucee.runtime.ComponentImpl.call(ComponentImpl.java:1933)
        at lucee.runtime.util.VariableUtilImpl.callFunctionWithoutNamedValues(VariableUtilImpl.java:787)
        at lucee.runtime.PageContextImpl.getFunction(PageContextImpl.java:1776)
... rest of stack trace...
At the end of the stack trace, I see:
Copy code
Locked ownable synchronizers: 
        - org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker <0x59f6a5c6>
        - java.util.concurrent.locks.ReentrantLock$NonfairSync <0x5945e5a1>
b
Interesting, that code is just this
Copy code
synchronized (this) {// print.err(timeout);
    this.wait(timeout.getMillis());
}
Can you tell what other thread is holding the same lock?
That specific code hasn't changed in 5 years per Git lens.
My understanding of tags in Lucee is that they are transients, checked in and out of a pool as they are used, and then reset for the next use. I wonder if two threads are managing to be using the same http tag instance
d
So the only request running (because this is Dev) it unit test. The code that's struggling is inside a structure each() call which is being done asynchronously. Inside of that are some CFHTTP calls to an OpenSearch endpoint.
I think that might be the problem.
It seems to be related to threaded CFHTTP calls.
I'm pretty sure I've seen the behavior in production before, but it's happening with high frequency right now (although this code was recently refactored to use asynchronous loops, so that could be the reason)
b
Yeah, I'm not sure right off where the tag instances are checked out from the pool, but each thread, if sharing the same page context, may be re-using the same http tag instance instead of getting a new one
👍 1
d
Let me try to put together a test case
b
Do some git blames around the 
use
method of the pageContextImpl class
The tagHandlerPool is stored at the pagecontext level
d
My gut feeling is this isn't new, but just coming up due to the new code I'm testing. However, I've been testing the latest snapshot to make sure the Float issue I reported was indeed fixed.
👍 1
15 Views
Open in Slack
PreviousNext
Powered by