Analyzing memory problems with verbose GC

This article is for WebSphere Portal version 6.0 or later (and 5.1 or later), running Java™software Development Kit (SDK) 1.4.2. For best tuning, it is recommended that you use the latest service release of the SDK to use at least one new SR13 Service release for the tuning discussed here.

Garbage collection can be simply defined as JAVATM Virtual Machine (JVM) frees the heap behavior of objects that are no longer referenced or used by the process, heap refers to a predefined part of memory that can be used to manage resources within a Java application.

The process has three main stages: Mark, sweep and compact: At Mark Stage, all objects within the heap are labeled with a bit. The objects are then checked to see if they are still referenced, and if so, the bit is deleted. In the sweep phase, the JVM traverses the entire heap and deletes all objects that still have the tag bit, and those objects are no longer referenced or used. The compact phase runs only in a full GC, at which point the GC attempts to reassign all objects within the heap to a more compact, contiguous, smaller space within the heap.

The best way to monitor heap usage is to analyze the output of this verbose GC.

First, make sure that the verbose GC is enabled on the server: from the IBM WebSphere Application Server Management console, navigate to Application Servers-websphere_portal-java an D Process management-process Definition-java Virtual Machine. Make sure the check box next to the Verbose garbage collection is selected, and then restart the server. You should now see entries similar to the following being written to the Native_stderr.log file:
<AF[177]: allocation failure. Need 528 bytes, 3602594 ms since last af>
<AF[177]: Managing allocation failure, Action=1 (0/585421800) (29966688/30811672) >
<GC (177): GC cycle started Fri Sep 21 23:48:29 2007
<GC (177): Freed 218620376 bytes, 40% free (248587064/616233472), in 459 ms>
<GC (177): mark:422 MS, sweep:37 MS, compact:0 ms>
<GC (177): Refs:soft 0 (age >=), weak, final 7424, Phantom 0>
<AF[177]: Completed in 460 ms>

Now let's break down the previous log entries into several sections and analyze them separately.

The first is:

<AF[177]: allocation failure. Need 528 bytes, 3602594 ms since last af>

With this entry, we can know that there is an allocation failure, and allocation failure occurs when there is not enough contiguous space within the heap to allocate to the object. Objects are the most common verbose GC outputs. In this case, it is a small object of 528 bytes.

As you can see from this line, it has been over a period of time since we last ran a GC loop, 3602594 Ms.

Next, we'll look at the last line:

<AF[177]: Completed in 460 ms>

This trip tells us the amount of time spent on the GC. Using this number, we will be able to get our most recent rate in GC and find out what percentage of the time we spend on GC and part-time work, such as:

460/3602594 =. 000127% of the time is spent in GC

Within a healthy server, the time spent in GC should be less than 13%, ideally around 7-10%.

Back to the second line:

<AF[177]: Managing allocation failure, Action=1 (0/585421800) (29966688/30811672) >

The first thing to notice is "action=". For an allocation failure, there are seven different actions that can occur: Action=0 says pinnedfreelist has been exhausted. Action=1 represents a preemptive garbage collection cycle. The action=2 represents a complete allocation failure. Action=3 said there had been a heap expansion. Action=4 indicates that all known soft references have been cleared. Action=5 said the temporary heap was temporarily stolen. Action=6 indicates that the free space is very low.

The order of these actions represents the severity level; Most seriously, the server is completely out of memory (action=6).

In this case, we are using action=1. Within such GC, only the mark and sweep stages of GC are run.

The trip also includes:

(0/585421800) (29966688/30811672)

This row is specific to AIX®JVM. As you can see, there are two basic numbers here, and if the two add up, it means the size of the heap to be expanded. One of the smaller ones is automatically used for allocation of large objects.

Note: large objects refer to objects larger than the K.

All other objects are placed in other parts of the heap. If a large object is partially full and another large object requests allocation, the object is placed on another major part of the heap. This object can be a useful tuning parameter in other multi-platform JVMs, called-xloratio.

The next line is:

<GC (177): GC cycle started Fri Sep 21 23:48:29 2007

