Memory Analysis

• 1: Memory Heap Analysis
• 2: Capturing Heap Dumps
• 3: JOverflow
• 4: Eclipse MAT
• 5: Visual VM
• 6: Memory Challenge
• 7: Garbage Collections

1 - Memory Heap Analysis

In the following sections, we are going to do some analysis of the JVM’s heap dump.

First, we’ll need to capture a heap dump:

• Capturing a Heap Dump

We will then go through three common tools in which we can do some analysis of a heap dump. All of which are free. 😃

• JOverflow Analysis
• Eclipse MAT
• VisualVM

We will then tie all our knowledge together and attempt to solve a quick challenge:

• Memory Challenge

2 - Capturing Heap Dumps

You may be aware by now, there are many different ways of getting data from the JVM. Here are just a few ways to get heap dump of the JVM.

jcmd

With jcmd, you have the ability to invoke the GC.heap_dump command. This requires that you are running as the same OS user as the target JVM process.

jcmd <PID> GC.heap_dump my_little_heap_dump.hprof

Note: If a full path is not specified, the heap_dump will be created relative to the location from where the process was started (when generated with jcmd)

jmap

A more traditional approach is using jmap and invoking the command on the target process.

jmap -dump:format=b,file=my_little_heap_dump.hprof <PID>

Core Dump

You can also use jmap to extract a heap dump from a core dump on the process:

sudo gdb --pid=<PID>
gcore /tmp/jvm.core
detach
quit
jmap -dump:format=b,file=my_little_heap_dump.hprof /usr/bin/java /tmp/jvm.core

💡 Capturing a heap dump from a core dump on Java 8, you may run into this issue: JDK-8073606.

HotSpot Diagnostic MBean

You can capture a heap dump by invoking a diagnostic MBean which is included in the Oracle JDK. You can do so by opening your favorite MBean browser (ex. jconsole, jmc) and invoke the com.sun.management.HotSpotDiagnostic. The arguments are:

• Filename of the heap dump that will be created. 💡 Note, it will be created with file ownership of the hosting JVM process.
• Indicator to dump all live object (true will dump only live objects)

3 - JOverflow

Included in JDK Mission Control is a plugin that used to be a separate instance, the JOverflow Heap Analyzer. This plugin now adds a context menu selection to Dump Heap of JVMs from the JVM Browser.

JOverflow is a great tool to start our analysis with since it is tailored to identifying common anti-patterns present in most heap dumps. This should give us an idea of the kinds of problems we can see in our JVMs.

Anti-Patterns

Here is a listing of some the patterns that JOverflow identifies:

• Empty Unused Collections: Empty collection, where modification count == 0.
• Empty Used Collections: Empty collection, where modification count != 0.
• Small Sparse: Only for array-based, where less than half the slots are occupied. Small is considered: size <= default (ex. 16 for HashMap).
• Large Sparse: Only for array-based, where less than half the slots are occupied. Large is considered: Size > default.
• Boxed: Contains boxed Numbers (ex. java.lang.Integer). Each of these boxed number has overhead as compared to their primitive counterpart due to object references.
• Small Collections: Collections with 1 to 4 elements. There are fixed costs of collections, which may lend this set of data better hosted in an array vs. a full Java collection type.
• Vertical Bar Collections: Collection which is a list of lists, where the outer collection is large, and it’s elements are all small collections (ex. List(1000) of List(100))
• Zero Size Arrays: Array where length == 0 (still consumers 12 - 16 bytes).
• Vertical Bar Arrays: Similar to Vertical Bar Collections, but for arrays.
• Sparse Arrays: Less than half of the elements are not null.
• Long Zero Tail Arrays: Ends with a consecutive series of zeros, where the tail length is >= size / 2.
• Empty Arrays: Only null elements.
• Duplicate Arrays: Where an array contents are the same in another instance, but they are separate array instances.
• Duplicate Strings: Same as Duplicate Array, where string1.equals(string2) and string1 != string2.

Reference: JOverflow: Advanced Heap Analysis in Java Mission Control

Filtering

As you play with JOverflow, once you click on something, it will begin filtering down your content. If you wish to reduce down to code that you may own, you can start doing a package filter on the ancestor section.

In this example, I want to see duplicate strings for code under cchesser. In this case, I can see that our workshop service has several duplicate strings (as this content is replicated on each object):

