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

Ceki Gülcü ceki at qos.ch
Mon Sep 6 22:32:55 CEST 2010


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.

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.


> -----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.




More information about the Logback-user mailing list