This row reported when the GC cycle began and which loop we were in, that is, GC (177). This is the 177th GC that has been running since the JVM was started.

Next line:

<GC (177): Freed 218620376 bytes, 40% free (248587064/616233472), in 459 ms>

Indicates how many bytes were freed during this GC cycle, and in this case the JVM was able to release 218620376 bytes.

Also, we can see that this heap now has 40% free, that is, 248,587,064 bytes in this heap total 616,233,472 bytes are idle:

(248587064/616233472)

Finally, the completion of this GC loop took 459 Ms.

This line is very useful because it tells us how much of this heap is idle, and that some objects are being cleaned and not taking up the heap.

The next line is:

<GC (177): mark:422 MS, sweep:37 MS, compact:0 ms>

This line is useful for the GC configuration tuning that we wait to make the GC run faster (see-xgcpolicy:optavgpause), but now we just need to know:

This line shows how long each loop runs. Mark Stage 422 Ms,sweep phase 0 Ms Ms,compact stage.

Also, through the following two points, we can know that this is not a complete gc:compact phase of the completion of the spent 0 Ms. Action=1 indicates that this is a preemptive GC before the full GC runs.

The last line to study is:

<GC (177): Refs:soft 0 (age >=), weak, final 7424, Phantom 0>

We must first understand that the GC not only manages objects, but also maintains a separate reference object to the actual object. These references are related to one of the four queries that were created, and this dependency cannot be changed at a later time. These four queries are marked in the mark phase in the following order: Soft Weak Final Phantom

Soft and weak references can be purged when the reference ceases to exist. If a finalizer (Final query) is associated with a soft or weak reference, the weak is deleted on the next GC pass that is run only if the soft or finalizer reference is deleted.

The above mentioned are some of the primary lines that can be seen in the default GC policy on the Java SDK 1.4.2. With these basics, let's explore how the JVM works.

The beginning of the JVM is typically an optional command-line argument used to start the process. These parameters are native JVM parameters added to the WebSphere Application Server management Console.

The following is a basic command that will be executed at the beginning of the Java process:

JAVA–XMX1024M–XMS256M–XVERBOSEGC Programtorun

The command line arguments

–xmx1024m–xms256m–xverbosegc

Indicates that the following events occur at startup: Heap Max is 1024 m (–xmx1024m) heap min 256 m (–xms256m) using Verbose GC (–XVERBOSEGC)

It is very important that even if we assign 1024 m to the JVM, as we did in the verbose GC fragment above, this does not mean that we will definitely use it or we will never use it all 1024 m. For example, in this verbose fragment, we use only 616,233,472 bytes.

The JVM was first assigned the least 256 M and put the space into use. As shown in Figure 1, the 1024 m of the entire heap is placed on standby (the entire bar), and only the original 256 m is assigned to use, as shown in the shaded area in the figure.
Fig. 1 schematic diagram of heap

Because only 256 m is available, the JVM populates this initial 256 m with the objects needed to run the program Programtorun first. These objects are gradually added to the space until there is not enough contiguous space to meet the requirement of placing the next object on the heap (see Figure 2).
Figure 2. Heap after loading objects of different sizes

At this point, the next object begins to request space on the heap, but there is not enough contiguous space to satisfy the request (see Figure 3).
Fig. 3. Schematic diagram of the Request object

When this request occurs, the JVM runs a GC with Action=1, and the schematic changes, as shown in Figure 4.
Figure 4. JVM runs GC with action=1 (note that unused objects have been deleted)

Become:

Therefore, the request can be satisfied at this time:

Sometimes, objects may not be moved or purged, and these objects are typically class objects and objects that are still in use. Suppose there were two requests that were similar to the one before, but no objects on the heap could be deleted (see Figure 5).
Figure 5. Current representation of heap in use

In this case, the GC runs a action=2 to try to run a compaction phase. In the compaction phase, the objects on the heap are consolidated to collect all the free space to meet the current request.

The schematic diagram of heap should be similar to Figure 6.
Figure 6. The heap of austerity

At this point, the next request can be processed (see Figure 7).
Figure 7. Progress of Heap

