Print-friendly Version

Understanding Concurrent Mark Sweep Garbage Collector Logs

May 2006

Concurrent Mark Sweep (CMS) is a type of Garbage Collector (GC) available in the Java Virtual Machine (JVM) of the Java 2 SDK. This document explains the traces generated by JVM when run with certain diagnostic flags, specifically the logs generated with VM option -XX:+PrintGCDetails for this collector.

Java technology-based applications can be instructed to run with CMS for the old generation by specifying -XX:UseConcMarkSweepGC. However, starting with JDK version 1.5, on server-class machines, VM automatically chooses CMS as the collector for the old generation.

By understanding these logs, users can tune the various GC parameters of their applications and improve performance. For example, this can help in deciding how much heap space should be given to each generation.

Using CMS GC with -XX:+PrintGCDetails and -XX:+PrintGCTimeStamps prints a lot of information. Understanding this information can help in fine-tuning various parameters of the application and CMS to achieve the best performance.

Let's have a look at some of the CMS logs generated with Java 2 Platform, Standard Edition (J2SE) version 1.4.2_10:

39.910: [GC 39.910: [ParNew: 261760K->0K(261952K), 0.2314667 secs] 
         262017K->26386K(1048384K), 0.2318679 secs]

Note: Young generation (ParNew) collection. The young generation capacity is 261952K and after the collection, its occupancy drops down from 261760K to 0. This collection took 0.2318679 seconds.

40.146: [GC [1 CMS-initial-mark: 26386K(786432K)] 26404K(1048384K), 
         0.0074495 secs]

Note: Beginning of tenured generation collection with CMS collector. This is the initial marking phase of CMS where all the objects directly reachable from roots are marked, and this is done with all the mutator threads stopped.

The capacity of the tenured generation space is 786432K and CMS was triggered at the occupancy of 26386K.

40.154: [CMS-concurrent-mark-start]

Note: Start of concurrent marking phase.
In the concurrent Marking phase, threads stopped in the first phase are started again, and all the objects transitively reachable from the objects marked in the first phase are marked here.

40.683: [CMS-concurrent-mark: 0.521/0.529 secs]

Note: Concurrent marking took a total of 0.521 seconds CPU time and 0.529 seconds wall time, which includes the yield to other threads also.

40.683: [CMS-concurrent-preclean-start]

Note: Start of precleaning.

Precleaning is also a concurrent phase. Here in this phase we look at the objects in CMS heap which were updated by promotions from the young generation or new allocations, or were updated by mutators while we were doing the concurrent marking in the previous concurrent marking phase. By rescanning those objects concurrently, the precleaning phase helps reduce the work in the next stop-the-world 'remark' phase.

40.701: [CMS-concurrent-preclean: 0.017/0.018 secs]

Note: Concurrent precleaning took 0.017 seconds of total CPU time and 0.018 wall time.

40.704: [GC40.704: [Rescan (parallel) , 0.1790103 secs]
40.883: [weak refs processing, 0.0100966 secs] 
[1 CMS-remark: 26386K(786432K)] 52644K(1048384K), 0.1897792 secs]

Note: Stop-the-world phase. This phase rescans any residual updated objects in CMS heap, retraces from the roots and also processes reference objects. Here the rescanning work took 0.1790103 seconds, and weak reference objects processing took 0.0100966 seconds. This phase took total 0.1897792 seconds to complete.

40.894: [CMS-concurrent-sweep-start]

Note: Start of sweeping of dead/non-marked objects. Sweeping is a concurrent phase performed with all other threads running.

41.020: [CMS-concurrent-sweep: 0.126/0.126 secs]

Note: Sweeping took 0.126 seconds.

41.020: [CMS-concurrent-reset-start]

Note: Start of reset.

41.147: [CMS-concurrent-reset: 0.127/0.127 secs]

Note: In this phase, the CMS data structures are reinitialized so that a new cycle may begin at a later time. In this case, it took 0.127 seconds.

This was how a normal CMS cycle runs. Now let us look at some other CMS log entries:

197.976: [GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]
197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs]
   (concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 
   663850K->248977K(1048384K), 2.3733725 secs]

This shows that a ParNew collection was requested, but was not attempted. (The reason is that it was estimated that there was not enough space in the CMS generation to promote the worst-case surviving young generation objects.) We name this failure a "full promotion guarantee failure".

As a result, the concurrent mode of CMS is interrupted and a full GC is invoked. This mark-sweep-compact stop-the-world full GC took 2.3733725 seconds, and the CMS generation space occupancy dropped from 402978K to 248977K.

The concurrent mode failure can either be avoided by increasing the tenured generation size or initiating the CMS collection at a lesser heap occupancy by setting CMSInitiatingOccupancyFraction to a lower value and setting UseCMSInitiatingOccupancyOnly to true. The value for CMSInitiatingOccupancyFraction should be chosen appropriately because setting it to a very low value will result in too frequent CMS collections.

Sometimes we see these promotion failures even when the logs show that there is enough free space in tenured generation. The reason is 'fragmentation' -- the free space available in tenured generation is not contiguous, and promotions from young generation require a contiguous free block to be available in tenured generation. CMS collector is a non-compacting collector, so this can cause fragmentation of space for some types of applications.

Jon Masamitsu's weblog talks in detail on how to deal with this fragmentation problem: http://blogs.sun.com/roller/page/jonthecollector?entry=when_the_sum_of_the

