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: [email protected] [mailto:[email protected]] >> 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: [email protected] [mailto:logback-user- >> [email protected]] 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: [email protected] [mailto:logback-user- >> [email protected]] 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 >> [email protected] >> http://qos.ch/mailman/listinfo/logback-user > > _______________________________________________ > Logback-user mailing list > [email protected] > http://qos.ch/mailman/listinfo/logback-user _______________________________________________ Logback-user mailing list [email protected] http://qos.ch/mailman/listinfo/logback-user
