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不算

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 157,198评论 4 359
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 66,663评论 1 290
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 106,985评论 0 237
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 43,673评论 0 202
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 51,994评论 3 285
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,399评论 1 211
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,717评论 2 310
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,407评论 0 194
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,112评论 1 239
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,371评论 2 241
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,891评论 1 256
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,255评论 2 250
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,881评论 3 233
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,010评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,764评论 0 192
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,412评论 2 269
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,299评论 2 260

推荐阅读更多精彩内容