https://issues.apache.org/bugzilla/show_bug.cgi?id=50213
Summary: Category callAppenders synchronization causes
java.lang.Thread.State: BLOCKED - synchronization can
be avoided by using immutable AppenderAttachableImpl
Product: Log4j
Version: 1.2
Platform: HP
OS/Version: Linux
Status: NEW
Severity: normal
Priority: P2
Component: Other
AssignedTo: [email protected]
ReportedBy: [email protected]
Using log4j 1.2.16 on Linux.
When logging from 10 threads almost simultaneously, I'm seeing intermittent
deadlocking. Doing a kill -3 on Linux shows the thread dump and shows
java.lang.Thread.State: BLOCKED - waiting to lock <0xd42e9a78> (a
org.apache.log4j.spi.RootLogger)
Looking at the Category code, I can see how threads could potentially deadlock:
Method: callAppenders(LoggingEvent event)
...
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;
}
}
...
However, before thinking too hard about exactly the scenario can occur I'd
rather just remove the need to synchronize altogether when looping through the
appenders attached to a Category.
Appenders are themselves thread safe due to AppenderSkeleton's doAppend()
method being synchronized. So, the only reason why Category synchronizes when
iterating through appenders is, as the comments say, to:
// Protected against simultaneous call to addAppender, removeAppender,...
This is only required because AppenderAttachableImpl aai is a mutable object
which allows appenders to be added or removed at any time. By making it
immutable (a copy-on-write list) we can avoid the synchronization at the most
contentious point in log4j, the point at which the logging occurs. I'm sure
we'll agree that adding and removing appenders is extremely rare compared to
writing logs. So, if we can remove the synchronization at this point then we
should see a significant benefit with very little performance hit for the
copy-on-write of the AppenderAttachableImpl.
I'll produce a patch for review.
Here's an extract of the kill -3 dump:
"message.receiver-1" prio=10 tid=0xcf2d4400 nid=0x6501 waiting for monitor
entry [0xcc12e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:205)
- waiting to lock <0xd42e9a78> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.info(Category.java:666)
"org.springframework.jms.listener.DefaultMessageListenerContainer#1-1" prio=10
tid=0xcf0e6800 nid=0x6507 waiting for monitor entry [0xcabc6000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:205)
- waiting to lock <0xd42e9a78> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.log(Category.java:856)
at
org.apache.commons.logging.impl.Log4JLogger.trace(Log4JLogger.java:146)
LOTS MORE OF THESE...
--
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]