• Regular Session
• 4-Hour Workshop
• 8-Hour Workshop

However, the number of instances / overhead is extremely low (since this is a small service), it gives you visibility of areas that you could optimize.

Navigating

Since JOverflow’s mechanism of drilling down is by applying filters, it doesn’t have an easy way to undo most operations, and instead relies on resetting the state to the unfiltered state. You can undo all operations by using the backwards arrow button:

Instances

We can also use the plugin to drill down a bit into particular instances.

We can enable the instances view by navigating to:

1. Window > Show View > Other
2. Selecting JOverflow Instances

Example - Arrays Size 1

In the following example, we’re going to find:

1. Arrays with One Element
2. Coming from our WorkshopConfiguration

This should filter the Instances view down to that single object.

Example - Conference Session Details

We can use this same mechanism to also explore values of some of the classes we own, in the next example we’re going to:

1. Use All Objects of type Conference Session
2. Drill down into a couple of the instances

4 - Eclipse MAT

Eclipse Memory Analyzer is a fairly mature tool on analyzing heap dumps. It is a rich tool that includes the abilities to do OQL queries on the heap, general reporting on anti-patterns, and helpful common views (like the dominator tree). Eclipse Memory Analyzer tool is a separate install which can be a standalone install, or it can run as a plugin within Eclipse.

Opening Heap Dumps

After you have it installed, go to File and then Open Heap Dump… and specify the hprof file that you wish to analyze.

Index Files

💡 When Eclipse Memory Analyzer loads your hprof file, it will create many other index files to assist in optimally analyzing and navigating through your heap dump. It may make it easier to isolate your prof file in its own directory prior to opening it, based on the secondary files which are created. You can always just delete these files within Eclipse Memory Analyzer by opening the Heap Dump History window, right-clicking the hprof which was previously loaded, and selecting Delete Index Files. Example listing of index files which get generated by suffix:

• .domIn.index
• .domOut.index
• .index
• .o2ret.index
• .a2s.index
• .idx.index
• .inbound.index
• .o2c.index
• .o2hprof.index
• .outbound.index
• .threads

Analyzing the Heap Dump

In the following section, we’ll go through a couple of the views and what sort of data we can gather from them.

Dominator Tree

A common first area to look at your heap within Eclipse Memory Analyzer is the dominator tree. From the dominator tree, you can organize by the retained heap size, and then begin drilling down the tree to see the contributors to the largest GC roots.

Histogram

The histogram gives you a quick listing of all the top consumers by type. Typically this is going to provide context of the large consumers based on their “lower-level” types. For example, char[] is a common large contributor, which then will be followed by String which is a type that is predominately weighted by the size of the char[].

From the histogram, we can drill down into particular instances of an object and see what’s referencing them by right clicking on a row and selecting List Objects > with Incoming References

This should let us drill down into an instance and find what exactly is holding on to that specific value:

Since this view shows references by incoming link, we would read the results as:

“angularjs” is pointed to by the [0] index of the tags of a specific ConferenceSession instance, which is pointed to by LocalCache. Notice that this specific example is the inverse of what we found with the dominator tree, if we explored this table enough we would end up at a ConferenceSessionLoader reference.

Thread Overview

The thread overview is a helpful view when you are looking at contributors based on the execution of code. For example, if you have a JVM which has thrown an OutOfMemoryError, you can tell if some type of request caused a massive spike which caused the exhaustion of memory, or if the requests may have not been abnormal, there just wasn’t sufficient space to support the request.

OQL

Another strong feature of Eclipse Memory Analyzer is the OQL studio to execute queries to do lookup on objects in your heap.

Lookup our ConferenceSession class type:

SELECT *
FROM INSTANCEOF cchesser.javaperf.workshop.data.ConferenceSession

💡 To execute the query, you click on the red exclamation mark (❗). Alternatively, you can press CTRL+Enter on Windows or Command+Enter on macOS.

By returning the raw type back, you can expand each one to further look at the contents of the object. If you wanted to just report the object with its title attribute and the object’s retained sized, you could do this:

SELECT c.title.toString(), c.@retainedHeapSize 
FROM INSTANCEOF cchesser.javaperf.workshop.data.ConferenceSession c 

Now, you could then filter this by including a WHERE clause, where you can filter it by the title or the abstract:

SELECT c.title.toString(), c.@retainedHeapSize FROM INSTANCEOF cchesser.javaperf.workshop.data.ConferenceSession c 
WHERE c.title.toString() LIKE ".*(J|j)ava.*" OR c.abstract.toString() LIKE ".*(J|j)ava.*"

Reference: Eclipse Memory Analyzer OQL Syntax

The auto-completion will also let you invoke fields and method’s from Eclipse Mat’s own internal model for the heap dump. You can view other methods available by exploring the API Reference

Useful Plugins

Calcite MAT

The Calcite MAT Plugin adds sort, group by and join behavior (among other things) and an additional SQL query engine.

We can use this plugin to do some more advanced analysis, for example:

• Getting a distribution of the number of tags in our ConferenceSessions

select getSize(c.tags) tag_cnt, count(getSize(c.tags)) 
from "cchesser.javaperf.workshop.data.ConferenceSession" c 
group by tag_cnt 
order by tag_cnt desc

5 - Visual VM

VisualVM is a tool which used to be part of Oracle’s JDK and is now a standalone tool. This tool was spawned from the Netbeans Profiler, and it has some helpful tools to inspect a heap dump.

Opening Dumps

To load the heap dump in VisualVM, you will just go to File -> Load… and specify the File Format to be Heap Dumps….

Analyzing the Heap Dump

VisualVM offers the following sections:

• Summary
• Objects
• Threads
• OQL Console
• R Console

For the purpose of this section we are only going to utilize the OQL Console to construct queries on the heap. There are other options in VisualVM (briefly discussed here), but we feel that the other tools presented before this offer much nicer views/data.

Summary

The Summary view gives you a quick overview of the state of the heap:

This view also lets you quickly gather the dominators for the heap, similar to the Dominator Tree in Eclipse MAT.

Objects

The Objects view groups instances by class.

Within this view, you can inspect individual instances of an object and see both the fields and the incoming references to that instance:

Threads

The Threads view visualizes the state of threads.

Within this view, you can drill down into certain threads and view what was specifically referenced in a stack frame:

OQL Console

One of the attractive features for VisualVM is that its OQL Console allows you to write Javascript code to query objects, which you can then do other functions on that data.

From the OQL Console, we will issue queries and then allow you to further play around with the language.

OQL Queries

Reference: VisualVM OQL Help

Deamon Threads

Query for Thread objects which are daemons (you can get context of Threads, since they are objects in your heap too):

select t from java.lang.Thread t where t.daemon == true

Previous versions of VisualVM used to return the results as hyperlinks, which you could then click and begin diving into the instance state:

The newer versions of VisualVM will populate the results in a view similar to the Objects view:

Mapping to JSON

Query for Thread objects (similar to last query), but return multiple attributes as JSON:

select {name: t.name.toString(), thread_id: t.tid }
from java.lang.Thread t
where t.daemon == true

Applying Javascript

VisualVM offers a helper object that represents the heap, the heap object, which offers a few useful functions.

During our OQL searching, we’ll be using heap.objects to gather the set of objects we want.

We’ll start by limiting our objects to instances of cchesser.javaperf.workshop.data.ConferenceSession and assign it to a variable called sessions (which we’ll reference later).

var sessions = heap.objects('cchesser.javaperf.workshop.data.ConferenceSession');

We’re going to find ConferenceSessions that which have tags, we’ll do that by writing a Javascript function to filter results which have tags. We’ll apply this filter to our sessions.

var sessions = heap.objects('cchesser.javaperf.workshop.data.ConferenceSession');

function hasTags(conf) {
  return conf.tags.size > 0
}

filter(sessions, hasTags);

Take that previous query and further expand it to list it in JSON with the number of tags. It is often times convenient to have a reference to the object we’re interacting with, to more easily see the available fields.

var sessions = heap.objects('cchesser.javaperf.workshop.data.ConferenceSession');

function hasTags(conf) {
  return conf.tags.size > 0
}

var withTags = filter(sessions, hasTags);

function toJSON(conf) {
return { conference: conf , tagCount : conf.tags.size };
}

map(withTags, toJSON);

We can further expand this to sort the results, descending by number of tags, and list the tags in the results:

var sessions = heap.objects('cchesser.javaperf.workshop.data.ConferenceSession');