With GC actions 1 and 2, we can now look at what to do if there is not enough space to allocate to the next object even after the actions 1 and 2 have been run.

This lack of space occurs when we continue to process our heap, as we have assumed that not all objects can be purged (see Figure 8).
Figure 8. The heap is tight and the allocation space is full

As you can see, the free space of the heap we are using is full. In our case, the 256 m of this heap is full, because we only assign 256 m as free space for heap. Be sure to remember that our heap is up to 1024 M, so if this happens, we have more room available.

In this case, the JVM executes a action=3 and expands the heap by 65,535 bytes to provide more heap for us to use (see Figure 9), as you can see in the verbose GC.
Figure 9. Extended 65536-byte system heap

Become this:

Now, the processing can continue. The GC loop continues until all newly allocated heap have undergone the same action, allocating more heap until the final 1024 M is allocated.

From this approach, we can see that starting with a smaller initial heap and increasing heap will keep heap close and relatively healthy.

As shown below is an example of a verbose GC from a full GC followed by a heap extension:

&LT;AF[12]: allocation failure. Need 8208 bytes, 2272 Ms since last af> &LT;AF[12]: Managing allocation failure, action=2 (3255768/52427264) > < GC: GC Cycle started Wed Dec 2 13:55:07 2009 &LT;GC (): Freed 9836696 bytes, 24% free (13092464/52427264), in M S> &LT;GC (): mark:50 MS, Sweep:8 MS, Compact:1-ms> &LT;GC (a): Refs:soft 0 (age >=), weak 0, final 1 Phantom 0> &LT;AF[12]: Managing allocation failure, ACTION=3 (13092464/52427264) > <gc (a): need to expand M Ark bits for 61602304-byte heap> &LT;GC (a): Expanded mark bits by 143360 to 962560 bytes> (a): &LT;GC to E Xpand alloc bits for 61602304-byte heap> &LT;GC (a): Expanded alloc bits by 143360 to 962560 bytes> (12): Need to expand FR bits for 61602304-byte heap> &LT;GC (a): expanded FR bits by 286720 to 1925120 bytes> &LT;GC (1 2): Expanded heap by 9175040 to 61602304 bytes, 36% free> <af[12]: Completed in ms>

With an understanding of how heap grows and how it is used by the JVM, you can now better understand how much memory is actually being used by the JVM when the process is running.

There are some misconceptions about how much memory a process or portal uses at run time. Typically, the user of the portal determines how much memory the Java process uses by using the PS avg command or Microsoft®windows®task Manager, which shows the amount of memory the system allocates to the Java process.

As you can see, assigning to process X amount of memory does not mean that a process actually uses so many amounts of memory.

If the Task Manager or "PS avg" shows that the Java process uses 616 M memory, if we look at the verbose GC, we see that it currently uses only 40% of that number:

<GC (177): Freed 218620376 bytes, 40% free (248587064/616233472), in 459 ms>

If you receive a outofmemory error while there is still free memory in the heap, you can determine what the reason is by looking at the verbose GC. As shown below is a sample output from an out-of-memory error in the verbose GC:

