OOM on debug level with SLF4j + Logback
Midway through the development of a new app, our Integration/Functional tests began failing with OOM. -Xmx is set to 1024m, so there should be plenty of memory. Our Logback test configuration logs to console, text file, and Lilith file. I profiled with Visual VM and found nothing extraordinary (memory usage bounced around, expanded, GC'd, came close to the max). 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. 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? We then removed a lot of debug messages (good to clean up some of the development leftover junk, but some could have proven useful). Running with DEBUG log level no longer fails with OOM. I started creating a small project to demonstrate this issue, but it seems will require "a lot of stuff" to mimic our ITs (using dbUnit). Just running some simple log messages out in a big loop didn't show much. The test appender snippets: <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36}: %msg%n</pattern> </encoder> </appender> <property name="baseLogFileName" value="${logback.file.path:-target/}${moduleName}-TEST" /> <appender name="FILE-LOG" class="ch.qos.logback.core.FileAppender"> <file>${baseLogFileName}.log</file> <append>false</append> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <pattern>%date %contextName [%thread] %-5level %-55logger{55} %mdc: %marker: %msg%n</pattern> </encoder> </appender> <appender name="FILE-LILITH" class="ch.qos.logback.core.FileAppender"> <file>${baseLogFileName}.lilith</file> <append>false</append> <encoder class="de.huxhorn.lilith.logback.encoder.ClassicLilithEncoder"> <IncludeCallerData>true</IncludeCallerData> </encoder> </appender> <appender name="SECURITY_FILE" class="ch.qos.logback.core.FileAppender"> <file>${logback.file.path:-target/}${moduleName}-security-TEST.log</file> <append>false</append> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <pattern>%date %contextName [%thread] %-5level %-55logger{55} %mdc: %marker: %msg%n</pattern> </encoder> </appender> Here are the versions and the Maven POM deps in use: <lilithVersion>0.9.39</lilithVersion> <logbackVersion>0.9.24</logbackVersion> <slf4jVersion>1.6.1</slf4jVersion> <dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> <version>${slf4jVersion}</version> </dependency> <dependency> <groupId>org.slf4j</groupId> <artifactId>jcl-over-slf4j</artifactId> <version>${slf4jVersion}</version> </dependency> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>${logbackVersion}</version> </dependency> <dependency> <groupId>de.huxhorn.lilith</groupId> <artifactId>de.huxhorn.lilith.logback.encoder.classic</artifactId> <version>${lilithVersion}</version> <scope>runtime</scope> </dependency> <dependency> <groupId>de.huxhorn.lilith</groupId> <artifactId>de.huxhorn.lilith.logback.appender.multiplex-classic</artifactId
<version>${lilithVersion}</version> <scope>runtime</scope> </dependency> <dependency> <groupId>de.huxhorn.lilith</groupId> <artifactId>de.huxhorn.lilith.logback.servlet</artifactId> <version>${lilithVersion}</version> <scope>runtime</scope> </dependency>
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.
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
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... For an example of its use, take a look at http://github.com/huxi/sulky/blob/master/sulky-junit/src/test/java/de/huxhor... 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
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
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?! :-/ -----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
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
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@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.
-----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
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@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
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
Hello Jeff, Why not just analyse the heap dump with jhat or a profiler? That's the normal approach for investigating an OOME and you should be able to see very quickly what's using all the memory. There's usually little need to try and speculate about the problem like this or manually eyeball your code.
Midway through the development of a new app, our Integration/Functional tests began failing with OOM. -Xmx is set to 1024m, so there should be plenty of memory. Our Logback test configuration logs to console, text file, and Lilith file.
participants (4)
-
Ceki Gülcü -
Chris Miller -
Jeff Jensen -
Joern Huxhorn