function hasTags(conf) {
  return conf.tags.size > 0
}

var withTags = filter(sessions, hasTags);

function toJSON(conf) {
  return { conference: conf , tagCount : conf.tags.size };
}

var confs = map(withTags, toJSON);

function tagSorter(lhs, rhs) {
  return rhs.tagCount - lhs.tagCount;
}

sort(confs, tagSorter);

We could also inline most of this using the inline syntax:

function hasTags(conf) {
  return conf.tags.size > 0
}

sort(map(filter(heap.objects('cchesser.javaperf.workshop.data.ConferenceSession'), hasTags), 
 '{ conference: it, tag_count: it.tags.size, tags: toArray(it.tags.elementData) }'), 'rhs.tag_count - lhs.tag_count')

Useful Plugins

OQL Syntax Support

This plugin adds some auto complete and syntax highlighting to the OQL Console

Challenge

Apply what you’ve learned about OQL in this section and write some javascript that will show the distribution of tag counts in our conference sessions (similar to what we did with calcite mat.)

Sample Solutions

JSON Output

This solution will return the result as a JSON object.

var sessions = heap.objects('cchesser.javaperf.workshop.data.ConferenceSession');

function toJSON(conf) {
  return { conference: conf , tagCount : conf.tags ? conf.tags.size : 0, title: conf.title };
}

var confs = map(sessions, toJSON);

var results = {}
var arr = toArray(confs)
arr.length;

for(var i = 0; i < arr.length; i++) {
  var conf = arr[i];
  if(!results[conf.tagCount]) { 
    results[conf.tagCount] = 0;
  }
  results[conf.tagCount] = results[conf.tagCount] + 1;
}
results

HTML Output

This solution will return the result as an HTML <ul>.

var sessions = heap.objects('cchesser.javaperf.workshop.data.ConferenceSession');

function toJSON(conf) {
  return { conference: conf , tagCount : conf.tags ? conf.tags.size : 0, title: conf.title };
}

var confs = map(sessions, toJSON);
var arr = toArray(confs)

var maxSize = max(map(arr, 'it.tagCount'))
var results = []
for(var i = 0; i < maxSize+1; i++ ) {
  results[i] = 0;
}

for(var i = 0; i < arr.length; i++) {
  var conf = arr[i];
  results[conf.tagCount]++
}

var report = "<html><ul>";

for(var i = 0; i < maxSize+1; i++) {
  var count = results[i];
  report += "<li><b>Size(" +i+")</b>="+count+"</li>" 
}
report+="</ul></html>"
toHtml(report)

6 - Memory Challenge

The provided WorkshopService has an intentional memory problem, use the previous sections as reference to try to pin point it.

Tips

• With the Dominator Tree (Eclipse MAT) determine what object would free up the most memory (if we could get rid of it)
• With the Histogram (Eclipse MAT) determine what type of object has the most instances
  • Using the Incoming Objects view, find out what’s pointing to them.

Once you’ve found the large object, look through it’s properties and determine why this object holds on to so many other objects.

select * from cchesser.javaperf.workshop.cache.CleverCache

SELECT c.cacheLimit AS "max entries", c.innerCache.size AS entries FROM cchesser.javaperf.workshop.cache.CleverCache c 

select c.cacheLimit as "max entries", getSize(c.innerCache) as "entries" 
from cchesser.javaperf.workshop.cache.CleverCache c

var caches = heap.objects("cchesser.javaperf.workshop.cache.CleverCache")

function report(cache) {
  return { maxEntries: cache.cacheLimit, entries: cache.innerCache.size }
}
 
map(caches, report)

@GET
@Path("/search")
@Produces(MediaType.APPLICATION_JSON)
@Timed
public Searcher.SearchResult searchConference(@QueryParam("q") String term, @QueryParam("c") String context) {
    return fetchResults(term, context);
}