Starting with JDK version 1.5, for the CMS collector, the promotion guarantee check is done differently. Instead of assuming that the promotions would be worst case (that is, all of the surviving young generation objects would get promoted into old gen), the expected promotion is estimated based on recent history of promotions. This estimation is usually much smaller than the worst-case promotion and hence requires less free space to be available in old generation. And if the promotion in a scavenge attempt fails, then the young generation is left in a consistent state and a stop-the-world mark-compact collection is invoked. To get the same functionality with UseSerialGC you need to explicitly specify the switch -XX:+HandlePromotionFailure.

283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000615 secs] 
          826554K->826554K(1048384K), 0.0003259 secs]
GC locker: Trying a full collection because scavenge failed
283.736: [Full GC 283.736: [ParNew: 261599K->261599K(261952K), 0.0000288 secs]

Stop-the-world GC happens when a JNI critical section is released. Here again the young generation collection failed due to "full promotion guarantee failure" and then the Full GC was invoked.

CMS can also be run in incremental mode (i-cms), enabled with -XX:+CMSIncrementalMode. In this mode, CMS collector does not hold the processor for the entire long concurrent phases but periodically stops them and yields the processor back to other threads in application. It divides the work to be done in concurrent phases into small chunks (called duty cycles) and schedules them between minor collections. This is very useful for applications that need low pause times and are run on machines with a small number of processors.

Here are some logs showing the incremental CMS.

2803.125: [GC 2803.125: [ParNew: 408832K->0K(409216K), 0.5371950 secs] 
           611130K->206985K(1048192K) icms_dc=4 , 0.5373720 secs]
2824.209: [GC 2824.209: [ParNew: 408832K->0K(409216K), 0.6755540 secs] 
           615806K->211897K(1048192K) icms_dc=4 , 0.6757740 secs] 

Here, the scavenges took respectively 537 ms and 675 ms. In between these two scavenges, iCMS ran for a brief period as indicated by the icms_dc value, which indicates a duty cycle. In this case the duty cycle was 4%. A simple calculation shows that the iCMS incremental step lasted for 4/100 * (2824.209 - 2803.125 - 0.537) = 821 ms, i.e. 4% of the time between the two scavenges.

Starting with 1.5, CMS has one more phase -- concurrent abortable preclean. Abortable preclean is run between a 'concurrent preclean' and 'remark' until we have the desired occupancy in Eden. This phase is added to help schedule the 'remark' phase so as to avoid back-to-back pauses for a scavenge closely followed by a CMS remark pause. In order to maximally separate a scavenge from a CMS remark pause, we attempt to schedule the CMS remark pause roughly mid-way between scavenges.

There is a second reason why we do this. Immediately following a scavenge there are likely a large number of gray objects that need rescanning. The abortable preclean phase tries to deal with such newly gray objects thus reducing a subsequent CMS remark pause.

The scheduling of the remark phase can be controlled by two JVM options: CMSScheduleRemarkEdenSizeThreshold and CMSScheduleRemarkEdenPenetration. The defaults for these are 2m and 50%, respectively. The first parameter determines the Eden size below which no attempt is made to schedule the CMS remark pause. (The reason for this is that the pay-off is expected to be minuscule.) The second parameter indicates the Eden occupancy at which a CMS remark is attempted.

7688.150: [CMS-concurrent-preclean-start]
7688.186: [CMS-concurrent-preclean: 0.034/0.035 secs]
7688.186: [CMS-concurrent-abortable-preclean-start]
7688.465: [GC 7688.465: [ParNew: 1040940K->1464K(1044544K), 0.0165840 secs] 
           1343593K->304365K(2093120K), 0.0167509 secs]
7690.093: [CMS-concurrent-abortable-preclean: 1.012/1.907 secs]
7690.095: [GC[YG occupancy: 522484 K (1044544 K)]
7690.095: [Rescan (parallel) , 0.3665541 secs]
7690.462: [weak refs processing, 0.0003850 secs] 
          [1 CMS-remark: 302901K(1048576K)] 825385K(2093120K), 
           0.3670690 secs]

In the above log, after a preclean, 'abortable preclean' starts. After the young generation collection, the young gen occupancy drops down from 1040940K to 464K. When young gen occupancy reaches 522484K, which is 50% of the total capacity, precleaning is aborted and 'remark' phase is started.

Note that in JDK version 1.5, young generation occupancy also is printed in the final remark phase.

For more detailed information and tips on GC tuning, please refer to the following documents:

• Tuning Garbage Collection with the 5.0 Java[tm] Virtual Machine
• Tuning Garbage Collection with the 1.4.2 Java[tm] Virtual Machine

Note: The terms "Java Virtual Machine" and "JVM" mean a Virtual Machine for the Java platform.

The information and links on this page have been provided by a BigAdmin user. The submitter is solely responsible for such information and links. Sun is not responsible for the availability of external sites or resources, and does not endorse and is not responsible or liable for any content, advertising, products, or other materials on or available from such sites or resources. Sun will not be responsible or liable, directly or indirectly, for any actual or alleged damage or loss caused by or in connection with use of or reliance on the information posted here, or goods or services available on or through any external site or resource.

Unless otherwise licensed, code in all technical manuals herein (including articles, FAQs, samples) is provided under this License.