verbosegc

Using verbosegc, which is enabled by the -verbosegc option, is a good way to see what's going on with GC. Output is displayed on stderr for every GC cycle, giving information about what occurred. You can use the information to tune the heap size or diagnose any problems. Note that verbosegc can, and usually does, change between releases. The following examples are taken from Java 1.3.1.

verbosegc for a System.gc

<GC(3): GC cycle started Tue Mar 19 08:24:34 2002
<GC(3): freed 58808 bytes, 27% free (1163016/4192768), in 14 ms>
  <GC(3): mark: 13 ms, sweep: 1 ms, compact: 0 ms>
  <GC(3): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

The above verbosegc output is an example of a System.gc collection, or forced GC. All the lines start with GC(3), which means this was the third GC in this JVM. The first line shows the date and time of the start of the collection. The second line shows that 58808 bytes were freed in 14ms, resulting in 27% free space in the heap. The figures in parentheses show the actual number of bytes free, and the total bytes available in the heap. The third line shows the times for the mark, sweep, and compaction phases. There was no compaction, so the time is zero. The last line shows the reference objects that were found during this GC, and the threshold for removing soft references. In this case no reference objects were found.

verbosegc for an allocation failure

<AF[5]: Allocation Failure. need 32 bytes, 286 ms since last AF>
<AF[5]: managing allocation failure, action=1 (0/6172496) (247968/248496)>
<GC(6): GC cycle started Tue Mar 19 08:24:46 2002
<GC(6): freed 1770544 bytes, 31% free (2018512/6420992), in 25 ms>
  <GC(6): mark: 23 ms, sweep: 2 ms, compact: 0 ms>
  <GC(6): refs: soft 1 (age >= 4), weak 0, final 0, phantom 0>
<AF[5]: completed in 26 ms>

The above verbosegc output is an example of an allocation failure (AF) collection. An AF does not mean there has been an error in the code; it's the name of the event that triggers when we cannot allocate a large enough chunk from the heap. As shown, we have the same four lines as the System.gc verbose output, plus some additional lines. The lines starting with AF[5] are the allocation failure lines and indicate this was the fifth AF collection in this JVM. The first line shows how many bytes were required by the allocation that had a failure, and how long it has been since the last AF. The second line shows what action we are taking to resolve the AF, how much free space is available in the main part of the heap, and how much is available in the wilderness. The possible AF actions are:

[1] Performing a GC without using the wilderness. It is designed to avoid compactions by keeping the wilderness available for a large allocation request.

[2] Tried to allocate out of the wilderness and failed.

[3] Attempting to expand the heap.

[4] Clearing any remaining soft references. This is only done if there is less than 12% free space in a fully expanded heap.

[5] Trying to steal some space from the transient heap. Only applies to resettable mode.

[6] Not actually an action. It gives a verbosegc message that we are very low on heap space, or totally out of heap space.

The last line shows how long the AF took, and includes the time it took to stop and start all the application threads.

verbosegc for a heap expansion

<AF[11]: Allocation Failure. need 24 bytes, 182 ms since last AF>
<AF[11]: managing allocation failure, action=1 (0/6382368) (10296/38624)>
<GC(12): GC cycle started Tue Mar 19 08:24:49 2002
<GC(12): freed 1877560 bytes, 29% free (1887856/6420992), in 21 ms>
  <GC(12): mark: 19 ms, sweep: 2 ms, compact: 0 ms>
  <GC(12): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>
<AF[11]: managing allocation failure, action=3 (1887856/6420992)>
<GC(12): need to expand mark bits for 7600640-byte heap>
<GC(12): expanded mark bits by 16384 to 118784 bytes>
<GC(12): need to expand alloc bits for 7600640-byte heap>
<GC(12): expanded alloc bits by 16384 to 118784 bytes>
<GC(12): expanded heap by 1179648 to 7600640 bytes, 40% free>
<AF[11]: completed in 31 ms>

