Request for review (M): 7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause

[Bengt Rutisson]

Hi again,

Updated webrev:
http://cr.openjdk.java.net/~brutisso/7178361/webrev.01/

I added some asserts as suggested by Vitaly and I did some white space 
changes to the TraceGen0Time logging. I hope this will not break any 
parsers. It is just intended to align the output up a bit better to be 
more readable.

Here is a webrev with just the change I made compared to my previous webrev:
http://cr.openjdk.java.net/~brutisso/7178361/webrev.00-01-diff/

Here is an example of what the TraceGen0Time output looks like after my 
change:

ALL PAUSES
    Total                    =     0.95 s (avg =    63.44 ms)
                                          (num =    15, std dev =    
47.84 ms, max =   150.30 ms)


    Young GC Pauses:       14
    Mixed GC Pauses:        1

EVACUATION PAUSES
    Evacuation Pauses        =     0.95 s (avg =    63.44 ms)
                                          (num =    15, std dev =    
47.84 ms, max =   150.30 ms)
       Root Region Scan Wait =     0.00 s (avg =     0.00 ms)
       Parallel Time         =     0.94 s (avg =    62.39 ms)
          Ext Root Scanning  =     0.11 s (avg =     7.22 ms)
          SATB Filtering     =     0.00 s (avg =     0.00 ms)
          Update RS          =     0.04 s (avg =     2.81 ms)
          Scan RS            =     0.03 s (avg =     2.07 ms)
          Object Copy        =     0.75 s (avg =    49.75 ms)
          Termination        =     0.00 s (avg =     0.02 ms)
          Parallel Other     =     0.01 s (avg =     0.51 ms)
       Clear CT              =     0.00 s (avg =     0.09 ms)
       Other                 =     0.01 s (avg =     0.90 ms)

MISC
    Stop World               =     0.01 s (avg =     0.48 ms)
                                          (num =    15, std dev =     
0.19 ms, max =     0.79 ms)
    Yields                   =     0.00 s (avg =     0.27 ms)
                                          (num =     2, std dev =     
0.05 ms, max =     0.32 ms)

Thanks,
Bengt


On 2012-06-20 15:15, Bengt Rutisson wrote:
>
> Hi everyone,
>
> Could I please have some reviews for this change:
> http://cr.openjdk.java.net/~brutisso/7178361/webrev.00/
>
> Background
> As part of the PrintGC and PrintGCDetails logging there is information 
> about how long the GC pause was. The timing of the pause was done 
> differently in G1 depending on whether PrintGC or PrintGCDetails were 
> enabled. It turns out that PrintGCDetails was just timing part of the 
> pause.
>
> This change will make both PrintGC and PrintGCDetails use the same 
> timing. To achieve this I had to refactor the code a bit. I moved all 
> the timing data out of G1CollectorPolicy into a new class called 
> G1GCPhaseTimes.
>
> My intention is that this change should not alter the format of the 
> output of PrintGC or PrintGCDetails. It should just correct the timing 
> data.
>
> However, I did find that we are collecting timing information about 
> card counts, under an #ifdef. I moved this to the finest log level 
> instead. This does not change the existing format for normal usage of 
> PrintGC or PrintGCDetails.
>
> Also, I had to update how the TraceGen0Time data is logged. I will 
> have another look at this, but my idea was to leave the format exactly 
> as it was. However, I think the format has decayed over time so maybe 
> I'll try to clean it up.
>
> I intend to follow this change up with a change to remove the special 
> treatment of the single threaded case for PrintGCDetails (tracked in 
> CR 7178363).
>
> Finally, this work revealed an issue with how the ergonomics in G1 
> measure the collection pauses. I did not want to change this behavior 
> now so I filed a separate RFE for that (7178365: G1: Ergonomics only 
> count part of the collection pause).
>
> Bengt