-----Original Message----- From: logback-user-bounces@qos.ch [mailto:logback-user-bounces@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@qos.ch [mailto:logback-user- bounces@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@qos.ch [mailto:logback-user- bounces@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@qos.ch http://qos.ch/mailman/listinfo/logback-user