[
http://jira.qos.ch/browse/LBCLASSIC-45?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11164#action_11164
]
Ceki Gulcu commented on LBCLASSIC-45:
-------------------------------------
For the record,
Thread "32900...@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl" invokes
o.m.jetty.servlet.ServletHandler.handle(ServletHandler.java:414)
as a consequence, a few lines down the stack trace
o.m.log.Slf4jLog.warn(Slf4jLog.java:128) is invoked
and as a consequence, a few lines further
c.q.l.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
is invoked. This latest call causes the thread to obtain a lock on
"<0x7395a770> (a ch.qos.logback.core.ConsoleAppender)"
During the logging process, PackagingDataCalculator.calculate is
invoked, this causes the thread to invoke
o.m.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341)
which attempts to obtain a lock on "<0x7391a760>
(o.m.jetty.webapp.WebAppClassLoader)"
which is already in possession of thread "15510...@qtp0-2" discussed below
Thread "15510...@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl" invokes
org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341)
which obtains a lock on <0x7391a760> (a o.m.jetty.webapp.WebAppClassLoader)
as a consequence, a few lines further
o.m.log.Slf4jLog.debug(Slf4jLog.java:73) is invoked
as a result,
c.q.l.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
is invoked, this latest call attempts to lock
<0x7395a770> (a c.q.l.core.ConsoleAppender) which is already in
possession of thread "32900...@qtp0-0" as discussed above.
The bug is an illustration of deadlocks occurring when a logback component,
during the process of logging, invokes a service which does logging itself.
There are two cheap and immediate ways to get rid of this *particular* bug.
1) reduce logging verbosity for the "org.mortbay.log" logger, which is the sole
logger used by Jetty. This can be done by setting the level
of "org.mortbay.log" logger to any level above or equal to INFO, that is INFO,
WARN and ERROR.
2) disable the addition of packaging information in stack traces output by
ConsoleAppender. This can be accomplished by adding "%ex" to
the end of conversion pattern. For example, if the configuration snippet for
ConsoleAppender is
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>%-5r [%thread] %level - %msg%n</Pattern>
</layout>
</appender>
then, change it to:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<!-- note the addition of %ex at the end -->
<Pattern>%-5r [%thread] %level - %msg%n%ex</Pattern>
</layout>
</appender>
Of course, while these two solutions are cheap and yield immediate results,
they are intellectually unsatisfactory.
Reducing the locking granularity in AppenderBase would most probably get rid of
the problem. Strictly speaking, as far as FileAppender and
co. are concerned, the lock needs to be active only while writing to the file.
In a similar fashion, the scope of lock could be reduced in many other
appenders, with DBAppender as one notable exception.
> Suggestion: Make LoggingEvent dumber, Logger more intelligent
> -------------------------------------------------------------
>
> Key: LBCLASSIC-45
> URL: http://jira.qos.ch/browse/LBCLASSIC-45
> Project: logback-classic
> Issue Type: Improvement
> Components: Other
> Affects Versions: unspecified
> Environment: Operating System: All
> Platform: All
> Reporter: Joern Huxhorn
> Assignee: Logback dev list
> Priority: Minor
>
> This change would introduce incompatibilities with previous versions but
> would increase general logging performance and decrease size of serialized
> events.
> After I have turned you off sufficiently ;), let me explain my idea:
> At the moment, LoggingEvent is handling it's own initialization. It even
> contains measures against manipulation after initialization in that a call of
> a setter results in an IllegalStateException if the attribute has already
> been initialized before.
> Instead, I'd suggest that LoggingEvent is changed into a dumb data container
> with getter and setters for all it's attributes.
> If it's really necessary to have a semi-const LoggingEvent I'd suggest to
> define LoggingEvent as an interface containing only the getters of the
> attributes and an implementation LoggingEventImpl that implements
> LoggingEvent including getters and setters.
> This communicates the *intent* that LoggingEvents aren't supposed to be
> modified but nothing more. It would still be possible to change e.g. the
> content of an array like argumentArray. Even if the getter would return a
> copy of the contained array, generating heat in the process, it would *still*
> be possible to brutally manipulate the LoggingEvent using
> java.lang.reflection setAccessible(true) so it's just not possible to
> guarantee constness.
> Instead of having a pseudo-const LoggingEvent let's dump the constness
> altogether and make it a dumb data container that contains no logic at all.
> This would instead be moved to the Logger class.
> I'd also suggest to remove formattedMessage and change the argumentArray to
> String[].
> This is possible because logback-classic/slf4j promises formatted message,
> not LoggingEvent.
> It would increase performance because a Logger would simply create a
> LoggingEvent without performing a possibly unnecessary formatting of the
> message. Creation of LoggingEvents should be as fast and simple as possible,
> obviously.
> The formatting of the message should/would instead be performed in the
> appender (or, more generally, user of the event) if required.
> A serializing appender, an xml appender (e.g. using java.beans.XMLEncoder) or
> a socket appender would *not* require a formatted message, executing
> significantly faster than before.
> The argumentArray should be String[] to securely prevent
> java.io.NotSerializableException in the serializer and .
> java.lang.ClassNotFoundException in the deserializer.
> LoggerRemoteView and LoggerContextRemoteView should be changed the same way
> as LoggingEvent, i.e. just data container, logic moved to Logger, for similar
> reasons.
> I have to admit, though, that I currently don't understand the reason the
> LoggingEvent needs to know about LoggerContext beside resolving of the Logger
> name. I couldn't find code that uses
> LoggerContextRemoteView.getPropertyMap(), beside loading and saving it.
> So I think it may be possible that LoggerRemoteView isn't really necessary
> and could be removed from LoggingEvent... remembering the Logger name instead.
> fqnOfLoggerClass could be omitted because the CallerData would be created in
> the Logger where fqnOfLoggerClass is known.
> And last but not least I'd also change Level into an java.lang.Enum.
> I don't expect that all this will be done but I wanted to suggest it
> nevertheless because it would both increase performance and produce cleaner
> code.
> Breaking compatibility would IMHO be worth it - after all, logback isn't 1.0,
> yet ;)
> If you are interested I'd volunteer to implement those changes, after signing
> http://logback.qos.ch/cla.txt of course.
> Keywords:
> Inversion of Control (IoC), separation of concerns, KISS principle
> Related bugs:
> http://bugzilla.qos.ch/show_bug.cgi?id=100
> http://bugzilla.qos.ch/show_bug.cgi?id=118
> http://bugzilla.slf4j.org/show_bug.cgi?id=70
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
