OutOfMemoryError warning system with Spring

Hi,

Everyone of us who has developed Java applications more involving that the HelloWorld example knows of the OOME. This happens when the Tenured Generation (old space) is filled up and there is no more available memory on the HEAP.

Heinz Kabutz, the world famous Java Champion and low-level, performant Java educator explains this approach in his newsletter 92. This article builds on his newsletter and demonstrates how to introduce, very simply, an OutOfMemoryError warning system in your applications with the help of Spring.

The beauty of this solution is that it uses features natively available in the JDK by using JMX  MBean server capabilities.

The OutOfMemoryError Warning class

The bulk of the OOME warning system is the following class:

package uk.co.jemos.experiments.oome;

import java.lang.management.ManagementFactory;
import java.lang.management.MemoryMXBean;
import java.lang.management.MemoryNotificationInfo;
import java.lang.management.MemoryPoolMXBean;
import java.lang.management.MemoryType;
import java.util.ArrayList;
import java.util.Collection;

import javax.management.Notification;
import javax.management.NotificationEmitter;
import javax.management.NotificationListener;

/**
 * This memory warning system will call the listener when we exceed the
 * percentage of available memory specified. There should only be one instance
 * of this object created, since the usage threshold can only be set to one
 * number.
 */

public class MemoryWarningSystem {

    private final Collection<Listener> listeners = new ArrayList<Listener>();

    private static final MemoryPoolMXBean tenuredGenPool = findTenuredGenPool();

    public MemoryWarningSystem() {
        MemoryMXBean mbean = ManagementFactory.getMemoryMXBean();
        NotificationEmitter emitter = (NotificationEmitter) mbean;
        emitter.addNotificationListener(new NotificationListener() {
            public void handleNotification(Notification n, Object hb) {
                if (n.getType().equals(
                        MemoryNotificationInfo.MEMORY_THRESHOLD_EXCEEDED)) {
                    long maxMemory = tenuredGenPool.getUsage().getMax();
                    long usedMemory = tenuredGenPool.getUsage().getUsed();
                    for (Listener listener : listeners) {
                        listener.memoryUsageLow(usedMemory, maxMemory);
                    }
                }
            }
        }, null, null);
    }

    public boolean addListener(Listener listener) {
        return listeners.add(listener);
    }

    public boolean removeListener(Listener listener) {
        return listeners.remove(listener);
    }

    public void setPercentageUsageThreshold(double percentage) {
        if (percentage <= 0.0 || percentage > 1.0) {
            throw new IllegalArgumentException("Percentage not in range");
        }
        long maxMemory = tenuredGenPool.getUsage().getMax();
        long warningThreshold = (long) (maxMemory * percentage);
        tenuredGenPool.setUsageThreshold(warningThreshold);
    }

    /**
     * Tenured Space Pool can be determined by it being of type HEAP and by it
     * being possible to set the usage threshold.
     */
    private static MemoryPoolMXBean findTenuredGenPool() {
        for (MemoryPoolMXBean pool : ManagementFactory.getMemoryPoolMXBeans()) {
            // I don't know whether this approach is better, or whether
            // we should rather check for the pool name "Tenured Gen"?
            if (pool.getType() == MemoryType.HEAP
                    && pool.isUsageThresholdSupported()) {
                return pool;
            }
        }
        throw new AssertionError("Could not find tenured space");
    }
}

The responsibility of this class is simple: everytime the JMX infrastructure communicates that the memory threshold has been exceeded this class notifies all its listeners passing as arguments the maximum memory available and the memory used so far.

 

The Thread Dumper

Thanks to Stephan and his blog we now have a Memory Thread Dumper which I have defined as a Spring bean and which gets invoked when the monitor gets an alert for heap being over the threshold. The memory dumper looks like the following (please note the that path to the file is Windows based - change accordingly):

/**
 *
 */
package uk.co.jemos.experiments.oome;

import java.io.BufferedWriter;
import java.io.File;
import java.io.FileWriter;
import java.io.IOException;
import java.io.Writer;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.HashMap;
import java.util.Map;

import org.apache.commons.io.IOUtils;
import org.springframework.stereotype.Component;

