JDK-8196862 : [REDO] STW phases at Concurrent GC should count in PerfCounter
  • Type: CSR
  • Component: hotspot
  • Sub-Component: gc
  • Priority: P4
  • Status: Closed
  • Resolution: Approved
  • Fix Versions: 11
  • Submitted: 2018-02-06
  • Updated: 2018-02-19
  • Resolved: 2018-02-15
Related Reports
CSR :  
JDK-8153333 - [REDO] STW phases at Concurrent GC should count in PerfCounter
Description
Summary
-------

Add CGC column to jstat for monitoring STW (stop the world) phases in concurrent GC.

Problem
-------

STW phases (Initial Mark and Remark) at CMS are counted in jstat FGC column. However, FGC column is incremented when Full GC is occurred. So we cannot judge Full GC is occurred or not from jstat output. Also STW phases on G1 (Remark and Cleanup) are not counted in any jstat output.

Solution
--------

I added new PerfCounters for monitoring STW concurrent GC phases count and elapsed time. Also I added new column to jstat output: CGC (count) and CGCT (elapsed time).

Specification
-------------

http://cr.openjdk.java.net/~ysuenaga/JDK-8153333/webrev.07/

I added new CollectorCounters which is named sun.gc.collector.2 . This counter keeps STW phase metrics in concurrent GC. It is incremented at VMOperations of STW phase in concurrent GC.

### G1 ###

#### jstat output in JDK 9 ####

Neither YGC nor FGC are not counted in spite of GC is occurred via jcmd. (Target VM is added `-XX:+ExplicitGCInvokesConcurrent` )

    $ jstat -gc 3576 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
     0.0    0.0    0.0    0.0   26624.0    0.0     487424.0     0.0      0.0    0.0    0.0    0.0        0    0.000   0      0.000    0.000
    $
    $ jcmd 3576 GC.run
    3576:
    Command executed successfully
    $
    $ jstat -gc 3576 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
     0.0   2048.0  0.0   2048.0 24576.0    0.0     487424.0     0.0     4864.0 3829.9 512.0  325.9       1    0.012   0      0.000    0.012

#### Proposal ####

CGC / CGCT are counted when concurrent GC is occurred. They show STW phases in concurrent GC.

    $ jstat -gc 16604 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
     0.0    0.0    0.0    0.0   26624.0    0.0     487424.0     0.0      0.0    0.0    0.0    0.0        0    0.000   0      0.000   0      0.000    0.000
    $
    $ jcmd 16604 GC.run
    16604:
    Command executed successfully
    $ jstat -gc 16604 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
     0.0   2048.0  0.0   2048.0 24576.0    0.0     487424.0     0.0     4864.0 3825.5 512.0  325.9       1    0.012   0      0.000   2      0.007    0.019

### CMS ###

#### jstat output in JDK 9 ####

FGC / FGCT are counted when GC is occurred via jcmd. (Target VM is added `-XX:+ExplicitGCInvokesConcurrent` )

    $ jstat -gc 3714 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
    17088.0 17088.0  0.0    0.0   137152.0  8229.3   342720.0     0.0      0.0    0.0    0.0    0.0        0    0.000   0      0.000    0.000
    $
    $ jcmd 3714 GC.run
    3714:
    Command executed successfully
    $
    $ jstat -gc 3714 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
    17088.0 17088.0  0.0   547.4  137152.0   0.0     342720.0     0.0     4864.0 3830.0 512.0  325.9       1    0.012   2      0.022    0.034

#### Proposal ####

CGC / CGCT are counted when concurrent GC is occurred. They show STW phases in concurrent GC, and FGC / FGCT are not counted for them.

    $ jstat -gc 20651 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
    17088.0 17088.0  0.0    0.0   137152.0  8229.3   342720.0     0.0      0.0    0.0    0.0    0.0        0    0.000   0      0.000   0      0.000    0.000
    $
    $ jcmd 20651 GC.run
    20651:
    Command executed successfully
    $ ~/OpenJDK/jdk-hs/build/linux-x86_64-normal-server-fastdebug/images/jdk/bin/jstat -gc 20651 1000 1
     S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
    17088.0 17088.0  0.0   544.2  137152.0   0.0     342720.0     0.0     4864.0 3830.0 512.0  325.9       1    0.005   0      0.000   2      0.014    0.019
Comments
Moving to approved. If this change has more than expected compatibility impact, please add a release note to the main issue.
15-02-2018
I added examples for jstat.
13-02-2018
Moving to Provisional. Before the request is finalized for the second phase of consideration, please have one or more gc engineers review the CSR. Also, please include in the text of the CSR or an attachment an example of the change. The link to an external webrev is informative, but not sufficient for normative text of the CSR.
13-02-2018