http://coldfusion.com logo
Join Slack
Powered by
Hi All.. I am seeing this lucee@5.3.10.120 log4j l...
# lucee
c
Hi All.. I am seeing this lucee@5.3.10.120 log4j lock regularly cause requests to run for 30+ seconds.. This is about all the info I can get from FusionReactor and am not sure if it's an application code issue, or something within Lucee.. It appears to me to be some logging after a cfquery has run.. Is anyone able to give me some hints on where to look next? The snippet below is from the FR Profiler.. 96.7% - 49.225s lucee.runtime.tag.Query.doEndTag(Query.java) 96.7% - 49.225s lucee.runtime.tag.Query._doEndTag(Query.java) 96.7% - 49.225s lucee.commons.io.log.log4j2.LogAdapter.info(LogAdapter.java) 96.7% - 49.225s lucee.commons.io.log.log4j2.LogAdapter.log(LogAdapter.java) ... 96.7% - 49.225s org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java) 96.7% - 49.225s lucee.commons.io.log.log4j2.appender.ResourceAppender.append(ResourceAppender.java) 83.9% - 42.733s Waiting on lock <0x78304b16> (a java.lang.String) 12.8% - 6.492s lucee.commons.io.res.type.file.FileResource.length(FileResource.java) 4 Collapsed Methods (show) 12.8% - 6.492s Waiting on lock <0x351c5e57> (a lucee.commons.lang.SerializableObject)
Interestingly, I reverted to 5.3.10.97 and this issue has not occurred since..
image.png
b
@chapmandu Can you show the full stack to see where the logging is coming from?
Actually, I guess the profiler doesn't have line numbers so that will be harder
If you can catch a thread in the middle of this you can get a proper stack
I assume it's this around line 780
Copy code
// log
			Log log = ThreadLocalPageContext.getLog(pageContext, "datasource");
			if (log.getLogLevel() >= Log.LEVEL_INFO) {
				<http://log.info|log.info>("query tag", "executed [" + sqlQuery.toString().trim() + "] in " + DecimalFormat.call(pageContext, exe / 1000000D) + " ms");
			}
That line of code is 4 years old,
The lock itself I THINK is in the Lucee ResourceAppender, but I'm not 100% sure
Hmm, here we go.. here is the lock in the append method
Copy code
synchronized (token) {
now THAT code was added 13 months ago in LDEV-1136
It's the logic that rolls the log file
This code was added in 5.3.9 though, so rolling back to another 5.3.10 version should still have that code https://luceeserver.atlassian.net/browse/LDEV-1136
I would guess there is file contention on disk
With locks-- it takes two (threads) to tango, so if your thread is held up waiting to acquire the lock, the question becomes, what other thread had the lock and what was it doing
In order to answer that you need to get a full thread dump of the JVM while it's happening
I would recommend enabling E-mail alerts in FR that trigger based on request time. You'll get an E-mail with a full thread dump of the JVM to help see a snapshot of what was happening
I'm going to guess one thread is rolling over a new log file, but taking a long time (or perhaps waiting on a lock of its own) and it's blocking all the other threads out there trying to log
c
Thanks Brad, I’ll look into it
z
I've filed a bug about this https://luceeserver.atlassian.net/browse/LDEV-4405 @chapmandu are you writing logs with log="application" or perhaps file="application" ?
also are there any "log-loading" errors in any of the logs?
c
Hey Zack, I’m not sure about log-loading errors, but I’m not using any explicit log code in my codebase.
z
what's in your logs then?
By default lucee has all logs set to error
What platform are u on?
Any anti virus?
c
This is occurring in a production commandbox AWS ECS container.. TBH, the offending containers are long gone (since reverting the lucee version) and I'm not sure can get to the logs..
z
So from that stack, the framework is logging
Are there logs which get rotated with the old version?
c
I'd need to do some digging.. I'm fairly new to ECS..
I can't see any reference to logging code in the framework? searching for 
cflog
log(
writeLog
z
Looks like you had the data source loglevel above error? https://github.com/lucee/Lucee/blob/5.3/core/src/main/java/lucee/runtime/tag/Query.java line 781
c
Yeah, I think that's what Brad deduced from my vague profiler info
If it's relevant, I'm using commandbox in production, with default logging settings
z
then it's @bdw429s fault, phew
😂 2
m
I'll hopefully remember to comment on the ticket tomorrow, but I wanted to chime in and mention I ran into the exact same issue, same version, and rolling back to the mentioned version solved it. Big thanks for mentioning it, performance was abysmal with the affected version and trying to debug it was tough. Was a docker container on EC2, no weird logging set up, just default AWS. Fun response time chart showing the impact:
👍 1
c
Kinda glad it wasn’t just me..
m
as @bdw429s has written a thread dump would be very helpful, i have attached a cfml template in the ticket that gives us the same info by simply copy it to the website and execute it, if a request is hanging
👍 1
22 Views
Open in Slack
PreviousNext
Powered by