The Unspoken - CMS and PrintGCDetails

What follows is an example of the GC logging output with CMS (UseConcMarkSweepGC) and PrintGCDetails plus some explanation of the output.

The "CMS-initial-mark" indicates the start of a CMS concurrent collection.

[GC [1 CMS-initial-mark: 463236K(515960K)] 464178K(522488K), 0.0018216 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

463236K above is the space occupied by objects in the old (CMS) generation at the start of the collection. Not all those objects are necessarily alive.

515960K is the total size of the old (CMS) generation. This value changes if the generation grows or shrinks.

464178K is the sum of the space occupied by objects in the young generation and the old (CMS) generation.

522488K is the total size of the heap (young generation plus old (CMS) generation)

0.0018216 secs is the duration of the initial mark pause. The initial mark is a stop-the-world phase.

After the initial mark completes the CMS concurrent mark starts. The concurrent mark phase is a concurrent phase and can be interrupted by young generation collections. In this case the ParNew (UseParNewGC) is being used to collect the young generation. When a ParNew collection is ready to start, it raises a flag and the CMS collector yields execution to ParNew and waits for ParNew to finish before resuming.

[GC[ParNew: 6528K->702K(6528K), 0.0130227 secs] 469764K->465500K(522488K), 0.0130578 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

6528K is the space in the young generation occupied by objects at the start of the ParNew collection. Not all those objects are necessarily alive.

702K is the space occupied by live objects at the end of the ParNew collection.

6528K is the total space in the young generation.

0.0130227 is the pause duration for the ParNew collection.

469764K is the space occupied by objects in the young generation and the old (CMS) generation before the collection starts.

465500K is the space occupied by live objects in the young generation and all objects in the old (CMS) generation. For a ParNew collection, only the liveness of the objects in the young generation is known so the objects in the old (CMS) generation may be live or dead.

522488K is the total space in the heap.

[Times: user=0.05 sys=0.00, real=0.01 secs] is like the output of time(1) command. The ratio user / real give you an approximation for the speed up you're getting from the parallel execution of the ParNew collection. The sys time can be an indicator of system activity that is slowing down the collection. For example if paging is occurring, sys will be high.

[GC[ParNew: 6526K->702K(6528K), 0.0136447 secs] 471324K->467077K(522488K), 0.0136804 secs] [Times: user=0.04 sys=0.01, real=0.01 secs]

[GC[ParNew: 6526K->702K(6528K), 0.0161873 secs] 472901K->468830K(522488K), 0.0162411 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

[GC[ParNew: 6526K->702K(6528K), 0.0152107 secs] 474654K->470569K(522488K), 0.0152543 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

...

[GC[ParNew: 6526K->702K(6528K), 0.0144212 secs] 481073K->476809K(522488K), 0.0144719 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

This is the completion of the concurrent marking phase. After this point the precleaning starts.

[CMS-concurrent-mark: 1.039/1.154 secs] [Times: user=2.32 sys=0.02, real=1.15 secs]

The 1.039 is the elapsed time for the concurrent marking. The 1.154 is the wall clock time.

The "Times" output is less meaningful because it is measured from the start of the concurrent marking and includes more than just the work done for the concurrent marking.

This is the end of the precleaning phase.

[CMS-concurrent-preclean: 0.006/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

The format of the precleaning phase output is analogous to that of the concurrent marking phase.

[GC[ParNew: 6526K->702K(6528K), 0.0141896 secs] 482633K->478368K(522488K), 0.0142292 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

[GC[ParNew: 6526K->702K(6528K), 0.0162142 secs] 484192K->480082K(522488K), 0.0162509 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

The remark phase is scheduled so that it does not occur back-to-back with a ParNew so as not to appear to be a pause that is the sum of the ParNew and the remark pause. A second precleaning phase is started and is aborted when the remark phase is ready to start. Aborting this second precleaning phase is the expected behavior. That it was aborted is not an indication of an error. Since the remark phase is waiting, why not preclean but don't delay the remark for the sake of precleaning.

[CMS-concurrent-abortable-preclean: 0.022/0.175 secs] [Times: user=0.36 sys=0.00, real=0.17 secs]

This is the remark phase.

[GC[YG occupancy: 820 K (6528 K)][Rescan (parallel) , 0.0024157 secs][weak refs processing, 0.0000143 secs][scrub string table, 0.0000258 secs] [1 CMS-remark: 479379K(515960K)] 480200K(522488K), 0.0025249 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

[YG occupancy: 820 K (6528 K)] shows that at the start of the remark the occupancy (sum of the total of the allocated objects in the young generation is 820K out of a total of 6528K. The length of the remark pause depends to some degree on the occupancy of the young generation so we print it out.

The "Rescan" completes the marking of live objects while the application is stopped. In this case the rescan was done in parallel and took 0.0024157 secs.

"weak refs processing" and "scrub string table" are tasks done during the remark. Those tasks took 0.0000143 secs and 0.0000258 secs, respectively. If those numbers dominate the remark pause time, they can explain unexpectedly large pauses. Not that they cannot legitimately be large. Just that generally they are not and when they are, take note. If the weak refs processing is dominate, you might be able to cut that time down by using parallel reference processing (-XX:+ParallelRefProcEnabled). No comment on the case when scrub string table is dominant. I've never had to deal with it.

The concurrent sweeping phase starts at the end of the remark.

[GC[ParNew: 6526K->702K(6528K), 0.0133250 secs] 441217K->437145K(522488K), 0.0133739 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

[GC[ParNew: 6526K->702K(6528K), 0.0125530 secs] 407061K->402841K(522488K), 0.0125880 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

...

[GC[ParNew: 6526K->702K(6528K), 0.0121435 secs] 330503K->326239K(522488K), 0.0121996 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]

The sweep phase ends here.

[CMS-concurrent-sweep: 0.756/0.833 secs] [Times: user=1.68 sys=0.01, real=0.83 secs]

The format above is analogous to that of the concurrent marking.

And lastly the reset phase.

[CMS-concurrent-reset: 0.009/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

It is not expected that another concurrent CMS collection start before several ParNew collections have been done. If another CMS collection starts immediately, check how full the old (CMS) generation is. If the old (CMS) generation is close to being full immediately after the end of a collection, the heap might be too small.

I took this log with an early build of JDK8

java version "1.8.0-ea" Java(TM) SE Runtime Environment (build 1.8.0-ea-b73) Java HotSpot(TM) Server VM (build 25.0-b14, mixed mode)

and used the flags

-server -XX:+UseConcMarkSweepGC -XX:NewRatio=8 -XX:-PrintGCCause -XX:ParallelGCThreads=4 -Xmx1g -XX:+PrintGCDetails

I usually also use -XX+PrintTimeStampsps to get time stamps in the logs and use -XX:+PrintGCDateStamps if I want to correlate the GC output to application events.

Ref: https://blogs.oracle.com/jonthecollector/entry/the_unspoken_cms_and_printgcdetails