[logback-user] OOM on debug level with SLF4j + Logback

Tue Sep 7 00:39:53 CEST 2010

Just a little additional info:
The MultiplexSocketAppender keeps a backlog of up to 1000 byte[] of serialized events to prevent congestion in case of event bursts.
This is probably unrelated since you said you removed the Lilith appender and still had the issue - but I wanted to make sure that you are aware of the fact.

Cheers,
Joern.

On 06.09.2010, at 23:30, Jeff Jensen wrote:

> 
> 
>> -----Original Message-----
>> From: logback-user-bounces at qos.ch [mailto:logback-user-bounces at qos.ch]
>> On Behalf Of Ceki Gülcü
>> Sent: Monday, September 06, 2010 3:33 PM
>> To: logback users list
>> Subject: Re: [logback-user] OOM on debug level with SLF4j + Logback
>> 
>> On 06/09/2010 10:09 PM, Jeff Jensen wrote:
>>> Heh, due to one of my fav things of Logback (parametric logging),
>> there are
>>> no "if(logger.isDebugEnabled())" calls in the codebase (makes me
>> happy).
>>> But that does lead to an idea I looked into a bit of what is
>> logged/what are
>>> methods called for the logging (what generates the toString(), etc.).
>> I
>>> didn't see anything obvious, but I did not do an exhaustive search.
>>> 
>>> Another thing I don't know is if it is test-induced or not.  My big
>> concern
>>> is what happens when running this code in production and we need
>> DEBUG on -
>>> is the OOM likely to occur?! :-/
>> 
>> Given that the cause of the OOM has not been identified, there is no
>> way to tell whether OOM exception will occur in production.
>> 
>> There are two things that change between enabled debug logger call and
>> a disabled one:
>> 
>> 1) the toString method of any parameters passed to the logger are
>> evaluated
>> 
>> 2) an LoggingEvent object is created
>> 
>> When you removed "stale" logging statements from your code, perhaps
>> you removed a statement with a parameter generating a large memory
>> footprint when its toString method was called.
> 
> Some of the removed messages were of data objects/entities.  Some had a
> small number of instance variables, some had large.
> I have no evidence either way; also depends on definition of "large" :-) !
> In review of them, none stood out to me to make that true (but could have
> easily missed something).
> 
> My interpretation at the time was the quantity of log messages, which I
> didn't think would have that kind of impact; slower exec speed, yes, due to
> the extra IO and String work.
> 
> 
>> Alternatively, the creation of many LoggingEvent can overwhelm memory,
>> especially if they continue to be referenced after the call to the
>> logger. Any appender or data structure holding on to LoggingEvents
>> can cause OOM exceptions.
> 
> Logging was heavy in DEBUG mode of our code, still is a decent amount but
> greatly reduced.  The high amount is what struck me, and as I removed log
> messages, the tests would run further before OOM.  This lead me to think it
> was general quantity more than a few heavy ones, but that could be
> misleading.
> 
> "Referenced" - I don't think our code continues referencing LoggingEvents;
> our code will just log the message.  After the logging, the only things
> still existing in our code that were shared with the log message are the
> data objects we wanted logged.  My guess is you already know that these two
> appenders must not hang onto a LoggingEvent.
>  - ch.qos.logback.core.ConsoleAppender 
>  - ch.qos.logback.core.FileAppender
> 
> Do encoders have any potential effect on continued reference?
> 
> 
>>> -----Original Message-----
>>> From: logback-user-bounces at qos.ch [mailto:logback-user-
>> bounces at qos.ch] On
>>> Behalf Of Joern Huxhorn
>>> Sent: Monday, September 06, 2010 2:04 PM
>>> To: logback users list
>>> Subject: Re: [logback-user] OOM on debug level with SLF4j + Logback
>>> 
>>> Well, on second thought I have to admit that it shouldn't have made
>> any
>>> difference anyway, given that the Logger needs to be created to
>> determine if
>>> a message should be logged or not...
>>> I assumed you used the LoggerFactory like this but it was the easiest
>> way to
>>> create a memory leak that I would've been aware of ;) (creating lots
>> of
>>> loggers)
>>> 
>>> Could it be possible that there was some awkward code inside of an
>>> if(logger.isDebugEnabled())-Scope?
>>> We've actually had such an issue twice in our codebase.
>>> 
>>> Because of that, I've developed a JUnit-Helper
>>> http://github.com/huxi/sulky/blob/master/sulky-
>> junit/src/main/java/de/huxhor
>>> n/sulky/junit/LoggingTestBase.java
>>> 
>>> For an example of its use, take a look at
>>> http://github.com/huxi/sulky/blob/master/sulky-
>> junit/src/test/java/de/huxhor
>>> n/sulky/junit/LoggingTestBaseExampleTest.java
>>> 
>>> You simple need to extend LoggingTestBase and provide a c'tor with an
>>> Boolean attribute that's calling the super-c'tor.
>>> 
>>> If you do this, all contained tests are executed three times:
>>> Once with Logging as defined by the usual logback-config
>>> Once with all Logging enabled (but ignored)
>>> Once with all Logging disabled.
>>> 
>>> This ensures that no such bugs are lurking in the code.
>>> It also results in a better test-coverage of your code since
>> otherwise every
>>> logging call will have a 50% branch coverage if wrapped in an
>>> if(logger.isXxxEnabled()) condition.
>>> This creates the IMHO wrong impression that code with lots of logging
>> isn't
>>> tested sufficiently.
>>> 
>>> I'm not sure if this will help you with your problem - but it might.
>>> 
>>> The dependency is
>>> <groupId>de.huxhorn.sulky</groupId>
>>> <artifactId>de.huxhorn.sulky.junit</artifactId>
>>> <version>0.9.11</version>
>>> 
>>> Joern.
>>> 
>>> On 06.09.2010, at 20:27, Jeff Jensen wrote:
>>> 
>>>> Hey Joern!
>>>> 
>>>> Thanks for the reply.  I should have mentioned that all loggers are
>>> created
>>>> as:
>>>>  private final Logger log =
>> LoggerFactory.getLogger(TheClassname.class);
>>>> 
>>>> None are static - I don't think there are affects of that, as it is
>> still
>>>> one logger instance per class.
>>>> 
>>>> 
>>>> Thanks for the code snippet.  I added that in a @BeforeClass and did
>> a
>>>> "loggers.size()" for the "// do something"; the max number was 673.
>>> That's
>>>> not high (to me).  And that count wouldn't go up or down based on
>> log
>>>> level...
>>>> 
>>>> I also output the names to review and they are all package or class
>> names.
>>>> 
>>>> 
>>>> Thanks again, I appreciate your ideas!
>>>> 
>>>> 
>>>> -----Original Message-----
>>>> From: logback-user-bounces at qos.ch [mailto:logback-user-
>> bounces at qos.ch] On
>>>> Behalf Of Joern Huxhorn
>>>> Sent: Monday, September 06, 2010 10:52 AM
>>>> To: logback users list
>>>> Subject: Re: [logback-user] OOM on debug level with SLF4j + Logback
>>>> 
>>>> Hi Jeff,
>>>> 
>>>> On 06.09.2010, at 17:25, Jeff Jensen wrote:
>>>> 
>>>>> 
>>>>> On a whim I changed the log level from DEBUG to INFO and the OOMs
>>> stopped;
>>>>> this really surprised us.  A lot of logging was occurring so I then
>>>>> experimented with appenders, e.g. not using Lilith appender, but
>> that had
>>>> no
>>>>> effect.  Only reducing the level had an effect.
>>>>> 
>>>> 
>>>> Nice to hear that Lilith wasn't the culprit ;)
>>>> 
>>>>> 
>>>>> Has anyone experienced this too?  Are their known issues or gotchas
>> that
>>>> we
>>>>> may be unknowingly doing with logging?  Any advice on how to find
>> root
>>>>> cause?
>>>>> 
>>>> 
>>>> The only idea I have how this could happen would be the creation of
>> a
>>> large
>>>> amount of loggers with different names.
>>>> Loggers instances are kept in the LoggerFactory so if you have code
>>>> somewhere that creates Loggers based on anything else than
>> classname, this
>>>> could be the reason.
>>>> For example, there could be some code that is creating Loggers using
>>>> toString - which would be quite random in case of Objects that have
>> no
>>>> explicit toString().
>>>> 
>>>> You could check for this using LoggerContext.getLoggerList():
>>>> 
>>>> ILoggerFactory loggerFactory = LoggerFactory.getILoggerFactory();
>>>> if (loggerFactory instanceof LoggerContext) {
>>>>  LoggerContext loggerContext = (LoggerContext) loggerFactory;
>>>>  List<Logger>  loggers=loggerContext.getLoggerList();
>>>>  // do something
>>>> }
>>>> 
>>>> I have no other idea right now.
>>>> 
>>>> Cheers,
>>>> Joern.
>> 
>> 
>> _______________________________________________
>> Logback-user mailing list
>> Logback-user at qos.ch
>> http://qos.ch/mailman/listinfo/logback-user
> 
> _______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://qos.ch/mailman/listinfo/logback-user