Java Reference
In-Depth Information
95.474: [CMS-concurrent-reset-start]
95.479: [CMS-concurrent-reset: 0.005/0.005 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
That is the last of the concurrent phases; the CMS cycle is now complete, and the unreferen-
ced objects found in the old generation are now free (resulting in the heap shown in Fig-
ure 6-5 ). Unfortunately, the log doesn't provide any information about how many objects
were freed; the reset line doesn't give any information about the heap occupancy. To get an
idea of that, look to the next young collection, which is:
98.049: [GC 98.049: [ParNew: 629120K->69888K(629120K), 0.1487040 secs]
1031326K->504955K(2027264K), 0.1488730 secs]
Now compare the occupancy of the old generation at 89.853 seconds (before the CMS cycle
began), which was roughly 703 MB (the entire heap occupied 772 MB at that point, which
included 69 MB in the survivor space, so the old generation consumed the remaining 703
MB). In the collection at 98.049 seconds, the old generation occupies about 504 MB; the
CMS cycle therefore cleaned up about 199 MB of memory.
If all goes well, these are the only cycles that CMS will run and the only log messages that
will appear in the CMS GC log. But there are three more messages to look for, which indic-
ate that CMS ran into a problem. The first is a concurrent mode failure:
267.006: [GC 267.006: [ParNew: 629120K->629120K(629120K), 0.0000200 secs]
267.006: [CMS267.350: [CMS-concurrent-mark: 2.683/2.804 secs]
[Times: user=4.81 sys=0.02, real=2.80 secs]
(concurrent mode failure):
1378132K->1366755K(1398144K), 5.6213320 secs]
[CMS Perm : 57231K->57222K(95548K)], 5.6215150 secs]
[Times: user=5.63 sys=0.00, real=5.62 secs]
When a young collection occurs and there isn't enough room in the old generation to hold all
the objects that are expected to be promoted, CMS executes what is essentially a full GC. All
application threads are stopped, and the old generation is cleaned of any dead objects, redu-
cing its occupancy to 1,366 MB—an operation which kept the application threads paused for
a full 5.6 seconds. That operation is single-threaded, which is one reason it takes so long
(and one reason why concurrent mode failures are worse as the heap grows).
Search WWH ::

Custom Search