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

Joern Huxhorn jhuxhorn at googlemail.com
Mon Sep 6 21:03:50 CEST 2010


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/huxhorn/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/huxhorn/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



More information about the Logback-user mailing list