Reporting of gc+stats

[Roman Kennke]

Hello Justinas,

I apologize for the late reply.

> hope this is the right place to ask  a few more questions. Sorry if answers were simply overlooked.  

Sure, here is perfect. We usually don't take so long to reply. :-)

> 1. I can't find an option for periodic printing of pacer statistics.  (gc+stats prints just on exit?)
> Pacers activity looks like the first indication of gc pressure. Don't you think it would be useful to get this information from gc log asap?  
> Maybe you can introduce ShenandoahPacerStatsPeriod flag for periodic printing of _delays histogram?

That sounds like a good idea. We may actually want more more general
periodic statistics, not only about pacing. I filed the following bug
about it:

https://bugs.openjdk.java.net/browse/JDK-8239786

> 1. How to interpret breakdown of roots scanning? 
> e.g.: "Scan Roots" took 327s, but I can't figure out what part exactly from breakdown. What I am missing?

the individual parts 'S: *' are averages over all workers. That means if
one tasks (here: CLDG Roots) is not very well parallelized, it will
report a low average. Consider what will happen if it's perfectly
serial, and we have 4 workers, 1 worker needs 320ms, but the others are
basically idle or get almost no work. It will average to 80ms, but the
total (reported in "Scan Roots") will add-up to 320+ms. We realize this
is confusing and we should improve this.

Does that answer your question?

Thank you,
Roman


> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ] Pause Init Mark (N)         =   338.46 s (a =    51057 us) (n =  6629) (lvls, us =     4023,    45508,    50781,    56641,    88198)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Accumulate Stats          =     1.42 s (a =      214 us) (n =  6629) (lvls, us =       33,      182,      209,      236,     3329)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Make Parsable             =     6.10 s (a =      920 us) (n =  6629) (lvls, us =       55,      732,      891,     1074,     6075)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Clear Liveness            =     1.29 s (a =      195 us) (n =  6629) (lvls, us =       91,      168,      189,      211,     3251)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Scan Roots                =   327.02 s (a =    49332 us) (n =  6629) (lvls, us =     3613,    43945,    49023,    54688,    86252)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Thread Roots         =     6.68 s (a =     1008 us) (n =  6629) (lvls, us =      137,      869,      994,     1113,     9622)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Universe Roots       =     0.08 s (a =       12 us) (n =  6629) (lvls, us =        2,        8,        9,       13,     4443)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: JNI Roots            =     0.37 s (a =       55 us) (n =  6629) (lvls, us =        4,       37,       46,       59,     8601)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Synchronizer Roots   =     0.00 s (a =        1 us) (n =  6629) (lvls, us =        0,        0,        0,        1,       22)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: Management Roots     =     0.06 s (a =        8 us) (n =  6629) (lvls, us =        1,        3,        8,       11,      102)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: System Dict Roots    =     0.54 s (a =       81 us) (n =  6629) (lvls, us =       16,       61,       74,       89,     4439)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: CLDG Roots           =    80.66 s (a =    12167 us) (n =  6629) (lvls, us =      811,     9004,    11133,    14453,    27327)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]     S: JVMTI Roots          =     0.50 s (a =       75 us) (n =  6629) (lvls, us =        7,       48,       62,       79,    12281)
> [2020-01-21T07:33:24.757-0500][info ][gc,stats     ]   Resize TLABs              =     0.95 s (a =      143 us) (n =  6629) (lvls, us =        7,      104,      133,      172,     1513)
>