Using verbose garbage collection to analyze IBM WebSphere Portal memory concerns

Learn how to read verbose garbage collection and how to use the tool to analyze IBM® WebSphere® Portal server memory concerns. This article discusses the life cycle of the JVM and shows you how to perform additional tuning for Java SDK 1.4.2.

Share:

Matt Munse, Support Engineer, IBM

Matt Munse is a Support Engineer focusing on WebSphere Portal run-time issues including memory, hangs, crash, performance, and WebSphere Portal search engine issues since 2002. Besides serving as the Support focal point for WebSphere Portal server performance issues, he contributes to IBM's patents and develops Java and J2EE applications for internal use. You can reach Matt at msmunse@us.ibm.com.



25 March 2010 (First published 18 March 2010)

Also available in Chinese Portuguese

Editor's note: Know a lot about this topic? Want to share your expertise? Participate in the IBM Lotus software wiki program today.

Introduction to garbage collection

This article is specific to versions 6.0 or later and 5.1 or later of WebSphere Portal, running Java™ Software Development Kit (SDK) 1.4.2. For proper tuning, use the latest service release of the SDK, or at least use a later service release than SR13 for the tuning discussed here.

A simple definition of garbage collection is the act of the JavaTM Virtual Machine (JVM) ridding the heap, a defined section of memory used for managing resources in a Java application, of objects that are no longer being referenced or used by the process.

The process has three major phases: mark, sweep, and compact:

  • In the mark phase, all the objects in the heap are “marked” with a bit. They are checked to see if they are still referenced, and, if so, the bit is removed.
  • In the sweep phase, the JVM goes through the heap and removes all the objects that still have the mark bit in place; these objects are no longer referenced or used.
  • The compact phase is run only in a full GC, which attempts to reallocate all the objects in the heap to a smaller, more compact, and more contiguous space in the heap.

How garbage collection works

The best way to inspect the heap usage is to analyze the verbose GC output.

Let’s begin by ensuring that verbose GC is enabled on the server:

  1. From the IBM WebSphere Application Server administrative console, navigate to Application Servers - WebSphere_Portal - Java and Process Management - Process Definition - Java Virtual Machine.
  2. Ensure that the check box next to Verbose garbage collection is selected, and then restart the server.
  3. You now see an entry similar to the following 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 >= 32), weak 11, final 7424, phantom 0>
    <AF[177]: completed in 460 ms>

Analyzing the log file entries

Now, let’s break down the preceding log entry into sections and determine what it tells us.

Begin here:

<AF[177]: Allocation Failure. need 528 bytes, 3602594 ms since last AF>

This entry lets us know that there was an allocation failure, which presents itself when there is not enough contiguous space in the heap to allocate the object. This object is the most common action that you see in the verbose GC output. In this case, it was a small object of 528 bytes.

We also see from this line that it has been a while since the last time we’ve had a GC cycle run, 3602594 ms.

Next, we examine the last line:

<AF[177]: completed in 460 ms>

This line shows us the amount of time that was spent in GC. Using this number, we can get the ratio of the last time that we were in GC and find out the percentage of time that we spend doing GC and not actual work; for example:

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

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

Return to the second line:

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

The first thing to notice here is the “action=” figure. Seven different actions can occur for an allocation failure:

  • action=0 means the pinnedFreeList was exhausted.
  • action=1 means a preemptive garbage collection cycle.
  • action=2 means a full allocation failure.
  • action=3 means that a heap expansion takes place.
  • action=4 means that all known soft references are cleared.
  • action=5 means that stealing from the transient heap is done.
  • action=6 means that free space is very low.

These actions are listed in the order of severity; the most severe occurs when the server is completely out of memory (action=6).

In this case, we have action=1. In this type of GC, only the mark and sweep phases of GC are run.

This line also includes:

(0/585421800) (29966688/30811672)

This line is specific to AIX® JVMs. As you can see, there are two base numbers that, when added together, are the size to which the heap has expanded. One is smaller and is automatically used for large object allocation.

NOTE: A large object is anything more than 64 K.

