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

[Jeff Jensen]

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