The above verbosegc output is an example of an AF collection that includes a heap expansion. The output is the same as a verbosegc output for an AF, plus some additional lines for the expansion. It shows how much the mark bits, alloc bits, and the heap are expanded by, and how much free space is available. In the example we expanded the heap by 1179648 bytes, which gave us 40% free space.

verbosegc for a heap shrinkage

<AF[9]: Allocation Failure. need 32 bytes, 92 ms since last AF>
<AF[9]: managing allocation failure, 
  action=1 (0/22100560) (1163184/1163184)>
<GC(9): may need to shrink mark bits for 22149632-byte heap>
<GC(9): shrank mark bits to 348160>
<GC(9): may need to shrink alloc bits for 22149632-byte heap>
<GC(9): shrank alloc bits to 348160>
<GC(9): shrank heap by 1114112 to 22149632 bytes, 79% free>
<GC(9): GC cycle started Tue Mar 19 11:08:18 2002
<GC(9): freed 17460600 bytes, 79% free (17509672/22149632), in 7 ms>
  <GC(9): mark: 4 ms, sweep: 3 ms, compact: 0 ms>
  <GC(9): refs: soft 0 (age >= 6), weak 0, final 0, phantom 0>
<AF[9]: completed in 8 ms>

verbosegc for heap shrinkage is very similar to the verbosegc output for heap expansion. We show how much the mark bits, alloc bits, and the heap are shrunk by, and how much free space is available. In the example we shrank the heap by 1114112 bytes, which gave us 79% free space. One other difference between the verbosegc output for heap expansion and heap shrinkage is the order of the output; expansion happens after all the threads have been restarted and shrinkage happens before all the threads have been restarted.

verbosegc for a compaction

<AF[2]: Allocation Failure. need 88 bytes, 5248 ms since last AF>
<AF[2]: managing allocation failure, action=1 (0/4032592) (160176/160176)>
<GC(2): GC cycle started Tue Mar 19 11:32:28 2002
<GC(2): freed 1165360 bytes, 31% free (1325536/4192768), in 63 ms>
  <GC(2): mark: 13 ms, sweep: 1 ms, compact: 49 ms>
  <GC(2): refs: soft 0 (age >= 32), weak 0, final 3, phantom 0>
  <GC(2): moved 32752 objects, 2511088 bytes, reason=2, used 8 more bytes>
<AF[2]: completed in 64 ms>

The above verbosegc example shows a compaction. The main difference from the others is the additional line showing how many objects have been moved, how many bytes have been moved, the reason for the compaction, and how many additional bytes have been added. It is possible to have additional bytes, because if we move an object that has been hashed we have to store the hash value in the object, which may mean increasing the object's size. The possible reasons for a compaction are:

reason=1 Following the mark and sweep phase there is insufficient free space for the allocation request.

reason=2 The heap is fragmented and will benefit from a compaction.

reason=3 Less than half the -Xminf value is free space (the default is 30%, in which case this will be less than 15% free space), and the free space plus the dark matter is not less than -Xminf.

reason=4 A System.gc collection.

reason=5 Less than 5% free space available.

reason=6 Less than 128K free space available.

reason=7 The -Xcompactgc parameter has been specified.

reason=8 The transient heap has less than 5% free space available.

reason=9 The heap is fragmented. This is different from reason 2 because it uses an additional heuristic to determine if compaction should be done.

verbosegc and concurrent mark kick-off

<CONCURRENT GC Free= 379544 Expected free space= 378884 Kickoff=379406>
<  Initial Trace rate is   8.01>

The two lines above are the verbosegc output indicating the concurrent phase has started. The first line shows how much free space is available, and how much there will be after this heap lock allocation. The Kickoff value is the level at which concurrent mark will start. In this example you can see that the expected space is 378884, which is less than the kick-off value of 379406. The second line shows the initial trace rate of 8.01, which means that for every byte allocated in a heap lock allocation we must trace 8.01 bytes of live data.

verbosegc and a concurrent mark System.gc collection

