Bug 57714

Summary: Blocked trying to get lock: org/apache/log4j/spi/RootLogger
Product: Log4j - Now in Jira Reporter: Sawan Patwari <sawan_p>
Component: AppenderAssignee: log4j-dev <log4j-dev>
Status: NEW ---    
Severity: critical CC: AL00339146
Priority: P2    
Version: unspecified   
Target Milestone: ---   
Hardware: Other   
OS: Linux   
Attachments: Thread Dump

Description Sawan Patwari 2015-03-16 11:24:09 UTC
Created attachment 32575 [details]
Thread Dump

Hi,
We found the below issue in our Thread Dumps. Please let us know your thoughts if this is a known issue with log4j. The JVM that we use is 'BEA JRockit(R) R27.6.5-32_o-121899-1.6.0_14-20091001-2113-linux-x86_64'. The JDK is - 1.6.0_14 and the Java Vendor is BEA Systems, Inc. The OS is Linux-x86_64. Because of this issue other threads are getting struck in the JVM forming too many blocked-threads. We have attached our thread-dumps as well. In the thread-dumps, we can see the blocked chains pointing to this below struck thread - ExecuteThread: '3'. We are using the following jars for logging:
1.  log4j-1.2.17.jar
2. slf4j-api-1.7.5.jar
3. slf4j-log4j12-1.7.5.jar

Please let us know if any information that needs to be shared.






"[STUCK] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'" id=43 idx=0xb0 tid=6731 prio=1 alive, in native, native_waiting, daemon
    at jrockit/vm/RNI.generateFixedCode(J)J(Native Method)
    at org/apache/log4j/spi/ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:0)
    at org/apache/log4j/spi/LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
    at org/apache/log4j/WriterAppender.subAppend(WriterAppender.java:313)
    at org/apache/log4j/RollingFileAppender.subAppend(RollingFileAppender.java:276)
    at org/apache/log4j/WriterAppender.append(WriterAppender.java:162)
    at org/apache/log4j/AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
    ^-- Holding lock: org/apache/log4j/RollingFileAppender@0x553f0ab8[thin lock]
    at org/apache/log4j/helpers/AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org/apache/log4j/Category.callAppenders(Category.java:206)
    ^-- Holding lock: org/apache/log4j/spi/RootLogger@0x553efbf8[thin lock]
    at org/apache/log4j/Category.forcedLog(Category.java:391)
    at org/apache/log4j/Category.log(Category.java:856)
    at org/slf4j/impl/Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:575)
Comment 1 Ralph Goers 2015-03-16 14:21:41 UTC
All new development work is happening on Log4j 2. I would recommend you use
1. slf4j-api-1.7.5.jar
2. log4j-slf4j-impl-2.2.jar
3. log4j-api-2.2.jar
4. log4j-core-2.2.jar

Then change your log4j configuration to match the format used by Log4j 2.  See http://logging.apache.org/log4j/2.x/manual/configuration.html.
Comment 2 Sawan Patwari 2015-03-16 16:15:02 UTC
Thank you Ralph. But I have one concern, which is, how can we be sure if its gonna solve our problem? Has this sort of issue been reported earlier or anything similar? I am asking this question because we between two minds here since we are seeing this line - 'jrockit/vm/RNI.generateFixedCode(J)J(Native Method)' in our thread-dumps. Our eyes are on Jrockit JVM too because that seems to be the root cause as seen in the stack trace. Please share your thoughts on this.

Thanks a lot in advance.

Regards,
-Sawan.Patwari
Comment 3 Ralph Goers 2015-03-16 16:23:10 UTC
Log4j 2 does not lock when processing the appenders collection. Individual appenders may hold locks while writing to streams, sockets, etc. where you wouldn't see same sort of behavior as below.

Also, in general processing a stack trace in Log4j 2 is going to be more efficient than in Log4j 1.

You may also want to take advantage of Asynchronous Loggers in Log4j 2 as that should keep your application threads from being hindered by logging.
Comment 4 Sawan Patwari 2015-03-16 16:41:39 UTC
Are you hinting by saying that we may perhaps not see the below issue in future with log4j 2? The below information is gotten from Thread-Dumps. ExecuteThread: '22' and like others are all struck due to ExecuteThread: '3' in the below fashion. Likewsie, there are 23 other Blocked-Chains in thread-dumps with the same issue. 

Chain 24:
"[STUCK] ExecuteThread: '22' for queue: 'weblogic.kernel.Default (self-tuning)'" id=415 idx=0x368 tid=10747 waiting for org/apache/log4j/spi/RootLogger@0x553efbf8 held by:
"[STUCK] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'" id=43 idx=0xb0 tid=6731 in chain 1

Thank you again.

Regards,
-Sawan.Patwari
Comment 5 Ralph Goers 2015-03-16 18:36:33 UTC
Yes, I am saying that the code in Log4j 2 is much different and locking is handled much differently. There is no lock on the root logger or on the appender loop.
Comment 6 Sawan Patwari 2015-03-17 05:27:17 UTC
Thank you Ralph. Appreciate your inputs. 

