Introduction:

This post is based on an interesting article that I came across. I have provided the link to those articles in the reference section.

Also the main inspiration of this article are the performance issues that I am facing daily in my ST applications.

When we talk about JVM which are used for a wide variety of applications from small applets on desktops to web services on large servers. Each JVM will manage its memory using some or the other Garbage Collectors. In the J2SE platform version 1.4.2 there were four garbage collectors but there was no choice given to user to select one of them. In version 5 as well the choice was not given by intelligence was incorporated to select the correct GC based on the class of the machine on which the application is started.
Usually the choice of Garbage Collector (GC) does not matter as applications perform within there limits, but for some applications it does. For example large application that scales well to large number of threads, processors, sockets, and a large amount of memory. As with the past experience usaully smaller application has no problem with GC and works very smoothly even with “serial GC” however for large application this can become a major bottleneck. For a sufficiently large system it becomes well worthwhile to choose the right garbage collector and to tune it if necessary.

This post is based on the JVM present in Oracle E-Business suite R12. We will be talking about garbage collection in R12 and see an interesting tool which can make quick analysis about how GC is happening in our application.

Generational Collections:

An object is considered garbage when it can no longer be reached from any pointer in the running program. The most straightforward garbage collection algorithms simply iterate over every reachable object. Any objects left over are then considered garbage. The time this approach takes is proportional to the number of live objects, which is prohibitive for large applications maintaining lots of live data.
Beginning with the J2SE Platform version 1.2, the virtual machine incorporated a number of different garbage collection algorithms that are combined using generational collection. Lets understand what it is.

Past experience showed that objects are usually allocated for short span of time. The blue area in the diagram below is a typical distribution for the lifetimes of objects. The X axis is object lifetimes measured in bytes allocated. The byte count on the Y axis is the total bytes in objects with the corresponding lifetime. Sharp peak on the left represent that maximum number of live objects can be reclaimed within a short span of time after being allocated.

Some objects do live longer, and so the distribution stretches out to the the right. Some applications have very different looking distributions, but a surprisingly large number possess this general shape. Efficient collection is made possible by focusing on the fact that a majority of objects “die young”.

To optimize this scenario JVM divides the memory into different generations of we can say pools holding objects of different ages. Garbage collection occurs in each generation when the generation fills up. Initially objects are assigned to younger generation (of pool where young objects are placed) and once young generation fills up minor GC (Garbage Collection) will take place which will clean up the dead object (since by the time most of the short leaving objects will be dead). The left over objects which might be still alive are transferred to elder generation (called tenured generation). When tenured generation gets full, “FULL GC” will take place which is quite slow compared to minor GC as all the live objects will be checked.

Below figure shows different pools in memory. “Young Generation” consist of 3 sub generation one EDEN, and two survivor space. Objects are initially allocated in EDEN. One survivor space is empty at any time, and serves as a destination of the next, copying collection of any live objects in EDEN and the other survivor space. Objects are copied between survivor spaces in this way until they are old enough to be tenured, or copied to the tenured generation.

“Tenured Generation” is bigger then Young Generation.

The permanent generation holds data needed by the virtual machine to describe objects that do not have an equivalence at the Java language level. For example objects describing classes and methods are stored in the permanent generation.

JVM in Oracle E-Business Suite R12

Talking about Oracle E-Business Suite R12 we specify the minimum and maximum size of jvm memory to be used for different processes.
Example in CONTEXT_FILE of application we specify JVM for

1. Forms process using – “forms_jvm_start_options” parameter
2. OACore process using – “oacore_jvm_start_options” parameter
3. OAFM process using – “oafm_jvm_start_options” parameter

Lets look at the various properties we specify for these parameter. Example for OACore

<oacore_jvm_start_options oa_var=”s_oacore_jvm_start_options”>-server -verbose:gc -Xmx1024M -Xms256M -XX:MaxPermSize=256M -XX:NewRatio=2  -XX:+PrintGCTimeStamps -XX:+UseTLAB -XX:+UseParallelGC  -XX:ParallelGCThreads=2  -Dcom.sun.management.jmxremote -Djava.security.policy=$ORACLE_HOME/j2ee/oacore/config/java2.policy -Djava.awt.headless=true -Dhttp.webdir.enable=false -Doracle.security.jazn.config=/slot/ems2339/appmgr/inst/apps/pz8st210_rws60056rems/ora/10.1.3/j2ee/oacore/config/jazn.xml</oacore_jvm_start_options>

-verbose:gc : This parameter is used to tell JVM to dump the log messages in oacore log file when ever garbage collection happens. The log file is located at $LOG_HOME/ora/10.1.3/opmn. We will refer/use this log file further down when I will demonstrate GCViewer tool.

-Xmx1024M : This is the maximum size of footprint of JVM

-Xms256M : This is the minimum size of footprint of JVM. So at the start “Young Generation” + “Tenure Generation” = -Xms value

-XX:MaxPermSize : This is the size of “Permanent Generation”