<GC(3): Concurrent ABORTED. Target=3025707 Traced=0 (0+0) Free=885720>
<GC(3): GC cycle started Tue Mar 19 13:04:02 2002
<GC(3): freed 30008 bytes, 26% free (1125368/4192768), in 15 ms>
  <GC(3): mark: 14 ms, sweep: 1 ms, compact: 0 ms>
  <GC(3): refs: soft 0 (age >= 32), weak 0, final 0, phantom 0>

The System.gc verbosegc output with concurrent mark has one additional line, line 1. The state of ABORTED shows that concurrent mark did not complete the initialization phase and was therefore aborted. This is not an error condition, but means we did not get time to initialize concurrent mark before the System.gc. The state could also be HALTED, which would mean that initialization completed and concurrent mark was interrupted by the System.gc. Target is the estimated amount of tracing to be done by the concurrent phase. Traced is the actual amount traced, which is zero in this example as the concurrent phase was aborted. Free is the amount of free space available when concurrent was aborted. All the above amounts are in bytes.

verbosegc and a concurrent mark AF collection

<AF[6]: Allocation Failure. need 4000016 bytes, 86 ms since last AF>
<AF[6]: managing allocation failure, action=2 (1596416/23263744)>
<GC(6): Concurrent HALTED (state=128). Target=21435225 
  Traced=3625624 (3625624+0) Free=1587376>
<GC(6): No Dirty Cards cleaned (Factor 0.130)>
<GC(6): GC cycle started Tue Mar 19 13:42:52 2002
<GC(6): freed 16834536 bytes, 79% free (18430952/23263744), in 23 ms>
  <GC(6): mark: 20 ms, sweep: 3 ms, compact: 0 ms>
  <GC(6): In mark: Final dirty Cards scan: 10 ms 2211 cards (total:36 ms)
  <GC(6): refs: soft 0 (age >= 1), weak 0, final 0, phantom 0>
<AF[6]: completed in 25 ms>

The above is an example of an AF collection when concurrent mark is running. Line 3 shows that concurrent was HALTED, and what state it was in at the time. The possible states are:

• 64 - Concurrent collection was tracing
• 128 - Concurrent collection was tracing and cleaning dirty cards

The Traced figures in parenthesis show how much is traced by the application threads and how much is traced by the background thread. In this example there was no background thread tracing, probably due to this being run on a busy uniprocessor.

Line 4 shows that no dirty cards had been cleaned concurrently when the AF occurred. Factor is used to estimate the number of dirty cards with respect to the heap size. Line 8 shows the time it took to do final card cleaning and how many cards were cleaned. It took 10ms to clean 2211 cards. The total time is the total card cleaning time for this JVM.

verbosegc and a concurrent mark collection

<CON[2]: Concurrent collection, (905720/22100560) (1163184/1163184), 
  115 ms since last CON>
<GC(8): Concurrent EXHAUSTED. Target=15506720 Traced=4300312 (4300312+0) 
  Free=905720>
<GC(8): Cards cleaning Done. cleaned:1922 (0 skipped). 
  estimation 5468 (Factor 0.120)>
<GC(8): GC cycle started Tue Mar 19 13:42:53 2002
<GC(8): freed 16554096 bytes, 80% free (18623000/23263744), in 6 ms>
  <GC(8): mark: 3 ms, sweep: 3 ms, compact: 0 ms>
  <GC(8): In mark: Final dirty Cards scan: 0 ms 258 cards (total:37 ms)
  <GC(8): refs: soft 0 (age >= 4), weak 0, final 0, phantom 0>
<CON[2]: completed in 7 ms>

The above verbosegc output is an example of a collection initiated by concurrent mark. Instead of AF at the start of the lines there is CON. The first line shows how much space is used and available in the main part of the heap and the wilderness. It also shows how long since the last collection. The second line shows that concurrent is EXHAUSTED, meaning there was no more work for concurrent to do so it initiated the GC. I have already discussed the other fields on this line. Line 3 shows that concurrent card cleaning was done; cleaned is the number of dirty cards that required cleaning and were cleaned, estimation is the number of dirty cards found.

verbosegc and resettable