private Searcher.SearchResult fetchResults(String term, String context) {
  
  if (context != null && !context.isEmpty()) {
      if (resultsByContext.exists(context)) {
          return resultsByContext.fetch(context);
      }
  }

// does not exist in cache, compute and store
  
  SearchResult results = searcher.search(term);
  resultsByContext.store(results.getResultsContext(), results);
  return results;
}

 /**
  * Stores the given key value pair in the cache
  *
  * @param key   the unique identifier associated with the given value
  * @param value the value mapped to the given key
  */
  public void store(K key, V value) {
    if (isFull()) {
        K keyToRemove = getLFUKey();
        CleverCache<K, V>.CacheEntry<V> removedEntry = innerCache.remove(keyToRemove);
    }

    CacheEntry<V> newEntry = new CacheEntry<V>();
    newEntry.data = value;
    newEntry.frequency = 0;

    innerCache.put(key, newEntry);
  }
  // other methods
  private boolean isFull() {
    return innerCache.size() == cacheLimit;
}

7 - Garbage Collections

A key piece to understanding what is happening in terms of GC cycles within your service, is enabling GC logs. In this section, we are going to do some analysis on the JVM in regards to it’s garbage collection (GC) cycles.

GC JVM Options

Here is a set of JVM options you can enable on your service and how to interpret those logs.

• -XX:+PrintGCDetails: Includes more details within your GC log
• -XX:+PrintGCDateStamps: Have a readable date/time string to correlate events in your log. Without this option, your GC log will have elapsed time since the JVM was started. This format (which is reported) in seconds (with millisecond precision), is not easy for someone to quickly correlate when this event was logged (as you have to infer the time based on when the JVM was started).
• -Xloggc: Specifies the log file for the garbage collection logs (otherwise will go to stdout). 💡 Note: -verbose:gc is NOT necessary when you set Xloggc (it is implied).
• -XX:+UseGCLogFileRotation: Support rotating your GC log file (you don’t want to let this get too big).
• -XX:GCLogFileSize: Size of the file for rotation (ex. 10M).
• -XX:NumberOfGCLogFiles: Number of GC log files to maintain (ex. 3). 💡 Note: if you are monitoring your log file with another solution (like splunk or logstash), you typically don’t need to be keeping an inventory of rolled files around, unless you are concerned about log forwarding failing and want to ensure a given amount is still capable of being captured from a host.

GC Log formats

With different garbage collectors in the JVM, you will get slightly different GC log formats.

Parallel GC

