Cougaar Memory Profiler

NOTE:
As of January 2007, the Cougaar memory profiler should be considered deprecated. The Cougaar memory profiler was written to overcome limitations in Sun's JVMPI implementation, as used by hprof, OptimizeIt^(tm), JProbe^(tm), etc. Most of these problems have been fixed in Java 1.6.

Instead of using the Cougaar memory profiler, we recommend that developers first try Sun's new, free `jhat` profiler:
  http://java.sun.com/javase/6/docs/technotes/tools/index.html#troubleshoot
See the above link's Developer's Guide for notes on how to use jhat and interpret the results.

For future reference, there may be interest in extending jhat to better identify non-leak memory problems and potential solutions. For example, a developer might want to estimate the potential memory savings of adding caching (e.g. intern the most common Strings) or changing a data structure (e.g. change an "Integer" field to a primitive "int"). These "identify potential memory saving" analysis methods would best be implemented as enhancements to the post-processing jhat dump reader:
  j2se/src/share/classes/com/sun/tools/hat/Main.java
The modified code could be a new Cougaar project (e.g. "jhat_extensions") and offered back to Sun.

The remainder of this page describes the Cougaar memory profiler, which still works but is more difficult to configure and use than jhat. Some of the concepts may be of interest for use in future projects, e.g. bytecode instrumentation and weak reference tables.

• Overview
• Snapshots
• Usage (General)
• Usage (ACME specific)
• Design details

Overview

The Cougaar memory profiler is a tool for debugging memory usage and leaks in any Java application. It features a scalable 100% Java design that is lighter weight than existing JVMPI-based profilers (hprof, OptimizeIt^(tm), JProbe^(tm), etc).

Memory leaks can arise in Java applications due to unintentional object references. For example, an application may fail to remove callback listeners or close streams, preventing these objects from being garbage collected. Even minor leaks can grow to major problems in deployed systems.

The profiler tracks memory usage within the application by using tables of WeakReferences. The developer selects which classes should be tracked and runs an automated classfile editor (using BCEL) to add profiling instructions to the constructors. The profiler maintains pointers to the live instances and can display useful debugging information:

• Total number of allocations of a profiled class, including the number of live and GC'ed instances
• Free/used/max VM heap size and force GC
• Show instances in order of:
  • allocation timestamp
  • compareTo
  • hashCode
  • toString
  • "size" (e.g. ArrayList.size() & String.length())
  • "capacity" (e.g. ArrayList.elementData.length)
  For example, find the largest HashMaps, ten newest "com.Foo", oldest "com.Foo", etc.
• Count unique occurences of:
  • allocation stacktrace
  • equals
  • toString
  • hashCode
  • allocation timestamp (& mod second/minute/hour)
  • "size" (& mod 100/1000)
  For example, what's the most common allocation point for ArrayLists, which are the most common "equals" values (for potential caching), etc.
• Sample instances for the above order/count views. For example, randomly select 100 of the 1000+ Strings and show the 10 most common "equals" values.
• The profiler can be configured to randomly sample the allocations to further reduce runtime overhead on a per-class basis. For example, track 5% of allocated Strings. The UI will adjust the displayed data to match the sampling ratio(s).

An interactive servlet-based UI is included that displays all the above profiling data. A servlet-based UI was developed instead of a Swing UI since it matched the Cougaar Agent Architecture's embedded servlet server. It'd be straight-forward to port the servlet to Swing or create a JEditorPane/HTMLEditorKit adaptor. The servlet has minimal Cougaar dependencies and can be modified to run in any servlet server.

Jump to snapshots

The developer controls the profiling overhead by selecting which classes to profile and reducing the level of profiling (e.g. turning off allocation stacktrace data). The runtime overhead is less than JVMPI tools, partially because the JVMPI tools must maintain similar heap tables (see the hprof source in $JDK/j2se/src/share/tools/hprof for details). We've found the JVMI overhead to be prohibitively expensive when debugging large applications. Long-term JSR-163 (Java^(tm) Platform Profiling Architecture) may address some of these performance issues, however the draft specification suggests that bytecode-based object profiling may be the recommended approach.

There are a couple noteworthy limitations of this approach vs JVMPI:

• The profiler can't trace the VM's roots, so one can't tell why an object hasn't been GC'ed. The profiler can help figure out which classes are being leaked and when/where they were allocated, which is often sufficient for most debugging.
• Arrays can't be profiled, since they're native to the VM and lack a constructor method. In the future this could be supported by tracking "newarray" bytecodes in all classes. Some VM-internal arrays can't be tracked, e.g. thread stacks. For now the profiler's "+Capacity Bytes" can track all arrays referenced by class fields (e.g. an ArrayList's "Object[] elementData").
• A handful of "java.lang" classes can't be profiled due to VM loading constraints:
  • java.lang.Class
  • java.lang.Object
  • java.lang.String$CaseInsensitiveComparator
  • java.lang.ThreadGroup
  • java.lang.Throwable
  • java.lang.ref.Reference
  • java.lang.ref.SoftReference
  • java.lang.ref.WeakReference
  Constant strings in class/interface APIs are also hidden within the VM, as are the Classes themselves and some dynamic proxies. Some odd JDK-internal classes may also be excluded (e.g. "sun.misc.Ref").

The main project page has the latest release. The download contains a "run" script that runs a simple example application.

Please send questions and comments to the cougaar-developers@cougaar.org mailing list.

Snapshots

Here's an example HTML snapshot:

The above snapshot shows:

• VM heap memory used/free/total/max
• Rows of profiled classes, where the "Live" and "+Capacity Bytes" columns are the most important. In Mozilla the column links will sort the column using JavaScript.

Here's a key for each table row:

Type

The class name

Sample%

The percent of allocated instances that were tracked. This is an option specified by the developer in the profiler filter configuration.

Live

The number of live instances of the class, multiplied by 1/sample

GC'ed

The number of garbage collected instances of the class, multiplied by 1/sample

Total

"Live" + "GC'ed"

Bytes Each

The estimated size of each instance, based upon the object header size and number of fields in the object

*Live

"Live" * "Bytes Each"

+Capacity Bytes

"*Live" + "Capacity Bytes", where "Capacity Bytes" is the sum of array lengths multipled by array element size in all the live instances (e.g. for ArrayList, for each "Object[] elementData", the sum of:
  (elementData == null ? 0 : 12 + 4*elementData.length)

Size Sum

The sum of all "size()" values of the instances (e.g. for Vector, the sum of all "int elementCount" values)

Size Max

The maximum "size()" of the live instances

Size Max Ever

The maximum "Size Max" observed since the start of the run

Size Mean

"Size Sum" / "Live"

Capacity Sum

The sum of all array lengths in all the live instances (e.g. for ArrayList, for each "Object[] elementData", the sum of:
  (elementData == null ? 0 : elementData.length)

Capacity Max

The maximum array length of the live instances

Capacity Max Ever

The maximum "Capacity Max" observed since the start of the run

Capacity Mean

"Capacity Sum" / "Live"

For example, 1% of String allocations were tracked. Currently 56 of 28042 tracked Strings are live, so we can estimate that 5600 are live out of 2804200 allocated (0.2%). Each String costs 24 bytes excluding the char[] data:

  header + fields =
  header + "char[] value" + "int offset" + "int count" + "int hash" =
  8 + 4 + 4 + 4 + 4 =
  24

If we click on the "java.lang.String" row a new page is generated:

This simply repeats the above data and allows the user to submit a query on instances of "java.lang.String". Here we select a decreasing view by "length()" and see:

In this run we disabled "java.*" allocation timestamps and stacktraces, to minimize the performance overhead, but we can see the "toString()" and other useful information. In this example shows the largest 20 of all 30 Strings (of the 1% we tracked).

Additional snapshots and notes can be found here.

Usage

BCEL 5.1 is required to modify the classes but not required when running the profiler.

The "profiler_transform/bin/transform_jar" script can be used to instrument complete jars (e.g. "lib/core.jar", "sys/tomcat_40.jar", etc) or JDK packages (e.g. "java.lang", "java.util", etc). For options run:

  ./profiler_impl/bin/transform_jar --help

The "transform_jar" script allows the developer to specify an "OptionsFactory" class that will define the profiling level at runtime, e.g.:

  ./profiler_impl/bin/transform_jar --config=foo.MyConfig xerces

    public static final Options getOptions(
        String module,
        String classname) {..}

The recommended usage is to specify a custom implementation that you'll modify between runs. This will allow you to run the "transform_jar" script on your jars only once (to instrument the bytecode and specify your OptionsFactory) and in subsequent runs you'll only need to change your OptionsFactory to change the profiling config.

Here's an example:

  package foo;

  import org.cougaar.profiler.Options;

  public class MyConfig {

    /**
     * Option that will track 100% of allocations,
     * record allocation timestamp,
     * record allocation stacktrace,
     * record size/capacity/context.
     * <p>
     * This is the best detail but the most overhead.
     */
    private static final Options FULL_DETAIL =
      new Options(
          true, // time
          true, // stack
          true, // size
          true, // capacity
          true, // context
          1.00  // sampleRatio
          );

    /**
     * Track only 1% of allocations,
     * record only the instance itself,
     * allow size/capacity.
     * <p>
     * This is very low overhead but only samples a small
     * subset of the instances.  This is ideal for the
     * initial profiling runs, to get a rough idea of the
     * allocation counts.
     */
    private static final Options MIN_DETAIL =
      new Options(
          false, // time
          false, // stack
          true,  // size
          true,  // capacity
          false, // context
          0.01   // sampleRatio
          );

    /*
     * The profiled class will call this method to get its options.
     *
     * @param module optional module name, e.g. "xerces" or null
     * @param classname non-null class name, e.g.
     *   "org.apache.xerces.dom.DocumentImpl$LEntry"
     * @return profiling options for the class, or null if the
     *   class shouldn't be tracked.
     */
    public static final Options getOptions(
        String module,
        String classname) {
      if ("core".equals(module)) {
        // we're interested in all classes in "lib/core.jar".
        // we want to track every allocation, timestamp, and stack
        return FULL_DETAIL;
      } else if (classname.startsWith("java.")) {
        // we're a little interested in "java.*", but
        // not enough to suffer a big overhead.  This is a good
        // "scatter-shot" approach.
        return MIN_DETAIL;
      } else {
        // everything else will be ignored
        return null;
      }
    }
  }

  #!/bin/sh
  ..
  BOOTCLASSPATH="\
    -Xbootclasspath/p:$COUGAAR_INSTALL_PATH/lib/profiler_config.jar\
    -Xbootclasspath/p:$COUGAAR_INSTALL_PATH/lib/profiler_impl.jar\
    -Xbootclasspath/p:$COUGAAR_INSTALL_PATH/lib/javalangpatch.jar\
    -Xbootclasspath/p:$COUGAAR_INSTALL_PATH/lib/javaiopatch.jar"
  ..
  java $BOOTCLASSPATH ..

  public JavaClass modifyClass(JavaClass clazz) {..}

ACME Usage

Here are usage notes specific to ACME, which is Cougaar's automation scripting environment (soon to be open-sourced). This is primarily of interest to Cougaar and Ultra*Log developers.

Download the latest profiler install and unzip it into your $CIP. It'll overwrite:
  $CIP/build/data/default.build
to specify the compile dependencies of UL jars (e.g. "ar_mic.jar").

To verify the basic install, run the "$CIP/run" script. It should generate output similar to "$CIP/run.log". After this test, delete the temporary files:
  rm -rf $CIP/tmp
  rm $CIP/lib/javautilpatch*
Also delete the example jar and config, which you won't need for testing:
  rm $CIP/lib/profiler_examples.jar
  rm $CIP/lib/profiler_config.jar


First you must create an "OptionsFactory" Java class to control the level of profiling. An example is shown above named "foo.MyConfig". A modified zip containing the source, jar, and compile script can be found here. This implementation will enable minimal profiling for all classes:
  Track 1% of instance allocations at minimal detail
You may want to modify the "profiler_config/src/foo/MyConfig.java" to profile more/less classes or capture more/less detail; see the above usage section for details.

Next you must transform the jars that you will profile. You can transform all the jars in sys and lib using:

  #!/bin/sh

  CONFIG="--config=foo.MyConfig"

  cd $CIP || exit -1

  # profile everything!  This may take a while...
  #
  # The following errors are expected:
  #   icu4j:        two class files are corrupt
  #   jena:         missing jars (sesame, antlr, sleepycat)
  #   juddi:        missing jars (axis)
  #   log4j:        missing jars (jms, jmx)
  #   openmap:      missing jars (j3d)
  #   tomcat_40:    missing jars (jmx)
  #   vishnuServer: missing jars (vishnu, util)
  # These errors and related NPEs can be ignored, since the classes
  # that depend upon these missing jars will never be loaded at
  # runtime.
  JAVA_PKGS="applet awt beans io lang math net nio rmi security sql text util"
  for x in $JAVA_PKGS; do ./transform_jar $CONFIG java.$x; done
  for x in $CIP/lib/*.jar; do ./transform_jar $CONFIG $x; done
  for x in $CIP/sys/*.jar; do ./transform_jar $CONFIG $x; done

  #!/bin/sh

  # replace second line:
  #  <script LANGUAGE="JavaScript" SRC="/$~/profiler?action=script"></script>
  # with:
  #  <script LANGUAGE="JavaScript" SRC="tablesort.js"></script>
  for x in $*; do
    cat <<"EOF" | ed $x
  2c
  <script LANGUAGE="JavaScript" SRC="tablesort.js"></script>
  .
  w
  EOF
  done

  public class Bar extends Foo {
    public Bar() {
      System.out.println("Hello, world!");
    }
  }

  import foo.MyConfig; // your config class
  import org.cougaar.profiler.MemoryTracker;

  public class Bar extends Foo {
    public Bar() {
      System.out.println("Hello, world!");
      MY_PROFILER.add(this);
    }
    private static final MemoryTracker MY_PROFILER =
      MemoryTracker.getInstance(
        "Bar", // classname
        8,     // object header + fields size
        MyConfig.getOptions("the_module", "Bar"));
  }

  private void run() {
    // make sure the serialVersionUID field exists, so we don't
    // break serialization
    addSerialVersionUID();

    if (ENABLE_SIZE_AND_CAPACITY) {
      // add "$get_size()" and "$get_capacity()" methods
      defineSize();
      defineCapacity();
    }

    // add static profiler field
    defineProfilerField();

    // init profiler field in class init method
    initProfilerField();

    // override "profile_<super>" method to disable super's profiler
    disableSuperProfiler();

    // add our "profile_<class>" method
    addClassProfiler();

    // update constructors with "profile_<class>" calls
    // (excluding constructors that call "this(..)")
    //
    // note that the default constructor always exists
    callProfilerInConstructors();

    // catch "readObject", which is a hidden constructor.
    //
    // we can ignore "readExternal" since it calls the no-arg
    // constructor.
    callProfilerInReadObject();

    // handle "clone", which is yet another hidden constructor.
    callProfilerInClone();
  }

  class Test {}

 import java.io.*;
 class Test implements Serializable {
    public static void main(String[] args) throws Exception {
      Test t1 = new Test();
      System.out.println("t1: "+t1);
      Test t2 = (Test) testSerial(t1);
      System.out.println("t2: "+t2);
    }
    public Test() {
      System.out.println("constructor");
    }
    private void readObject(ObjectInputStream s) throws Exception {
      System.out.println("readObject");
      s.defaultReadObject();
    }
    private static Object testSerial(Object o) throws Exception {
      ByteArrayOutputStream bos = new ByteArrayOutputStream();
      ObjectOutputStream os = new ObjectOutputStream(bos);
      os.writeObject(o);
      os.flush();
      o = null;
      byte[] b = bos.toByteArray();
      ByteArrayInputStream bis = new ByteArrayInputStream(b);
      ObjectInputStream is = new ObjectInputStream(bis);
      Object newO = is.readObject();
      return newO;
    }
  }

  constructor
  t1: Main@1a16869
  readObject
  t2: Main@19efb05

  import sun.reflect.ReflectionFactory;
    private static final ReflectionFactory reflFactory = ..;
      ..
      Constructor cons = reflFactory.newConstructorForSerialization(cl, cons);
      ..
      return cons.newInstance(..);