<TH_AF[8]: Transient heap Allocation Failure. need 64 bytes, 9716 ms 
  since last TH_AF>
<TH_AF[8]: managing TH allocation failure, action=3 (0/4389888)>
<GC(25): need to expand transient mark bits for 4586496-byte heap>
<GC(25): expanded transient mark bits by 3072 to 71672 bytes>
<GC(25): need to expand transient alloc bits for 4586496-byte heap>
<GC(25): expanded transient alloc bits by 3072 to 71672 bytes>
<GC(25): expanded transient heap fully by 196608 to 4586496 bytes>
<TH_AF[8]: completed in 1 ms>

When running resettable there is a middleware heap and a transient heap. The verbosegc for the transient heap is slightly different. In the above example, we use TH_AF instead of AF. The policy when running resettable is to expand the transient heap when an allocation failure occurs, rather than GC it. The preceding example shows a successful expansion.

<TH_AF[11]: Transient heap Allocation Failure. need 32 bytes, 16570 ms 
  since last TH_AF>
<TH_AF[11]: managing TH allocation failure, action=3 (0/4586496)>
<TH_AF[11]: managing TH allocation failure, action=2 (0/4586496)>
  <GC(29): GC cycle started Tue Mar 19 14:47:42 2002
<GC(29): freed 402552 bytes from Transient Heap 8% free (402552/4586496) and...>
<GC(29): freed 1456 bytes, 38% free (623304/1636864), in 1285 ms>
  <GC(29): mark: 1263 ms, sweep: 22 ms, compact: 0 ms>
  <GC(29): refs: soft 0 (age >= 6), weak 0, final 0, phantom 0>
<TH_AF[11]: completed in 1287 ms>

The example above shows what happens when the expansion is not successful. Here we have to do a GC and can see how much space is freed from each of the heaps.

Back to top

Command line parameters

The following list contains all the GC command line parameters available up to Java 1.3.1.

-verbosegc

-verbose:gc

Prints garbage collection information. The format for the information is not architected and varies from platform to platform and release to release.

-Xcompactgc

Compact the heap every GC cycle. The default is false.

-Xgcpolicy:<optthruput | optavgpause>

Setting gcpolicy to optthruput disables concurrent mark. If you do not have pause time problems, denoted by erratic application response times, you should get the best throughput with this option. Optthruput is the default.

Setting gcpolicy to optavgpause enables concurrent mark with its default values. If you do have problems with erratic application response times caused by normal garbage collection, you can alleviate those problems, at the cost of some throughput, when running the optavgpause option.

-Xgcthreads<number>

Sets the number of total number of threads used for garbage collection. On a system with N processors, the default setting for -Xgcthreads is 1 when in resettable mode and N when not in resettable mode.

-Xinitacsh<size>

Sets the initial size of the application-class system heap. This option is only available in the resettable JVM. Classes in this heap exist for the lifetime of the JVM. They are reset during a ResetJavaVM(), and so are serially reusable by applications running in the JVM. There is only one application-class system heap per Persistent Reusable JVM. In nonresettable mode, this option is ignored. For example: -Xinitacsh256k Default: 128K on 32-bit architecture, and 8M on 64-bit architecture.

-Xinitsh<size>

Sets the initial size of the system heap. Classes in this heap exist for the lifetime of the JVM. The system heap is never subjected to garbage collection. The maximum size of the system heap is unbounded. For example: -Xinitsh256k Default: 128K on 32-bit architecture, and 8M on 64-bit architecture.

-Xinitth<size>

Sets the initial size of the transient heap within the nonsystem heap. This option is only available in the resettable JVM. If this option is not specified and -Xms is, the initial size is taken to be half the -Xms value. If -Xms is not specified, a value of half the platform-dependent default value is used. For example: -Xinitth2M Default: 1M/2 = 512K

-Xjvmset<size>

Creates a master JVM. You can specify an optional size in megabytes to set the total size of the shared memory segment. The default is 1MB. When JNI_CreateJavaVM() returns successfully, the "extrainfo" field of the JavaVMOption contains the token to be passed to each worker. An attempt to create two master JVMs with the same token will fail.