All other objects are placed in the other section of the heap. If the large-object section is filled and another large object requests allocation, the object is placed on the other main section of the heap. This object can be a useful tuning parameter in other multiplatform JVMs and is called a -Xloratio.

The next line is:

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

This line reports the time at which the GC cycle began and the cycle that we’re in, that is, GC(177). This is the 177th GC that has run since the JVM was started.

The following line:

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

states how many bytes were freed during the GC cycle; in this case, the JVM was able to free 218620376 bytes.

Also, we see that the heap is now 40 percent free and that there are 248,587,064 bytes free in the heap size of 616,233,472 bytes:

(248587064/616233472)

Finally, the GC cycle took 459 ms to complete.

This line is useful because it tells us how much of the heap is free and that there are objects being cleaned up and not pinned to the heap.

The next line is:

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

This line is useful later in this article for tuning how we can configure GC to run faster (see -Xgcpolicy:optavgpause) but, for now, understand the following:

This line shows how long each cycle has run. The mark phase took 422 ms, the sweep phase took 37 ms, and the compact phase took 0 ms.

Also, two things tell us that this is not a full GC:

  • The compact phase took 0 ms to complete.
  • The action=1 shows us that is was a preemptive GC, before a full GC runs.

The last line to study is:

<GC(177): refs: soft 0 (age >= 32), weak 11, 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 associated with one of four queues on creation, and the association cannot change later. The four queues are marked during the mark phase in this order:

  1. Soft
  2. Weak
  3. Final
  4. Phantom

Soft and weak references can be cleaned up when they are no longer referenced. If a finalizer (Final queue) is associated with a soft or weak reference, then only after the soft or weak reference is removed is the finalizer removed on the next GC pass that is run.

These are the main lines that you see in the default GC policy on a Java SDK 1.4.2. With that understanding, let’s explore how a JVM runs.


Life cycle of the JVM

The JVM starts with optional command-line arguments that begin the process. These are the generic JVM arguments that are added in the WebSphere Application Server administrative console.

On a basic level, this command is what's executed when the Java process starts:

Java –Xmx1024M –Xms256M –Xverbosegc programToRun

where the command-line arguments

–Xmx1024M –Xms256M –Xverbosegc

mean that the following occur on startup:

  • The max heap size is 1024 M (–Xmx1024M)
  • The min heap size is 256 M (–Xms256M)
  • Verbose garbage collection is used (–Xverbosegc)

It's important to note that, even though we allocate 1024 M for the JVM, as was done in the above verbose GC snippet, this case doesn’t mean that we use, or will ever use, the full 1024 M. For example, in the verbose snippet, we used only 616,233,472 bytes.

The JVM starts with the minimum 256 M allocated and put this space into use. As shown in figure 1, here the entire heap, 1024 M, is set aside to be used (the entire bar), but only the initial 256 M is allocated to be used, as shown by the shaded area.

Figure 1. Pictorial representation of the heap
Pictorial representation of the heap

Because there is 256 M available, the JVM begins to fill this initial 256 M with the objects that are needed to run the program programToRun. The objects are added to this space until there is not enough contiguous space to satisfy the request for the next object being placed on the heap (see figure 2).

Figure 2. Heap with different-sized objects loaded
Heap with different-sized objects loaded

The next object now requests space on the heap, but there is not enough contiguous space to satisfy this request (see figure 3).

Figure 3. Pictorial representation of the requesting object
Pictorial representation of the requesting object

When this request happens, the JVM runs a GC with action=1, and the pictorials change as shown in figure 4.

Figure 4. JVM running GC with action=1 (note the unused object is removed)
JVM running GC with action=1 (note the unused object is removed)

Becomes:

So now this request can be satisfied:

At times, there are objects that cannot be moved or cleaned up; namely, class objects and objects that are still in use. Let's say two more requests come in like the previous one, but now no more objects on the heap can be removed (see figure 5).

Figure 5. Current representation of the heap in use
Current representation of the heap in use

In this case, the GC then runs an action=2, which attempts to run a compaction phase. In a compaction phase, the objects that are on the heap are consolidated to allow any free memory to gather together and satisfy the current request.