/**
 * @author mtedone
 *
 */
@Component
public class MemoryThreadDumper {

  

    /**
     * It dumps the Thread stacks
     *
     * @throws IOException
     */
    public void dumpStacks() {

        ThreadMXBean mxBean = ManagementFactory.getThreadMXBean();
        ThreadInfo[] threadInfos = mxBean.getThreadInfo(
                mxBean.getAllThreadIds(), 0);
        Map<Long, ThreadInfo> threadInfoMap = new HashMap<Long, ThreadInfo>();
        for (ThreadInfo threadInfo : threadInfos) {
            threadInfoMap.put(threadInfo.getThreadId(), threadInfo);
        }

        // choose our dump-file
        File dumpFile = new File("C:/tmp/stacks.dump");
        BufferedWriter writer = null;
        try {
            writer = new BufferedWriter(new FileWriter(dumpFile));
            this.dumpTraces(mxBean, threadInfoMap, writer);
        } catch (IOException e) {
            throw new IllegalStateException(
                    "An exception occurred while writing the thread dump");
        } finally {
            IOUtils.closeQuietly(writer);
        }

    }  

    private void dumpTraces(ThreadMXBean mxBean,
            Map<Long, ThreadInfo> threadInfoMap, Writer writer)
            throws IOException {
        Map<Thread, StackTraceElement[]> stacks = Thread.getAllStackTraces();
        writer.write("Dump of "
                + stacks.size()
                + " thread at "
                + new SimpleDateFormat("yyyy/MM/dd HH:mm:ss z")
                        .format(new Date(System.currentTimeMillis())) + "\n\n");
        for (Map.Entry<Thread, StackTraceElement[]> entry : stacks.entrySet()) {
            Thread thread = entry.getKey();
            writer.write("\"" + thread.getName() + "\" prio="
                    + thread.getPriority() + " tid=" + thread.getId() + " "
                    + thread.getState() + " "
                    + (thread.isDaemon() ? "deamon" : "worker") + "\n");
            ThreadInfo threadInfo = threadInfoMap.get(thread.getId());
            if (threadInfo != null) {
                writer.write("    native=" + threadInfo.isInNative()
                        + ", suspended=" + threadInfo.isSuspended()
                        + ", block=" + threadInfo.getBlockedCount() + ", wait="
                        + threadInfo.getWaitedCount() + "\n");
                writer.write("    lock=" + threadInfo.getLockName()
                        + " owned by " + threadInfo.getLockOwnerName() + " ("
                        + threadInfo.getLockOwnerId() + "), cpu="
                        + mxBean.getThreadCpuTime(threadInfo.getThreadId())
                        / 1000000L + ", user="
                        + mxBean.getThreadUserTime(threadInfo.getThreadId())
                        / 1000000L + "\n");
            }
            for (StackTraceElement element : entry.getValue()) {
                writer.write("        ");
                writer.write(element.toString());
                writer.write("\n");
            }
            writer.write("\n");
        }
    }

    // ------------------->> equals() / hashcode() / toString()

    // ------------------->> Inner classes

}

 

The Listener

In this example, the listener simply prints out the memory information and delegates to the Thread dumper the creation of a file with the thread dump; but in a real production system it could, in additon, send a notifacation to a monitoring tool for the infrastructure folks to be notified, or send alarms to BlackBerries, with the thread dump file attached, etc.

package uk.co.jemos.experiments.oome;

import javax.annotation.Resource;

import org.springframework.stereotype.Component;

@Component
public class MemoryWarningListenerImpl implements MemoryWarningListener {

    @Resource
    private MemoryThreadDumper threadDumper;

    public void memoryUsageLow(long usedMemory, long maxMemory) {
        System.out.println("Memory usage low!!!");
        double percentageUsed = (double) usedMemory / maxMemory;
        System.out.println("percentageUsed = " + percentageUsed);

        if (null == threadDumper) {
            throw new IllegalStateException("The Thread dumper cannot be null!");
        }

        threadDumper.dumpStacks();

    }

}

 