The -Xresettable option must be used with this option when starting a master JVM.

-Xjvmset

Creates a worker JVM. The "extrainfo" field of the JavaVMOption must contain the token returned on the -Xjvmset option used to create the master JVM.

-Xmaxe<size>

Specifies the maximum expansion size of the heap. The default is 0. In resettable mode, this sets a maximum expansion size of <size>/2 for both the middleware and transient heaps.

-Xmaxf<number>

A floating point number between 0 and 1 that specifies the maximum percentage of free space in the heap. The default is 0.6, or 60%. When this value is set to 0, heap contraction is a constant activity. With a value of 1, the heap never contracts. In resettable mode, this parameter applies to the middleware heap only.

-Xmine<size>

Specifies the minimum expansion size of the heap. The default is 1M. In resettable mode, this option sets a minimum expansion size of <size>/2 for both the middleware and transient heaps.

-Xminf<number>

A floating point number between 0 and 1 that specifies the minimum free heap size percentage. The heap grows if the free space is below the specified amount. In resettable mode, this option specifies the minimum percentage of free space for the middleware and transient heaps. The default is .3, or 30%.

-Xms<size>

Sets the initial size of the heap. If this option is not specified it will default as follows:

• Java 1.2.2 and 1.3.0
• Windows - 4M
• All other platforms - 1M
• Java 1.3.1
• Windows, AIX, and Linux - 4M
• OS/390 - 1M

-Xmx<size>

Sets the maximum size of the heap. In resettable mode, this option sets the maximum size of the combined middleware and transient heaps. The middleware heap grows from the bottom of this region, and the transient heap grows from the top of the region. If this option is not specified it will default as follows:

• Java 1.2.2 and 1.3.0
• Windows - Half the real storage with a minimum of 16M and a maximum of 2G-1
• All other platforms - 64M
• Java 1.3.1
• Windows - Half the real storage with a minimum of 16M and a maximum of 2G-1
• OS/390 and AIX - 64M
• Linux - Half the real storage with a minimum of 16M and a maximum of 512M-1

-Xnocompactgc

Never compact the heap. Default is "false."

-Xresettable

Specifies that this instance of the JVM will be capable of supporting the resettable JVM.

Back to top

Summary

I hope you found this series about the IBM Java Garbage Collector useful. Part 1 discussed how objects are allocated in the Java heap. Part 2 reviewed how garbage collection works, and covered the three main phases: mark sweep, and compact. This article delved into verbosegc and other command line parameters. Dealing with garbage isn't always easy, but the IBM Java Garbage Collector allows for sensible sanitation.

Resources

• Participate in the discussion forum.
  
  
• Resettable JVM and JVMSet JVM documentation.
  
  
• Garbage Collection - Algorithms for Automatic Dynamic Memory Management, by Richard Jones and Rafael Lins (John Wiley & Son Ltd, 1996, ISBN:0-471-94148-4).
  
  
• Read Part 1, Object allocation (developerWorks, August 2002) and Part 2, Garbage collection (developerWorks, August 2002) in this series.
  
  
• Find more Java resources on the developerWorks Java technology zone.
  
  

About the author

Comments

Back to top

Trademarks  |  My developerWorks terms and conditions

Table of contents

• verbosegc
• Command line parameters
• Summary
• Resources
• About the author
• Comments

Next steps from IBM

Spring, JRuby, and Ajax development is easier with WebSphere Application Server - a smart Java 5 and J2EE Web services-based application server.

---

• Try: The no-charge WebSphere Application Server Community Edition is a pre-integrated, lightweight Java 5 application server built on Apache Tomcat and other best-of-breed open source software such as OpenEJB, Apache Axis, and Apache Derby.
• Article: The article leverage the Spring Framework and the WebSphere Application Server to improve your J2EE project productivity.
• Tutorial: See how the free WebSphere Application Server and XML can improve the efficiency of your JRuby on Rails and Ajax development.
• Buy: WebSphere Application Server - Express

My developerWorks community