RFR (M): 8027962: Per-phase timing measurements for strong roots processing

[Thomas Schatzl]

Hi all,

  can I have reviews for the following change that adds detailed logging
for the ext root scan phase of the g1 collector?

If you add -XX:+UnlockExperimentalOptions -XX:G1LogLevel=finest, the
"Ext Root Scan" phase is now split up into several sub-categories, e.g.
instead of 

[Parallel Time: ...]
  [GC Worker Start...
    Min: ... Avg: ... Max: ... ]
  [Ext root scan...
    Min: ... Avg: ... Max: ... ]
  [Update RS...
    Min: ... Avg: ... Max: ... ]

You get a detailed breakdown like this:

[Parallel Time: ...]
  [GC Worker Start...
    Min: ... Avg: ... Max: ... ]
  [Ext root scan...
    Min: ... Avg: ... Max: ... ]
    [Thread Roots: 
      Min: ... Avg: ... Max: ... ]
    [StringTable Roots:
      Min: ... Avg: ... Max: ... ]
    [same for Universe Roots, JNI Handles Roots, ObjectSynchronizer
Roots, FlatProfiler Roots, Management Roots, SystemDictionary Roots,
CLDG Roots, JVMTI Roots, CodeCache Roots, Filter SATB Roots, CM
RefProcessor Roots, Wait for Strong CLD]
    [Weak CLD Roots:
      Min: ... Avg: ... Max: ... ]
  [Update RS...
    Min: ... Avg: ... Max: ... ]

I intentionally only enabled this with -XX:G1LogLevel=finest because I
think typically this information would just increase the log file
without much additional information.

Unfortunately there is no log level between finer and finest that could
be used to show this information without the per-thread timing, which
would cut the number of lines in half at least.
There is the option of adding another global option (some diagnostic
option maybe?), but I do think its use is limited (i.e. only after you
notice that "Ext Root Scan" grows over time) so you do not want all
those lines of information using only G1LogLevel=finer/PrintGCDetails.

It would be trivial to change either way.

E.g. something like

[Parallel Time: ...]
  [GC Worker Start... Min: ... Avg: ... Max: ... ]
  [Ext root scan... Min: ... Avg: ... Max: ... ]
    [Thread Roots:...  Min: ... Avg: ... Max: ... ]
    [StringTable Roots:...  Min: ... Avg: ... Max: ... ]
    [same for Universe Roots, JNI Handles Roots, ObjectSynchronizer
Roots, FlatProfiler Roots, Management Roots, SystemDictionary Roots,
CLDG Roots, JVMTI Roots, CodeCache Roots, Filter SATB Roots, CM
RefProcessor Roots, Wait for Strong CLD]
    [Weak CLD Roots: Min: ... Avg: ... Max: ... ]
  [Update RS... Min: ... Avg: ... Max: ... ]

These messages help a lot in diagnosing the type of root leaks in root
processing.

JIRA:
https://bugs.openjdk.java.net/browse/JDK-8027962
Webrev:
http://cr.openjdk.java.net/~tschatzl/8027962/webrev/
Testing:
jprt, test case

Thanks,
  Thomas