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

[Bengt Rutisson]

Hi everyone,

When this was first sent out for review I suggested a couple of cleanup 
changes before doing this change. One of the cleanups has been pushed:

8074037: Refactor the G1GCPhaseTime logging to make it easier to add new 
phases
https://bugs.openjdk.java.net/browse/JDK-8074037

The other one is out for review and is close to being pushed:

8075210: Refactor strong root processing in order to allow G1 to evolve 
separately from GenCollectedHeap
https://bugs.openjdk.java.net/browse/JDK-8075210

Based on the above patches, here's an updated webrev to fix 8027962:

http://cr.openjdk.java.net/~brutisso/8027962/webrev.02

Could I have some reviews for this change?

A couple of things to note.

- The test TestGCLogMessages.java is the same test that Thomas had in 
his original patch. The test passes, so the logging output is the same 
as he suggested in his patch.

- The "Filter SATB Roots" filtering phase that Thomas suggested in his 
patch was actually already recorded as a separate phase called "SATB 
Filtering". The "SATB Filtering" was printed on the "finer" level and at 
indentation level 2. Given that we now log all sub phases to the 
external root scanning it makes more sense to have this logging at the 
"finest" log level and at indentation level 3. I've made that change in 
my patch. Also, the "SATB Filtering" was only logged if we were in a 
marking cycle. That kind of makes sense since there won't be any work to 
do in that phase otherwise. But it makes parsing of the log files easier 
if the phase is always printed. Now that we print it a the "finest" 
level I think it is ok to always print it.

Thanks,
Bengt

On 2015-02-17 10:02, Thomas Schatzl wrote:
> 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
>
>