[logback-dev] [JIRA] Commented: (LBCLASSIC-45) Suggestion: Make LoggingEvent dumber, Logger more intelligent

[Ceki Gulcu (JIRA)]

    [ 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 "32900144 at 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 "15510444 at qtp0-2" discussed below
 
Thread "15510444 at 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 "32900144 at 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