2015-09-30T10:57:20.215+0600: 0.847: [GC (Allocation Failure) [PSYoungGen: 65536K->10748K(76288K)] 65536K->12607K(251392K), 0.0118637 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
2015-09-30T10:57:20.556+0600: 1.188: [GC (Metadata GC Threshold) [PSYoungGen: 44312K->10748K(141824K)] 46171K->12786K(316928K), 0.0077755 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
2015-09-30T10:57:20.564+0600: 1.196: [Full GC (Metadata GC Threshold) [PSYoungGen: 10748K->0K(141824K)] [ParOldGen: 2038K->10444K(116736K)] 12786K->10444K(258560K), [Metaspace: 20976K->20976K(1067008K)], 0.0286381 secs] [Times: user=0.14 sys=0.01, real=0.03 secs]

Concurrent Mark Sweep

2015-09-30T11:11:35.994+0600: 0.838: [GC (Allocation Failure) 0.838: [ParNew: 69952K->8703K(78656K), 0.0128204 secs] 69952K->12781K(253440K), 0.0128848 secs] [Times: user=0.04 sys=0.01, real=0.01 secs]
2015-09-30T11:11:38.009+0600: 2.853: [GC (CMS Initial Mark) [1 CMS-initial-mark: 4077K(174784K)] 67493K(253440K), 0.0088311 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
2015-09-30T11:11:38.018+0600: 2.862: [CMS-concurrent-mark-start]
2015-09-30T11:11:38.018+0600: 2.862: [CMS-concurrent-mark: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2015-09-30T11:11:38.018+0600: 2.862: [CMS-concurrent-preclean-start]
2015-09-30T11:11:38.019+0600: 2.863: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2015-09-30T11:11:38.019+0600: 2.863: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2015-09-30T11:11:43.074+0600: 7.918: [CMS-concurrent-abortable-preclean: 1.233/5.055 secs] [Times: user=1.23 sys=0.01, real=5.06 secs]
2015-09-30T11:11:43.074+0600: 7.918: [GC (CMS Final Remark) [YG occupancy: 63415 K (78656 K)]7.918: [Rescan (parallel) , 0.0052614 secs]7.924: [weak refs processing, 0.0000337 secs]7.924: [class unloading, 0.0029068 secs]7.927: [scrub symbol table, 0.0025781 secs]7.929: [scrub string table, 0.0002699 secs][1 CMS-remark: 4077K(174784K)] 67493K(253440K), 0.0117740 secs] [Times: user=0.04 sys=0.01, real=0.01 secs]
2015-09-30T11:11:43.086+0600: 7.930: [CMS-concurrent-sweep-start]
2015-09-30T11:11:43.086+0600: 7.930: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2015-09-30T11:11:43.087+0600: 7.930: [CMS-concurrent-reset-start]
2015-09-30T11:11:43.110+0600: 7.954: [CMS-concurrent-reset: 0.023/0.023 secs] [Times: user=0.01 sys=0.01, real=0.03 secs]

G1

015-09-30T11:13:03.870+0600: 0.395: [GC pause (G1 Evacuation Pause) (young), 0.0052206 secs]
   [Parallel Time: 1.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 395.4, Avg: 395.5, Max: 395.8, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 1.1, Diff: 1.1, Sum: 2.0]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 0.5]
      [Object Copy (ms): Min: 0.7, Avg: 1.4, Max: 1.6, Diff: 0.9, Sum: 11.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1.5, Avg: 1.8, Max: 1.8, Diff: 0.3, Sum: 14.2]
      [GC Worker End (ms): Min: 397.3, Avg: 397.3, Max: 397.3, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.1 ms]
   [Clear CT: 0.1 ms]
   [Other: 3.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 24.0M(24.0M)->0.0B(39.0M) Survivors: 0.0B->3072.0K Heap: 24.0M(256.0M)->5754.5K(256.0M)]
 [Times: user=0.02 sys=0.01, real=0.00 secs]
2015-09-30T11:13:04.343+0600: 0.868: [GC pause (G1 Evacuation Pause) (young), 0.0082908 secs]
   [Parallel Time: 5.1 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 868.3, Avg: 868.4, Max: 868.8, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 1.7, Diff: 1.7, Sum: 2.7]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
         [Processed Buffers: Min: 0, Avg: 0.4, Max: 1, Diff: 1, Sum: 3]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 1.4, Diff: 1.4, Sum: 3.5]
      [Object Copy (ms): Min: 3.2, Avg: 4.0, Max: 4.6, Diff: 1.4, Sum: 32.1]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 4.6, Avg: 4.9, Max: 5.0, Diff: 0.5, Sum: 39.5]
      [GC Worker End (ms): Min: 873.3, Avg: 873.3, Max: 873.4, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.1 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 39.0M(39.0M)->0.0B(147.0M) Survivors: 3072.0K->6144.0K Heap: 44.6M(256.0M)->13.9M(256.0M)]
 [Times: user=0.04 sys=0.00, real=0.01 secs]
2015-09-30T11:13:04.650+0600: 1.176: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0090083 secs]
   [Parallel Time: 5.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1175.9, Avg: 1176.0, Max: 1176.0, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 1.1, Avg: 1.2, Max: 1.4, Diff: 0.3, Sum: 9.4]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.2]
         [Processed Buffers: Min: 0, Avg: 1.1, Max: 2, Diff: 2, Sum: 9]
      [Scan RS (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 1.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 2.0]
      [Object Copy (ms): Min: 3.4, Avg: 3.7, Max: 3.8, Diff: 0.4, Sum: 29.3]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 5.4, Avg: 5.4, Max: 5.5, Diff: 0.1, Sum: 43.3]
      [GC Worker End (ms): Min: 1181.4, Avg: 1181.4, Max: 1181.4, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 3.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 33.0M(147.0M)->0.0B(140.0M) Survivors: 6144.0K->13.0M Heap: 46.9M(256.0M)->20.9M(256.0M)]
 [Times: user=0.04 sys=0.00, real=0.01 secs]
2015-09-30T11:13:04.660+0600: 1.185: [GC concurrent-root-region-scan-start]
2015-09-30T11:13:04.664+0600: 1.190: [GC concurrent-root-region-scan-end, 0.0046509 secs]
2015-09-30T11:13:04.664+0600: 1.190: [GC concurrent-mark-start]
2015-09-30T11:13:04.665+0600: 1.190: [GC concurrent-mark-end, 0.0007287 secs]
2015-09-30T11:13:04.665+0600: 1.190: [GC remark 1.190: [Finalize Marking, 0.0001736 secs] 1.191: [GC ref-proc, 0.0000411 secs] 1.191: [Unloading, 0.0016740 secs], 0.0020377 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs]
2015-09-30T11:13:04.667+0600: 1.193: [GC cleanup 21M->14M(256M), 0.0004254 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs]