The pictorial heap becomes like the one shown in figure 6.

Figure 6. Compacted heap
Compacted heap

At this point, the next request can be allocated (see figure 7).

Figure 7. Progression of the working heap continues
Progression of the working heap continues

Now that the GC actions 1 and 2 are understood, we can see what happens when there is not enough space to allocate the next object, even after both actions 1 and 2 are run.

This lack of space is the case if we continue with our heap because we assigned the assumption that not all objects are able to be cleaned up (see figure 8).

Figure 8. Compacted heap with the allocated space full
Compacted heap with the allocated space full

We can see that the amount of heap that we’re using is full. In our example, we have 256 M of our heap full, and we have allocated only 256 M as usable heap thus far. Keep in mind that our max heap size is set to 1024 M, so we have more that we can use if this situation were to occur.

In this case, the JVM conducts an action=3 and expands the heap by 65,535 bytes to give us more heap to use (see figure 9), and this case will be seen in the verbose GC.

Figure 9. System heap expanded by 65536 bytes
System heap expanded by 65536 bytes

Becomes this:

And now the processing can continue. The GC cycles continue until all the newly allocated heap goes through the same actions as above, and then more heap is allocated until, finally, the full 1024 M is reached.

As we can see with this method, small initial heap, the heap grows sequentially and remains compact and relatively healthy.

Here is an example of a verbose GC from a full GC, followed by a heap expansion:

<AF[12]: Allocation Failure. need 8208 bytes, 2272 ms since last AF>
<AF[12]: managing allocation failure, action=2 (3255768/52427264)>
  <GC(12): GC cycle started Wed Dec  2 13:55:07 2009
  <GC(12): freed 9836696 bytes, 24% free (13092464/52427264), in 59 ms>
  <GC(12): mark: 50 ms, sweep: 8 ms, compact: 1 ms>
  <GC(12): refs: soft 0 (age >= 32), weak 0, final 102, phantom 0>
<AF[12]: managing allocation failure, action=3 (13092464/52427264)>
  <GC(12): need to expand mark bits for 61602304-byte heap>
  <GC(12): expanded mark bits by 143360 to 962560 bytes>
  <GC(12): need to expand alloc bits for 61602304-byte heap>
  <GC(12): expanded alloc bits by 143360 to 962560 bytes>
  <GC(12): need to expand FR bits for 61602304-byte heap>
  <GC(12): expanded FR bits by 286720 to 1925120 bytes>
  <GC(12): expanded heap by 9175040 to 61602304 bytes, 36% free>
<AF[12]: completed in 75 ms>

Now that you understand how the heap grows and is used by the JVM, you can better understand how much memory is actually being used by the JVM while the process is running.


Analyzing how much memory a process uses

Misconceptions can arise about how much memory a process, or portal, uses during runtime. Often, users of the portal determine how much memory the Java process is using through the ps avg command or the Microsoft® Windows® Task Manager, which shows how much memory has been allocated to the Java process.

As we've seen, just because X amount of memory is allocated to the process, it does not mean that’s how much is being used.

If the Task Manager or “ps avg” shows that the Java process is using 616 M, and we look at the verbose GC, we see that it is currently using only 40 percent of that amount:

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

OUTOFMEMORY error with free space in the heap

If you receive an OUTOFMEMORY error and there’s free space in the heap, you can examine the verbose GC to determine what caused it. Here's an example of output from an out-of-memory occurrence in the verbose GC:

<AF[2474]: Allocation Failure. need 16777232 bytes, 114 ms since lastAF>
<AF[2474]: managing allocation failure, action=2(1026078032/1601894912)>
  <GC(2835): GC cycle started Thu Jul 16 11:21:34 2009
  <GC(2835): freed 5827392 bytes, 64% free (1031905424/1601894912), in 2519 ms>
  <GC(2835): mark: 567 ms, sweep: 24 ms, compact: 1928 ms>
  <GC(2835): refs: soft 0 (age >= 32), weak 0, final 6, phantom 0>
  <GC(2835): moved 1711341 objects, 87482984 bytes, reason=1, used 8 more bytes>
