[logback-user] OOM on debug level with SLF4j + Logback
Joern Huxhorn
jhuxhorn at googlemail.com
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
More information about the Logback-user
mailing list