The Spring configuration

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xmlns:context="http://www.springframework.org/schema/context"
    xmlns:task="http://www.springframework.org/schema/task"
    xsi:schemaLocation="http://www.springframework.org/schema/task http://www.springframework.org/schema/task/spring-task-3.0.xsd
        http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd
        http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd">

    <context:component-scan base-package="uk.co.jemos.experiments.oome" />

    <bean id="memoryWarningSystem">
        <property name="percentageUsageThreshold" value="0.7" />
    </bean>   

    <task:annotation-driven scheduler="myScheduler" />   

    <task:scheduler id="myScheduler" pool-size="10" />   

</beans>

In Spring I simply defines a bean for the Memory warning system. I externalised the declaration in XML (e.g. didn't use the @Component annotation here) because I wanted to pass the threshold percentage as property (which could be retrieved externally). Alternatively, if you want to use the annotations, you could simply declare a bean of type Double, fill it with the property value and inject it in the OOME warning bean.

The rest of the Spring configuration sets up the Task infrastructure.

The Memory HEAP filler

I created a simple task which progressively fills up the HEAP by adding random doubles to a Collection<Double>. This solution uses the new Spring 3 task feature:

package uk.co.jemos.experiments.oome;

import java.util.ArrayList;
import java.util.Collection;

import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.stereotype.Component;

@Component
public class MemoryFillerTaskExecutor {

    private static final Collection<Double> GARBAGE = new ArrayList<Double>();

    @Scheduled(fixedDelay = 1000)
    public void addGarbage() {
        System.out.println("Adding data...");
        for (int i = 0; i < 1000000; i++) {
            GARBAGE.add(Math.random());
        }

    }

}

The Maven Setup

I used Maven to build this project and to create an executable. This is the pom.xml

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>
  <groupId>uk.co.jemos.experiments</groupId>
  <artifactId>memory-warning-system</artifactId>
  <version>0.0.1-SNAPSHOT</version>
  <name>memory-warning-system</name>
  <build>
    <plugins>
      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-jar-plugin</artifactId>
        <version>2.3.1</version>
        <configuration>
          <archive>
            <manifest>
              <addClasspath>true</addClasspath>
              <mainClass>uk.co.jemos.experiments.oome.MemTest</mainClass>
            </manifest>
          </archive>
        </configuration>
      </plugin>
      <plugin>
        <groupId>org.apache.maven.plugins</groupId>
        <artifactId>maven-assembly-plugin</artifactId>
        <version>2.2.1</version>
        <executions>
          <execution>
            <id>executable</id>
            <phase>install</phase>
            <goals>
              <goal>assembly</goal>
            </goals>
          </execution>
        </executions>
        <configuration>
          <outputDirectory>${project.build.directory}/executable</outputDirectory>
          <descriptors>
            <descriptor>src/main/assembly/executable.xml</descriptor>
          </descriptors>         
        </configuration>
      </plugin>
    </plugins>
  </build>
  <dependencies>
    <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-beans</artifactId>
      <version>3.0.5.RELEASE</version>     
    </dependency>
    <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-context</artifactId>
      <version>3.0.5.RELEASE</version>     
    </dependency>
    <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-core</artifactId>
      <version>3.0.5.RELEASE</version>     
    </dependency>
    <dependency>
      <groupId>javax.annotation</groupId>
      <artifactId>jsr250-api</artifactId>
      <version>1.0</version>
    </dependency>
    <dependency>
      <groupId>commons-io</groupId>
      <artifactId>commons-io</artifactId>
      <version>2.0.1</version>
    </dependency>
    <dependency>
        <groupId>junit</groupId>
        <artifactId>junit</artifactId>
        <version>4.8.2</version>
        <scope>test</scope>
    </dependency>
    <dependency>
        <groupId>log4j</groupId>
        <artifactId>log4j</artifactId>
        <version>1.2.16</version>       
        <scope>test</scope>
    </dependency>
  </dependencies>
</project>

When running mvn clean install Maven will create a memory-warning-system-0.0.1-SNAPSHOT-jar-with-dependencies.jar file under target/executable. To execute the jar, open a command prompt and point to target/executable then execute:

$ jar -xvf memory-warning-system-0.0.1-SNAPSHOT-jar-with-dependencies.jar

$ java -Xmx64m -jar memory-warning-system-0.0.1-SNAPSHOT.jar

The results

This is what I see in my console:

20-Jul-2011 22:43:09 org.springframework.context.support.AbstractApplicationContext prepareRefresh
INFO: Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@7c64dc11: startup date [Wed Jul 20 22:43:09 BST 2011]; root of context hierarchy
20-Jul-2011 22:43:09 org.springframework.beans.factory.xml.XmlBeanDefinitionReader loadBeanDefinitions
INFO: Loading XML bean definitions from class path resource [appCtx.xml]
20-Jul-2011 22:43:10 org.springframework.scheduling.concurrent.ExecutorConfigurationSupport initialize
INFO: Initializing ExecutorService  'myScheduler'
20-Jul-2011 22:43:10 org.springframework.context.support.AbstractApplicationContext$BeanPostProcessorChecker postProcessAfterInitialization
INFO: Bean 'myScheduler' of type [class org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
20-Jul-2011 22:43:10 org.springframework.beans.factory.support.DefaultListableBeanFactory preInstantiateSingletons
INFO: Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7ec5495e: defining beans [memoryFillerTaskExecutor,memoryThreadDumper,memoryWarningListenerImpl,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,memoryWarningSystem,org.springframework.scheduling.annotation.internalAsyncAnnotationProcessor,org.springframework.scheduling.annotation.internalScheduledAnnotationProcessor,myScheduler]; root of factory hierarchy
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Memory usage low!!!
percentageUsed = 0.7066739850741411
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
Adding data...
20-Jul-2011 22:44:02 org.springframework.scheduling.support.MethodInvokingRunnable run
SEVERE: Invocation of method 'addGarbage' on target class [class uk.co.jemos.experiments.oome.MemoryFillerTaskExecutor] failed
java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:2760)
    at java.util.Arrays.copyOf(Arrays.java:2734)
    at java.util.ArrayList.ensureCapacity(ArrayList.java:167)
    at java.util.ArrayList.add(ArrayList.java:351)
    at uk.co.jemos.experiments.oome.MemoryFillerTaskExecutor.addGarbage(MemoryFillerTaskExecutor.java:19)
    at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
    at org.springframework.scheduling.support.MethodInvokingRunnable.run(MethodInvokingRunnable.java:65)
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:51)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
    at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)

