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

6 Sep 2010

      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>

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

Jeff Jensen