https://issues.apache.org/bugzilla/show_bug.cgi?id=50614
Summary: Lock in CallAppenders causing all Thread to wait
forever
Product: Log4j
Version: 1.2
Platform: Sun
OS/Version: Solaris
Status: NEW
Severity: major
Priority: P2
Component: Appender
AssignedTo: [email protected]
ReportedBy: [email protected]
Dear All,
We are facing a problem that JBoss Threads are all consumed causing the
whole web application to hang. We investigated the issue and found that all
Threads are waiting on a synchronized block inside log4j.
exactly in this block of code:
public
void callAppenders(LoggingEvent event) {
int writes = 0;
for(Category c = this; c != null; c=c.parent) {
// Protected against simultaneous call to addAppender, removeAppender,...
synchronized(c) {
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}
if(writes == 0) {
repository.emitNoAppenderWarning(this);
}
}
There are two reported bugs here (41214,44157) and we followed the below
recommendations:
1. upgrade log4j from 1.2.15 to 1.2.16.
2. upgrade jdk from 1.5.17 to 1.5.22 ( we cannot go for 1.6.22 right now)
More over, we made sure that there are no shared logger i.e. there are new
logger for each class and created by that class itself.
But the problem exists.
Here I collected the thread dump of threads locking the synchronize object over
few days.
2011-01-18
"Some Thread1" daemon prio=3 tid=0x011e0b78 nid=0x33a runnable
[0x53d7e000..0x53d7fa70]
at java.lang.Throwable.fillInStackTrace(Native Method)
at java.lang.Throwable. (Throwable.java:181)
at
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
at
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
at
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
- locked <0x780a04c8> (a org.apache.log4j.ConsoleAppender)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
- locked <0x7807cfa8> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.debug(Category.java:257)
____________________________
2011-01-17-13:51:28
Thread: Some Thread2 : priority:5, demon:true, threadId:5093,
threadState:RUNNABLE, lockName:null
java.lang.Throwable.getStackTraceElement(Native Method)
java.lang.Throwable.getOurStackTrace(Throwable.java:592)
java.lang.Throwable.printStackTrace(Throwable.java:511)
org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105)
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
_____________________________________
2010-12-27 13:29:47
Thread: Some Thread3 - Pre-Rendering Page - Rendering Page : priority:5,
demon:true, threadId:8960, threadState:RUNNABLE, lockName:null
java.lang.Throwable.fillInStackTrace(Native Method)
java.lang.Throwable.(Throwable.java:181)
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
________________________________________
Thread: Some Thread4 : priority:5, demon:true, threadId:8977,
threadState:RUNNABLE, lockName:null
java.lang.Throwable.getStackTraceElement(Native Method)
java.lang.Throwable.getOurStackTrace(Throwable.java:592)
java.lang.Throwable.printStackTrace(Throwable.java:511)
org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105)
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
____________________________________
Thread: Some Thread5 : priority:5, demon:true, threadId:8991,
threadState:RUNNABLE, lockName:null
java.lang.Throwable.getStackTraceElement(Native Method)
java.lang.Throwable.getOurStackTrace(Throwable.java:592)
java.lang.Throwable.printStackTrace(Throwable.java:511)
org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105)
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
____________________________________________________________
Thread: Some Thread6 : priority:5, demon:true, threadId:9017,
threadState:RUNNABLE, lockName:null
java.lang.Throwable.getStackTraceElement(Native Method)
java.lang.Throwable.getOurStackTrace(Throwable.java:592)
java.lang.Throwable.printStackTrace(Throwable.java:511)
org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105)
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
____________________________________________________________
2011-01-03 18:17:26
Thread: Some Thread 7 : priority:5, demon:true, threadId:38364,
threadState:RUNNABLE, lockName:null
java.io.FileOutputStream.writeBytes(Native Method)
java.io.FileOutputStream.write(FileOutputStream.java:260)
java.io.BufferedOutputStream.write(BufferedOutputStream.java:105)
java.io.PrintStream.write(PrintStream.java:412)
sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(StreamEncoder.java:336)
sun.nio.cs.StreamEncoder$CharsetSE.implFlushBuffer(StreamEncoder.java:404)
sun.nio.cs.StreamEncoder$CharsetSE.implFlush(StreamEncoder.java:408)
sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:152)
java.io.OutputStreamWriter.flush(OutputStreamWriter.java:213)
org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:57)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:315)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
__________________________________________________________
2011-01-03 18:22:43
Thread: Some Thread8 : priority:5, demon:true, threadId:9604,
threadState:RUNNABLE, lockName:null
java.lang.Throwable.getStackTraceElement(Native Method)
java.lang.Throwable.getOurStackTrace(Throwable.java:592)
java.lang.Throwable.printStackTrace(Throwable.java:511)
org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105)
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
_______________________________________
Thread: Some Thread9: priority:5, demon:true, threadId:38364,
threadState:RUNNABLE, lockName:null
java.lang.Throwable.getStackTraceElement(Native Method)
java.lang.Throwable.getOurStackTrace(Throwable.java:592)
java.lang.Throwable.printStackTrace(Throwable.java:511)
org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105)
org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:191)
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:483)
org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:64)
org.apache.log4j.PatternLayout.format(PatternLayout.java:503)
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
org.apache.log4j.Category.callAppenders(Category.java:203)
org.apache.log4j.Category.forcedLog(Category.java:388)
org.apache.log4j.Category.debug(Category.java:257)
************************
Is there any way to avoid this blocking?
Can we add some sort of timeout to release the lock?
appreciate your feedback.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