..etc

The Thread dump result:

Dump of 6 thread at 2011/07/20 22:43:41 BST

"DestroyJavaVM" prio=5 tid=11 RUNNABLE worker
    native=false, suspended=false, block=0, wait=0
    lock=null owned by null (-1), cpu=546, user=436

"Reference Handler" prio=10 tid=2 WAITING deamon
    native=false, suspended=false, block=1, wait=2
    lock=java.lang.ref.Reference$Lock@7f328c7a owned by null (-1), cpu=0, user=0
        java.lang.Object.wait(Native Method)
        java.lang.Object.wait(Object.java:485)
        java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)

"Finalizer" prio=8 tid=3 WAITING deamon
    native=false, suspended=false, block=1, wait=2
    lock=java.lang.ref.ReferenceQueue$Lock@6c3c9c31 owned by null (-1), cpu=15, user=0
        java.lang.Object.wait(Native Method)
        java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Attach Listener" prio=5 tid=5 RUNNABLE deamon
    native=false, suspended=false, block=0, wait=0
    lock=null owned by null (-1), cpu=0, user=0

"myScheduler-1" prio=5 tid=10 TIMED_WAITING worker
    native=false, suspended=false, block=0, wait=103
    lock=null owned by null (-1), cpu=1950, user=1934
        sun.misc.Unsafe.park(Native Method)
        java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)                java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
        java.util.concurrent.DelayQueue.take(DelayQueue.java:164)                java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)                java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
        java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        java.lang.Thread.run(Thread.java:662)

"Signal Dispatcher" prio=9 tid=4 RUNNABLE deamon
    native=false, suspended=false, block=0, wait=0
    lock=null owned by null (-1), cpu=0, user=0

 It is clear from the memory dump that myScheduler-1 is the culprit and the thread which shouldbe investigated.