CMS-logs相关整理

hehehe

• Retire Some Rarely-Used GC Combinations

  • DefNew + CMS
  • ParNew + SerialOld
  • Incremental CMS

• -XX:+UseConcMarkSweepGC(常用组合)

  • UseConcMarkSweepGC is "ParNew" + "CMS" + "Serial Old".
    • "CMS" is used most of the time to collect the tenured generation.
    • "Serial Old" is used when a concurrent mode failure occurs.
  • FAQ
    • How do I use "CMS" with "Serial"?
      • -XX:+UseConcMarkSweepGC -XX:-UseParNewGC.
      • Don't use -XX:+UseConcMarkSweepGC and -XX:+UseSerialGC. Although that's seems like
        a logical combination, it will result in a message saying something about
        conflicting collector combinations and the JVM won't start. Sorry about that.
        Our bad.

• Serial GC logs

  • introduce
    • uses mark-copy for the Young Generation and mark-sweep-compact for the Old Generation
    • -XX:+UseSerialGC (Enabling this collector for both the Young and Old Generation is done via specifying a single parameter in the JVM startup script)
    • both of these collectors are single-threaded collectors
    • Both collectors also trigger stop-the-world pauses
  • -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps
    • 2015-05-26T14:45:37.987-0200: 151.126: [GC (Allocation Failure) 151.126:
      [DefNew: 629119K->69888K(629120K), 0.0584157 secs] 1619346K->1273247K(2027264K), 0.0585007 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
    • 2015-05-26T14:45:59.690-0200: 172.829: [GC (Allocation Failure) 172.829:
      [DefNew: 629120K->629120K(629120K), 0.0000372 secs]172.829:
      [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs] 1832479K->755802K(2027264K),
      [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs] [Times: user=0.18 sys=0.00, real=0.18 secs]
  • Minor GC(第一段)
    • Time when the GC event started.
    • Time when the GC event started, relative to the JVM startup time. Measured in seconds.
    • Flag to distinguish between Minor & Full GC. This time it is indicating that this was a Minor GC.
    • Cause of the collection. In this case, the GC is triggered due to a data structure not fitting into any region in the Young Generation.
    • Name of the garbage collector used. This cryptic name stands for the single-threaded mark-copy stop-the-world garbage collector used to clean Young generation.
    • Usage of the Young Generation before and after collection.
    • Total size of the Young Generation.
    • Total used heap before and after collection.
    • Total available heap.
    • Duration of the GC event in seconds. 0.0585007 secs
    • Duration of the GC event, measured in different categories:
      user – Total CPU time that was consumed by the garbage collector threads during this collection
      sys – Time spent in OS calls or waiting for system event
      real – Clock time for which your application was stopped. As Serial Garbage Collector always uses just a single thread, real time is thus equal to the sum of user and system times.
    • conclusion
      • heap usage totaled at 1,619,346K. Out of this, the Young Generation consumed 629,119K. From this we can calculate the Old Generation usage being equal to 990,227K.
      • Young Generation usage decreased by 559,231K but total heap usage decreased only by 346,099K. From this we can again derive that 213,132K of objects were promoted from the Young Generation to the Old Generation.
  • Full GC(第二段)
    • For this collection the same DefNew collector was run as before and it decreased the usage of the Young Generation from 629120K to 0. Notice that JVM reports this incorrectly due to buggy behavior and instead reports the Young Generation as being completely full. This collection took 0.0000372 seconds.
    • Tenured – Name of the garbage collector used to clean the Old space. The name Tenured indicates a single-threaded stop-the-world mark-sweep-compact garbage collector being used.
    • Similar information about Metaspace collection. As seen, no garbage was collected in Metaspace during the event.
    • conclusion
      • The difference with Minor GC is evident – in addition to the Young Generation, during this GC event the Old Generation and Metaspace were also cleaned.

• Concurrent Mark and Sweep logs

  • introduce
    • uses the parallel stop-the-world mark-copy algorithm in the Young Generation and the mostly concurrent mark-sweep algorithm in the Old Generation.
    • -XX:+UseConcMarkSweepGC
  • avoid long pauses
    • does not compact the Old Generation but uses free-lists to manage reclaimed space.
    • does most of the job in the mark-and-sweep phases concurrently with the application
  • drawbacks
    • the most notable of them being the Old Generation fragmentation and the lack of predictability in pause durations in some cases, especially on large heaps.
    • still competes for CPU time with the application threads. By default, the number of threads used by this GC algorithm equals to 1/4 of the number of physical cores of your machine.
    • at least some CPU resources are consumed by the GC and not executing your application’s code, CMS generally often worse throughput than Parallel GC in CPU-bound applications.
  • -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

    cms-logs
    2015-05-26T16:23:07.219-0200: 64.322: [GC (Allocation Failure) 64.322: [ParNew: 613404K->68068K(613440K), 0.1020465 secs] 10885349K->10880154K(12514816K), 0.1021309 secs] [Times: user=0.78 sys=0.01, real=0.11 secs]
    2015-05-26T16:23:07.321-0200: 64.425: [GC (CMS Initial Mark) [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
    2015-05-26T16:23:07.321-0200: 64.425: [CMS-concurrent-mark-start]
    2015-05-26T16:23:07.357-0200: 64.460: [CMS-concurrent-mark: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
    2015-05-26T16:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start]
    2015-05-26T16:23:07.373-0200: 64.476: [CMS-concurrent-preclean: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
    2015-05-26T16:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start]
    2015-05-26T16:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs]
    2015-05-26T16:23:08.447-0200: 65.550: [GC (CMS Final Remark)
    [YG occupancy: 387920 K (613440 K)]65.550:
    [Rescan (parallel) , 0.0085125 secs]65.559:
    [weak refs processing, 0.0000243 secs]65.559:
    [class unloading, 0.0013120 secs]65.560:
    [scrub symbol table, 0.0008345 secs]65.561:
    [scrub string table, 0.0001759 secs]
    [1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
    2015-05-26T16:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start]
    2015-05-26T16:23:08.485-0200: 65.588: [CMS-concurrent-sweep: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
    2015-05-26T16:23:08.485-0200: 65.589: [CMS-concurrent-reset-start]
    2015-05-26T16:23:08.497-0200: 65.601: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
    - explainations
    - Minor GC
    - Name of the collector used, this time it indicates a parallel mark-copy stop-the-world garbage collector used in the Young Generation, designed to work in conjunction with Concurrent Mark & Sweep garbage collector in the Old Generation.
    - 0.1021309 secs – The time it took for the garbage collector to mark and copy live objects in the Young Generation. This includes communication overhead with ConcurrentMarkSweep collector, promotion of objects that are old enough to the Old Generation and some final cleanup at the end of the garbage collection cycle.
    - conclusion
    - From the above we can thus see that before the collection the total used heap was 10,885,349K and the used Young Generation share was 613,404K. This means that the Old Generation share was 10,271,945K. After the collection, Young Generation usage decreased by 545,336K but total heap usage decreased only by 5,195K. This means that 540,141K was promoted from the Young Generation to Old.
    - Full GC
    - Just to bear in mind – in real world situation Minor Garbage Collections of the Young Generation can occur anytime during concurrent collecting the Old Generation. In such case the major collection records seen below will be interleaved(交错) with the Minor GC events covered in previous chapter.
    - CMS Initial Mark
    - The goal of this phase is to mark all the objects in the Old Generation that are either direct GC roots or are referenced from some live object in the Young Generation. The latter is important since the Old Generation is collected separately.
    - 10812086K – Currently used Old Generation.
    - (11901376K) – Total available memory in the Old Generation.
    - 10887844K – Currently used heap
    - (12514816K) – Total available heap
    - Concurrent Mark
    - traverses the Old Generation and marks all live objects, Note that not all the live objects in the Old Generation may be marked, since the application is mutating references during the marking
    - Concurrent Preclean
    - accounting for references being changed during previous marking phase.
    - While the previous phase was running concurrently with the application, some references were changed. Whenever that happens, the JVM marks the area of the heap (called “Card”) that contains the mutated object as “dirty” (this is known as Card Marking).
    - In the pre-cleaning phase, these dirty objects are accounted for, and the objects reachable from them are also marked. The cards are cleaned when this is done.
    - Additionally, some necessary housekeeping and preparations for the Final Remark phase are performed.
    - Concurrent Abortable Preclean
    - This one attempts to take as much work off the shoulders of the stop-the-world Final Remark as possible
    - CMS Final Remark
    - The goal of this stop-the-world phase is to finalize marking all live objects in the Old Generation. Since the previous preclean phases were concurrent, they may have been unable to keep up with the application’s mutating speeds. A stop-the-world pause is required to finish the ordeal.
    - Usually CMS tries to run final remark phase when Young Generation is as empty as possible in order to eliminate the possibility of several stop-the-world phases happening back-to-back.
    - Final Remark in this occasion – that is marking all live objects in the Old Generation, including the references that were created/modified during previous concurrent marking phases.
    - YG occupancy: 387920 K (613440 K) – Current occupancy and capacity of the Young Generation.
    - [Rescan (parallel) , 0.0085125 secs] – 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.0085125 seconds.
    - weak refs processing, 0.0000243 secs]65.559 – First of the sub-phases that is processing weak references along with the duration and timestamp of the phase.
    - class unloading, 0.0013120 secs]65.560 – Next sub-phase that is unloading the unused classes, with the duration and timestamp of the phase.
    - scrub(擦洗) string table, 0.0001759 secs – Final sub-phase that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively. Clock time of the pause is also included.
    - 10812086K(11901376K) – Occupancy and the capacity of the Old Generation after the phase.
    - 11200006K(12514816K) – Usage and the capacity of the total heap after the phase.
    - After the five marking phases, all live objects in the Old Generation are marked and now garbage collector is going to reclaim all unused objects by sweeping the Old Generation:
    - Concurrent Sweep
    - to remove unused objects and to reclaim the space occupied by them for future use. sweeping unmarked and thus unused objects to reclaim space.
    - Concurrent Reset
    - resetting inner data structures of the CMS algorithm and preparing them for the next cycle.
    - G1 garbage first(jdk9默认)
    - both fit for young and old generation
    - Shenandoah
    - to manage heaps of 100GB and larger with pauses of 10ms or shorter. This is traded off against throughput: the implementers are aiming at a no more than 10% of a performance penalty for applications with no GC pauses.

• jonthecollector-The Unspoken - Phases of CMS
  • 上面有个preclean过程没怎么看懂,没关系再来看看Jon Masamitsu的文章就好了
  • 1.Initial mark
    • This is the the start of CMS collection. This is a stop-the-world phase. All the applications threads are stopped and CMS scans the application threads (e.g. the thread stacks) for object references.(这里还有一些全局位置,如静态字段等)
  • 2.Concurrent mark
    • This is a concurrent phase. CMS restarts all the applications threads and then starting from the objects found in 1), it finds all the other live objects. Almost (see the remark phase).
  • 3.Precleaning phase
    • This is a concurrent phase. This phase is an optimization and you don't really need to understand what it does so feel free to skip to 4. While CMS is doing concurrent marking (2.), the application threads are running and they can be changing the objects they are using. CMS needs to find any of these changes and ultimately does that during the remark phase. However, CMS would like to discovery this concurrently and so has the precleaning phase. CMS has a way of recording when an application thread makes a change to the objects that it is using. Precleaning looks at the records of these changes and marks live objects as live. For example if thread AA has a reference to an object XX and passes that reference to thread BB, then CMS needs to understand that BB is keeping XX alive now even if AA no longer is.
  • 4.The remark phase
    • The remark phase is a stop-the-world. CMS cannot correctly determine which objects are alive (mark them live), if the application is running concurrently and keeps changing what is live. So CMS stops all the application threads during the remark phase so that it can catch up with the changes the application has been making.
  • 5.The sweep phase
    • This is a concurrent phase. CMS looks at all the objects and adds newly dead objects to its freelists. CMS does freelist allocation and it is during the sweep phase that those freelists get repopulated.
  • 6.The reset phase
    • This is a concurrent phase. CMS is cleaning up its state so that it is ready for the next collection.
• 其实就是6个过程, abortable preclean不算

• References
  • Java Garbage Collection handbook
  • Our Collectors
  • The Unspoken - Phases of CMS