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

[Bengt Rutisson]

Hi Thomas,

Thanks for splitting the root scanning logging up. This will be very useful.

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/

I think it would be good if we can make sure that the GC code does not 
leak in to runtime/timer. Not sure exactly how, but it would be good to 
try some change out to avoid this dependency.


TestGCLogMessages.java

I find it a little confusing that the instance variable messages has the 
same name as the parameter to the method checkMessagesAtLevel(). Could 
you change the name of one of them?

   47     LogMessageWithLevel messages[] = new LogMessageWithLevel[] {

   79     void checkMessagesAtLevel(OutputAnalyzer output, 
LogMessageWithLevel messages[], int level) throws Exception {

Also, what do you think about using an enum instead of using the integer 
values 2, 3 etc for levels?

Thanks,
Bengt

> Testing:
> jprt, test case
>
> Thanks,
>    Thomas
>
>