Type of Collections

A simple rule to watch for on your logs is the prefix of either:

[GC ...      <- Minor GC cycle (young gen)
[Full GC ... <- Full GC cycle

(❗) Explicit GCs can also be identified, which is when something is invoking the System.gc() API. Note, this is not good thing, as something is forcing a GC cycle to occur, rather than letting the JVM trigger this on its own (what should naturally occur).

2015-09-30T12:23:44.425+0600: 195.699: [GC (System.gc()) [PSYoungGen: 39223K->3562K(76288K)] 49685K->14032K(190464K), 0.0047880 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2015-09-30T12:23:44.430+0600: 195.704: [Full GC (System.gc()) [PSYoungGen: 3562K->0K(76288K)] [ParOldGen: 10469K->9174K(114176K)] 14032K->9174K(190464K), [Metaspace: 25137K->25137K(1071104K)], 0.0724521 secs] [Times: user=0.38 sys=0.01, real=0.07 secs]

It is generally recommended to use the -XX:+DisableExplicitGC JVM option to disable forceful GC events. This will allow the JVM to still have garbage collections, but it disables them from being triggered explicitly. The description of this option:

By default calls to System.gc() are enabled (-XX:-DisableExplicitGC). Use -XX:+DisableExplicitGC to disable calls to System.gc(). Note that the JVM still performs garbage collection when necessary.

Gathering GC Logs

Enabling logs

With our service, let’s go ahead and start it up with GC logging enabled:

# Navigate to the root directory of this project
java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.log -XX:GCLogFileSize=5M -XX:NumberOfGCLogFiles=2 \
 -jar java-perf-workshop-server/target/java-perf-workshop-server-1.1.0-SNAPSHOT.jar server server.yml 

Enabling while JVM is running

In higher versions of the JDK (9+), you can enable GC logging without having to restart the JVM (reference: Thomas Darimont):

Parsing the log

For parsing the logs, we are just going to show a simple approach using R to parse the gc.log that we created. To do this, we will use the stringr package.

# Including stringr package for regex
library(stringr)

# Navigating to where the project is at on my filesystem
setwd("~/java-perf-workshop")

# Read the GC log file in
gc <- readLines("gc.log")

# Regex the matches
matches <- str_match(gc, "(\\d+)K->(\\d+)K\\((\\d+)K\\),\\s(\\d+.\\d+)\\ssecs.*\\[Times\\: user=(\\d+.\\d+) sys=(\\d+.\\d+), real=(\\d+.\\d+) secs")

# Look at what matches, now we want to filter out the NA
matches

# Filter content out and convert to a data frame
gc.df <- data.frame(na.omit(matches[,-1]), stringsAsFactors=FALSE)

# Add a column header to describe fields
colnames(gc.df) <- c("HeapUsedBeforeGC_KB","HeapUsedAfterGC_KB", "HeapCapacity_KB", "GCPauseTime_Sec", "GCUserTime_Sec", "GCSysTime_Sec", "GCRealTime_Sec")

# List out the contents of the data frame
gc.df

Example output:

  HeapUsedBeforeGC_KB HeapUsedAfterGC_KB HeapCapacity_KB GCPauseTime_Sec GCUserTime_Sec GCSysTime_Sec GCRealTime_Sec
1               65536              12554          251392       0.0091645           0.03          0.01           0.01
2               45883              12707          316928       0.0092271           0.03          0.01           0.01

Reminder on the types of time being collected:

• GCUserTime_Sec: User space time
• GCSysTime_Sec: Kernel space time (operating system)
• GCRealTime_Sec: Complete time taken

Notice that the GCRealTime_Sec should closely align with the GCPauseTime_Sec value (just rounded up). If you notice that the GCUserTime_Sec is much larger than the GCRealTime_Sec, you can conclude that multiple threads are executing garbage collection, as GCUserTime_Sec is just the sum time of all the threads.

External Tools

GC Easy

There’s an existing tool GC Easy which will do GC log parsing and analysis as well.