&LT;AF[2474]: allocation failure. Need 16777232 bytes, 114 ms since lastaf>-<af[2474]: Managing Allocation, Failure (action=2) 1026078032/1601894912 T &LT;GC (2835): GC cycle started Thu June 11:21:34 2009 (&LT;GC): 2835 freed 5827392, bytes free (1031905424/16018949 , in 2519 ms> &LT;GC (2835): mark:567 MS, sweep:24 MS, compact:1928 ms>-&LT;GC (2835): Refs:soft 0 (age (=), weak 0, final 6, Phantom 0> &LT;GC (2835): Moved 1711341 objects, 87482984 bytes, reason=1, used 8 more bytes& Gt &LT;AF[2474]: Managing allocation failure, ACTION=3 (1031905424/1601894912) > <gc (2835): Need to expand Mark bits F or 1610611200-byte heap> &LT;GC (2835): Expanded mark bits by 135168 to 25165824 bytes>-&LT;GC (2835): Need to Exp and alloc bits for 1610611200-byte heap> &LT;GC (2835): Expanded alloc bits by 135168 to 25165824 bytes> (2 835): Need to expand fr bits for 1610611200-byte heap> &LT;GC (2835): Expanded FR bits by 270336 to50331648 bytes> &LT;GC (2835): Expanded heap fully by 8716288 to 1610611200 bytes, 64% free> <af[2474]: managing Allocation failure, action=4 (1040621712/1610611200) > <af[2474]: Clearing all remaining soft refs> &LT;GC (2836 ): GC cycle started Thu 11:21:35 2009 &LT;GC (2836): Freed 227346312 bytes, 78% free (1267968024/1610611200), in 1 Ms> &LT;GC (2836): mark:370 MS, sweep:19 MS, compact:1211 ms> (&LT;GC): 2836 Refs:soft (age 438 32), Weak 1178, final, Phantom 0> &LT;GC (2836): Moved 1359393 objects, 60973368 bytes, reason=1, used T &LT;AF[2474]: Managing allocation failure, ACTION=6 (1267968024/1610611200) > Jvmdg217:dump Handler is Processing OutO Fmemory-please wait. JVMDG315:JVM requesting Heap dump file jvmdg318:heap dump file written to/opt/websphere/appserver/heapdump.20090716.112 135.19377.phd JVMDG303:JVM requesting Java core file Jvmdg304:java core file written To/opt/websphere/appserver/javacoRe.20090716.112144.19377.txt jvmdg274:dump Handler has processed outofmemory. &LT;AF[2474]: Insufficient spaces in javaheap to satisfy allocation request> <af[2474]: Completed in 19738 ms>

As you can see, there is enough free memory in this instance:

<GC (2836): Freed 227346312 bytes, 78% free (1267968024/1610611200), in 1600 ms>

But the objects that require space allocation are also quite large:

<AF[2474]: allocation failure. Need 16777232 bytes, 114 ms since lastaf>

There are two ways to deal with this kind of out-of-memory situation: One way is to use K-cluster (-XK), and another way is to define a heap segment (–xloratio) for a larger object, where loratio means large object ratio.

-xkn

This parameter leaves a space within the heap for the class object to be stored. As you can see in the previous example, the references in use cannot be moved or cleared. So they are "nailed" to this position within the heap, and if enough objects are pinned to different positions within the heap, the heap becomes broken.

To resolve this splitting problem, you can use parameter –XKN, which specifically provides a heap segment for class objects. A better starting value for n is parameter 40,000, even if you need to use the WebSphere Portal Support for system tuning analysis.

If we set this argument to 40,000,JVM, we would allow up to 40,000 class objects to be stored in this k-cluster. If the k-cluster is full, the system continues normally and is processed using the remainder of the heap.

To add –xk to the native JVM parameters in the admin console, follow these steps: On the WebSphere application Server V6.0, select Servers-application servers-server_name -Java and Process management-process definition-java Virtual machine-generic JVM Arguments.

Or on the WebSphere application Server V5.0 and V5.1, select Servers-application servers-server_name-process definition-jav A Virtual machine-generic JVM Arguments. Enter –xk40000, save this configuration, and then reboot the server.

–xloration

This setting allows a portion of heap to be left out for use by large objects, where large objects refer to objects larger than the K.

As we have seen in the previous sketch, we need to allocate the contiguous space on the heap to the object. Obviously, looking for 528 bytes of contiguous space is much simpler than looking for contiguous space of more than 1,000,000 bytes.

Large objects can be allocated more easily if they are stored in specific segments of the heap, and smaller objects do not need to compete with them for heap use.

This GC can tune the value of this parameter by monitoring it after the verbose GC is implemented. The value of this parameter, N, represents the percentage of the total heap being expanded at this time. For this example, we used the value –xloratio0.2.

When this value is added to the server, you can see that there is a new row in the verbose GC output, as follows:

<GC (2): Heap layout: (424744560/429495496) (107373880/107373880)/0>

As shown below is a block from the verbose GC with the –xloratio0.2 enabled:

<AF[2]: allocation failure. Need 536 Bytes, 235 ms since last af> <af[2 ]: Managing allocation failure, Action=0 (423162736/429495496) (1 07373880/107373880) > <GC (2): GC cycle started Sat Aug 17:07:25 2009 <GC (2): Heap layout: ( 424744560/429495496) (107373880/107373880) /0> <GC (2): Freed 1581824, Bytes free (532118440/ 536869376), in ms> <GC (2): Mark:9 MS, Sweep:9 MS, compact:0-ms> <GC (2): Refs:soft 0 (age >= Weak 0, final 0, Phantom 0> <af[2]: Completed in ms>

One of the lines (shown below) shows how we can tune this value n, because we can now see the layout of the heap:

<GC (2): Heap layout: (424744560/429495496) (107373880/107373880)/0>

The first ratio is the regular area of the heap (80% for regular processing), and the second is the heap segment (20% allocated to large objects) that we allocate for large objects.

In addition, the amount of free space within each section is also shown. From this output we can see that the entire large object segment is idle, indicating that no large objects are in use.

If this trend continues, we need to reduce the heap segment of the large object from 20% to 10% to allow more space for routine processing. We use –xloratio0.1 as the new value, preferably with 10% or 0.1 as the starting value.

To add –xloratio to the native JVM parameters in the admin console, follow these steps: On the WebSphere application Server V6.0, select Servers-application servers-server _name-java and Process management-process definition-java Virtual machine-generic JVM Arguments.

Or on the WebSphere application Server V5.0 and V5.1, select Servers-application servers-server_name-process definition-jav A Virtual machine-generic JVM Arguments. Enter –xloratio0.1, save this configuration, and then reboot the server.

You can use multiple threads to perform GC. This value should be 1 less than the number of processors on the system; For example, if there are four processors on the system, three threads should be used for GC. To get this value, we used the following parameters:

–xgcthreadsn
To set up three threads on a four-processor system, add the –xgcthreads parameter to the native JVM parameter in the admin console, following these steps: On the WebSphere application Server V6.0, select Servers-applica tion Servers-server_name-java and Process management-process definition-java Virtual machine-generic JVM Argumen Ts.

Or on the WebSphere application Server V5.0 and V5.1, select Servers-application servers-server_name-process definition-jav A Virtual machine-generic JVM Arguments. Enter –XGCTHREADS3, save this configuration, and then reboot the server.

Post SR12

Another way to improve GC performance is to enable the concurrent mark parameter. As can be seen from the output of the verbose GC, the mark phase of the GC loop takes most of the time. Like what:

<AF[1640]: allocation failure. Need 536 bytes, 154266 Ms since last af> <af[1640 ]: Managing allocation failure, Action=1 (0/879124880) (215 122200/219781232) > <gc (1718): GC cycle started Wed Aug 13:16:24 2009 <GC (1718): Heap layout: ( 308539208/879124880) (215136552/219781232) /0> <GC (1718): Freed 308553560 bytes, 47% free (523675760/ 1098906112), in 684 ms> <GC (1718): mark:607 MS, sweep:77 MS, compact:0 ms> (<GC): 1718 FT 1 (age >=), weak, final 582, Phantom 3> <af[1640]: Completed in 685 ms>

Here, a total of 685ms of time, 607ms is spent at Mark Stage. To shorten the time spent, you can introduce the following parameters, which are proven to work well in newer versions of version SR13 or JDK:

–xgcpolicy:optavgpause
This parameter shortens the time spent on Mark and retains the mark phase while the GC cycle is not in progress.

To add the –xgcpolicy:optavgpause parameter to the native JVM parameters in the admin console (SR13 or later in the Java SDK 1.4.2), follow these steps: In WebSphere application Server V6.0 , select Servers-application Servers-server_name-java and Process management-process Definition-java Virtual Machine -Generic JVM Arguments.

Or on the WebSphere application Server V5.0 and V5.1, select Servers-application servers-server_name-process definition-jav A Virtual machine-generic JVM Arguments. Enter –xgcpolicy:optavgpause, save this configuration, and then reboot the server.