Regards,
-Sawan.Patwari
Comment 7 Aakash 2015-08-06 12:14:08 UTC
Hi Team,

I am facing issue with log4j root logger. RootLogger is getting blocked. Below are the thread dumps from our managed server. Could you please help me to resolve the issue.

###<Jul 21, 2015 9:23:58 AM IST> <Info> <Server> <aukpczbr.dc-dublin.de> <aukpczbr_p2> <[ACTIVE] ExecuteThread: '13' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1437467038573> <BEA-002634> <The server "pci_p2_ad_admin" disconnected from this server.> 
####<Jul 21, 2015 9:23:58 AM IST> <Error> <WebLogicServer> <aukpczbr.dc-dublin.de> <aukpczbr_p2> <[STANDBY] ExecuteThread: '11' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1437467038600> <BEA-000337> <[STUCK] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "652" seconds working on the request "weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl@58887aee", which is more than the configured time (StuckThreadMaxTime) of "600" seconds. Stack trace:
Thread-3471 "[STUCK] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'" <alive, suspended, blocked, priority=1, DAEMON> {
    -- Blocked trying to get lock: org.apache.log4j.spi.RootLogger@21cb1369[not locked]
    org.apache.log4j.Category.callAppenders(Category.java:204)
    org.apache.log4j.Category.forcedLog(Category.java:391)
    org.apache.log4j.Category.log(Category.java:856)
    org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:541)
    com.vodafone.pciadaptor.core.emis.HttpConnectionProbe.onRun(HttpConnectionProbe.java:105)
    com.vodafone.pciadaptor.core.scheduling.AbstractScheduledTask.run(AbstractScheduledTask.java:42)
    org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:51)
    java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
    java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
    java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
    org.springframework.scheduling.commonj.TimerManagerTaskScheduler$TimerScheduledFuture.timerExpired(TimerManagerTaskScheduler.java:112)
    org.springframework.scheduling.commonj.TimerManagerTaskScheduler$ReschedulingTimerListener.timerExpired(TimerManagerTaskScheduler.java:165)
    weblogic.timers.internal.commonj.ListenerWrap.timerExpired(ListenerWrap.java:37)
    weblogic.timers.internal.TimerImpl.run(TimerImpl.java:273)
    weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:528)
    weblogic.work.ExecuteThread.execute(ExecuteThread.java:207)
    weblogic.work.ExecuteThread.run(ExecuteThread.java:176)
}

>
Comment 9 Aakash 2015-08-06 14:16:34 UTC
Could you please help with a temporary solution for this. As this is creating issue on production server with business impact.

Thanks in advance
Comment 10 Aakash 2015-08-07 08:49:33 UTC
Hi Gary,

Could you please help with a temporary solution for resolving this issue. Also will upgrading log4j 1.x to log4j2 resolve this issue?
Comment 11 Ralph Goers 2015-08-07 09:24:37 UTC
There is no temporary fix for this issue and is one of the reasons Log4j 2 came about. The only fix is to upgrade to Log4j 2.
Comment 12 Aakash 2015-08-07 09:28:42 UTC
Thanks a lot Ralph. Appreciate your quick response.
Comment 13 Aakash 2015-08-07 13:02:37 UTC
As stated in the reference link provided by you, we have two solutions for upgrading lo4j 1.x to log4j2.At this point of time we wont be able to upgrade to log4j2 completely as this application deals with live transactions. So please suggest if we can can go with migrating to log4j 2 with the help of log4j 1.2 Bridge.Also let me know the latest and and stable version log4j1.2 bridge 

Can you also confirm if this solution is going to resolve this issue as it is affecting the live transactions.

Many thanks.
Comment 14 Ralph Goers 2015-08-07 13:18:32 UTC
Your stack trace shows you are calling Log4j1 via the SLF4J API. You can use Log4J 2's sLF4J binding instead of the Binding to Log4j 1 provided by the SLF4J project. 

Log4j 2 does not have this issue with locking.
Comment 15 Aakash 2015-08-10 13:38:04 UTC
Many Thanks Ralph.

Currently I am using log4j version 1.2.16 and slf4j version 1.6.1. Which is the stable version that can be used to resolve this issue.
Comment 16 Aakash 2015-08-10 13:39:27 UTC
Stable version for migrating using logging Bridge 1.x
Comment 17 Ralph Goers 2015-08-10 14:06:05 UTC
*** Bug 58218 has been marked as a duplicate of this bug. ***
Comment 18 Aakash 2015-08-12 07:08:31 UTC
Hi Ralph 

I have replaced the existing log4j 1.2.16 jar with log4j1.2-api jar version 2.3.Am I  replacing with the right jar for using bridge for migrating from log4j1.x to log4j 2. Could you please help.

Thanks in advance.
Comment 19 Gary Gregory 2015-08-12 15:50:48 UTC
Please see https://logging.apache.org/log4j/2.x/manual/migration.html