<AF[2474]: managing allocation failure, action=3 (1031905424/1601894912)>
  <GC(2835): need to expand mark bits for 1610611200-byte heap>
  <GC(2835): expanded mark bits by 135168 to 25165824 bytes>
  <GC(2835): need to expand alloc bits for 1610611200-byte heap>
  <GC(2835): expanded alloc bits by 135168 to 25165824 bytes>
  <GC(2835): need to expand FR bits for 1610611200-byte heap>
  <GC(2835): expanded FR bits by 270336 to 50331648 bytes>
  <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>
  <GC(2836): GC cycle started Thu Jul 16 11:21:35 2009
  <GC(2836): freed 227346312 bytes, 78% free (1267968024/1610611200), in 1600 ms>
  <GC(2836): mark: 370 ms, sweep: 19 ms, compact: 1211 ms>
  <GC(2836): refs: soft 438 (age >= 32), weak 1178, final 70, phantom 0>
  <GC(2836): moved 1359393 objects, 60973368 bytes, reason=1, used 600 more bytes>
<AF[2474]: managing allocation failure, action=6 (1267968024/1610611200)>
JVMDG217: Dump Handler is Processing OutOfMemory - Please Wait.
JVMDG315: JVM Requesting Heap dump file
JVMDG318: Heap dump file written to
/opt/WebSphere/AppServer/heapdump.20090716.112135.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.
<AF[2474]: Insufficient space in Javaheap to satisfy allocation request>
<AF[2474]: completed in 19738 ms>

As we can see, there is plenty of free memory in this instance:

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

but the object requesting allocation space was also quite large:

<AF[2474]: Allocation Failure. need 16777232 bytes, 114 ms since lastAF>

There are two ways to combat this type of out-of-memory situation, either with a k-cluster (-Xk) or by defining a segment of the heap for large objects (–Xloratio), where loratio is large object ratio.

-Xkn

This parameter sets aside a place in the heap for class objects to be stored. As we saw in the previous example, references that are still in use by the process cannot be moved or cleaned up. They are therefore “pinned” to that place in the heap, and, if enough objects are pinned in different locations in the heap, the heap becomes fragmented.

To fix this fragmentation, we can use the parameter –Xkn, which provides a section of the heap exclusively for class objects. A good starting value for n in this parameter is 40,000, though you need to engage WebSphere Portal Support for system tuning analysis.

If we set this parameter at 40,000, the JVM allows space for 40,000 class objects to be stored in the k-cluster. If this k-cluster becomes full, the system continues as normal and uses the remainder of the heap for the processing.

To add the –Xk to generic JVM arguments in the administrative console, follow these steps:

  1. On 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 WebSphere Application Server V5.0 and V5.1, select Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments.
  2. Enter –Xk40000, save this configuration, and then restart the server.

–Xloration

This setting allows for a section of the heap to be set aside for the use of large objects, which are defined as any objects greater than 64 K.

As we saw in the pictorial example, an object needs contiguous space to be allocated on the heap. Obviously, it would be easier to find 528 bytes of contiguous space than 1,000,000 bytes of contiguous space.

If the large objects are kept within a certain segment of the heap, they can be more easily allocated; moreover, smaller objects do not need to compete with them to gain heap usage.

The value of this parameter is one that you can tune by monitoring the verbose GC after implementation. The value n for this parameter is given as a percentage of the total heap that is expanded at that time. For this example, let's use the value –Xloratio0.2.

When this value is added to the server, you see a new line added to the verbose GC output, such as:

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

Below is a block from the verbose GC with –Xloratio0.2 enabled:

<AF[2]: Allocation Failure. need 536 bytes, 235 ms since last AF>
<AF[2]: managing allocation failure, action=0 (423162736/429495496) 
(107373880/107373880)>
  <GC(2): GC cycle started Sat Aug 15 17:07:25 2009
  <GC(2): heap layout:  (424744560/429495496) (107373880/107373880)  /0>
  <GC(2): freed 1581824 bytes, 99% free (532118440/536869376), in 18 ms>
  <GC(2): mark: 9 ms, sweep: 9 ms, compact: 0 ms>
  <GC(2): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>