-XX:NewRatio : This is the ratio of “Tenure Generation”/”Young Generation”

-XX:+PrintGCTimeStamps : This parameter is going to print the time stamp when garbage collection is done.

In my case the log file path and location is $LOG_HOME/ora/10.1.3/opmn/default_group~oacore~default_group~1.log (This is the log file for oacore. Similarly there will be log file for forms and oafm in the same location).
The sample content of log file is as given below.

94562.018: [GC 670227K->595360K(892672K), 0.0221060 secs]
94617.600: [GC 672480K->617324K(799104K), 0.0307160 secs]
94648.483: [GC 694444K->623826K(872384K), 0.0405620 secs]
94706.754: [Full GC 756173K->264184K(790720K), 0.8990440 secs]
94718.575: [GC 458782K->424403K(737536K), 0.0471040 secs]
94740.380: [GC 501646K->436633K(793600K), 0.0656750 secs]
94817.197: [GC 512473K->441116K(795136K), 0.0749340 secs]

Here the first column 94562.018, 94617.600 shows the time in seconds when GC happened. Inside the square bracket it indicates whether its a minor GC or FULL GC. That is followed by some number 670227K->595360K. The number on left side of -> indicate original size of live objects before GC and number after -> indicate size of live objects after GC. Number in the bracket (892672K) indicates total size of live objects allocated. Number after comma indicates time it took to complete garbage collection. For example in the first rows it took 0.0221060 secs for completing GC.

Having known this much on information let me introduce you to a tool called GCViewer which is a java based tool and shows the content of this log file in the form of graph giving huge information which will help us tuning our application.

GC Viewer Tool

1) Download and installation :- You can download this tool from this location
While downloading and using in windows you can just download the bin file (no need to downlaod source file) – gcviewer-1.29-bin.zip

unzip the file and you will get a folder consisting of a jar file. Double click on the jar file and an application will open as shown below.

2) Uploading the log file :- You can either ftp the oacore log file from $LOG_HOME/ora/10.1.3/opmn or you can give the URL for log file. For giving URL copy the log file to OA_HTML location as shown below.

-bash-3.00$ cp default_group~oacore~default_group~1.log $OA_HTML

In this case URL becomes – http://(hostname):(port)/OA_HTML/default_group~oacore~default_group~1.log
In my case it is

http://rws60056rems.us.oracle.com:8039/OA_HTML/default_group~oacore~default_group~1.log

You can load this log file by giving URL to the tool as shown below and click on OK.

After loading the file the graph is shown below.

This is really not a good sign. In my case the FULL GC was happening at every second and thats why I have to go deep inside and think about tuning JVMs. The black portion that you see in the above fig are the FULL GC. You can see various matrix values and hide other matrix values using View button in the top menu. Black lines are most important for me as I want to avoid frequent FULL GC. Below fig shows continuous black lines every second indicating that FULL GC is happening.

View for FULL GC

Also another important things to look for are read and blue lines. The red line indicates the total heap size, the blue line shows how much of the heap is actually used.

If you observe carefully the blue line follows a saw-tooth pattern. This is because when new live objects are loaded the size of JVM increase steadily as shown by inclined lines and when minor collection happens the size reduces suddenly.

The green line shows time required for garbage collections (Shown below). Usually minor GC take less time and FULL GC takes more time.

Tuning Application

Finally after doing all this exercise we need to use this information for tuning our application. Based on the above observations we can make certain rules for tuning.

When ever a full GC happens the memory consumption (blue line) is reduced to more or less the same value as after the last full collection. This means that even though some objects were promoted to the older generation, most of them didn’t become very old either. Which means, that maybe they should not have been promoted to the older generation in the first place.

In that case it is beneficial to increase the size of “Younger Generation” to prevent the early promotion of medium-lived objects. The parameter -XX:NewRatio=<value> defines the ratio of “Tenure Generation”/”Young Generation”. So if we reduce this ration (lets say to 1) then in that case “Younger Generation” size will get increased and most of the live objects will stay and die in “Younger Generation” rather then shifting to Tenure Generation and dying. This will cause Tenure generation to get full after longer period and that will reduce FULL GC. So in case if there are huge number of FULL GC and heap size is getting reduced to more or less same level after FULL GC then you can consider reducing the value of -XX:NewRatio=<value> parameter in CONTEXT_FILE for oacore (we are concentrating more in oacore here). Disadvantage of this is that overall size of footprint will increase as Younger Generation size increased.

So initially it will start with 256M (as in my case) and then as the memory consumption increases it will gradually increase the size of JVM to accommodate more objects and it will increase the size until max upto -Xmx parameter value.

Usually it is recommended that we should allocate as much as memory as possible in the initial stage instead of waiting for JVM to increase it automatically. This will prevent application from suffering due to performance in the initial period of time.

Hope this helps !!!

References:

Metalink Note ID : 342799.1
Tuning Garbage Collection with the 5.0 Java[tm] Virtual Machine
Java Performance Tuning using GC Viewer