<AF[2]: completed in 18 ms>

This line is how we can tune this value of n because we can now see the heap layout:

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

The first ratio is the normal area of the heap (80 percent used for normal processing), and the second is what we have defined for the large objects (20 percent for large-object allocation).

What is displayed is the amount of free space in each section. As we can see from this output, all the large-object section is free, and there are no large objects being used.

If this trend were to continue, we lower the fraction from 20 percent to 10 percent, to allow more space to be used for normal processing. We use –Xloratio0.1 for the new value, a good value to begin with is 10 percent, or 0.1.)

To add –Xloratio to generic JVM arguments in the administrative console, follow these steps:

  1. On 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 WebSphere Application Server V5.0 and V5.1, select Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments.
  2. Enter –Xloratio0.1, save this configuration, and then restart the server.

Additional tuning for Java SDK 1.4.2

Multiple processors

You can use more than one thread to perform GC. This number is one less than the number of processors that you have on the system; for example, if you have a four-processor system, you should use three threads for GC. To obtain this value, we implement the following parameter:

–Xgcthreadsn
To set three threads on a four-processor system, add the –Xgcthreads parameter to generic JVM arguments in the administrative console, follow these steps:

  1. On 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 WebSphere Application Server V5.0 and V5.1, select Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments.
  2. Enter –Xgcthreads3, save the configuration, and then restart the server.

Post SR12

Another thing you can do to help with GC performance is to enable a concurrent mark parameter. As we've seen with monitoring the verbose GC output, most of the time spent occurs in the mark phase of the GC cycle. For example:

<AF[1640]: Allocation Failure. need 536 bytes, 154266 ms since last AF>
<AF[1640]: managing allocation failure, action=1 (0/879124880) 
(215122200/219781232)>
  <GC(1718): GC cycle started Wed Aug 19 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): refs: soft 1 (age >= 32), weak 19, final 582, phantom 3>
<AF[1640]: completed in 685 ms>

Here, 607 ms of the total 685 ms was spent in mark. To combat this time spent, you can introduce the following parameter, which has proved to work correctly in versions SR13 and later of the JDK:

–Xgcpolicy:optavgpause
The parameter reduces the time spent in mark and keeps the mark phase running, even if a GC cycle is not in process.

To add the –Xgcpolicy:optavgpause parameter to generic JVM arguments in the administrative console (SR13 and later of Java SDK 1.4.2), follow these steps:

  1. On 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 WebSphere Application Server V5.0 and V5.1, select Servers - Application Servers - server_name - Process Definition - Java Virtual Machine - Generic JVM Arguments.
  2. Enter –Xgcpolicy:optavgpause, save the configuration, and then restart the server.

Conclusion

You should now understand how to read verbose garbage collection and how to use this tool to analyze and address WebSphere Portal server memory concerns.

Resources

Comments

developerWorks: Sign in

Required fields are indicated with an asterisk (*).


Need an IBM ID?
Forgot your IBM ID?


Forgot your password?
Change your password

By clicking Submit, you agree to the developerWorks terms of use.

 


The first time you sign into developerWorks, a profile is created for you. Information in your profile (your name, country/region, and company name) is displayed to the public and will accompany any content you post, unless you opt to hide your company name. You may update your IBM account at any time.

All information submitted is secure.

Choose your display name



The first time you sign in to developerWorks, a profile is created for you, so you need to choose a display name. Your display name accompanies the content you post on developerWorks.

Please choose a display name between 3-31 characters. Your display name must be unique in the developerWorks community and should not be your email address for privacy reasons.

Required fields are indicated with an asterisk (*).

(Must be between 3 – 31 characters.)

By clicking Submit, you agree to the developerWorks terms of use.

 


All information submitted is secure.

Dig deeper into WebSphere on developerWorks


static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=1
Zone=WebSphere
ArticleID=473630
ArticleTitle=Using verbose garbage collection to analyze IBM WebSphere Portal memory concerns
publish-date=03252010