Request for review (M): 7178363 G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
Bengt Rutisson
bengt.rutisson at oracle.com
Thu Jul 19 09:01:24 UTC 2012
Hi again,
Just in case anybody already started looking at this: I have updated the
webrev since I had to make some changes to make it compile with the NMT
fixes that have just made it into the hotspot-gc repository. Those
updates were just to make it compile and not really related to my
change, so I just overwrote the existing webrev. Just use the same link
as before:
http://cr.openjdk.java.net/~brutisso/7178363/webrev.00/
Also, if you want to see what the new output looks like I am attaching a
file called new.txt with an example from running SpecJBB2005 with this
command line:
-XX:+UseG1GC -XX:ParallelGCThreads=4 -XX:+UnlockExperimentalVMOptions
-XX:G1LogLevel=finest -XX:+TraceGen0Time -Xms256m -Xmx2G
I am also attaching a file called old.txt with what the output, using
the same command line, looked like before my change. As you can see the
differences are what I listed in my earlier email. You will also notice
that the "old" version has an entry for the SATB filtering, even though
all the entries are 0 (we didn't do a concurrent cycle so there has been
no SATB filtering). This was a bug I just introduced with my last change
(for 7178361), so the new example is more correct.
Thanks,
Bengt
On 2012-07-18 15:55, Bengt Rutisson wrote:
>
> Hi everyone,
>
> I would like some reviews of this change:
> http://cr.openjdk.java.net/~brutisso/7178363/webrev.00/
>
> This removes the special treatment for ParallelGCThreads=0 from the G1
> logging. I did keep the log output unchanged for that case. Basically
> it just has one indentation level less and skips some output. I am not
> sure this is really necessary since it is really a special case. I'm
> open to change that special treatment too and just have the same
> output as for ParallelGCThreads=1.
>
> The PrintGCDetails log output should be the same as before with three
> minor adjustments:
>
> - The "Sum" is now not printed for the start and end values for GC
> workers. This sum does not really make sense to me.
>
> - The "(ms)" unit was removed from output that aren't in milliseconds
> (termination attempts for example).
>
> - The average value is now printed as a double for all types.
>
> I tried to clean up the code a bit and introduced a separate class,
> Snippet WorkerDataArray, to keep track of the per thread logging. I
> also introduced getters and setters to avoid having to make
> G1CollectorPolicy and TraceGen0TimeData friend classes to G1GCPhaseTimes.
>
> Thanks,
> Bengt
-------------- next part --------------
[GC pause (G1 Evacuation Pause) (young), 0.0103623 secs]
[Parallel Time: 9.7 ms, GC Workers: 4]
[GC Worker Start (ms): 5762.8 5762.8 5762.8 5772.3
Min: 5762.8, Avg: 5765.1, Max: 5772.3, Diff: 9.5]
[Ext Root Scanning (ms): 1.4 1.2 1.2 0.0
Min: 0.0, Avg: 0.9, Max: 1.4, Diff: 1.4, Sum: 3.8]
[Update RS (ms): 1.5 1.7 1.3 0.0
Min: 0.0, Avg: 1.1, Max: 1.7, Diff: 1.7, Sum: 4.5]
[Processed Buffers: 5 4 4 0
Min: 0, Avg: 3.3, Max: 5, Diff: 5, Sum: 13]
[Scan RS (ms): 1.1 1.1 1.5 0.0
Min: 0.0, Avg: 0.9, Max: 1.5, Diff: 1.5, Sum: 3.8]
[Object Copy (ms): 5.5 5.5 5.5 0.0
Min: 0.0, Avg: 4.1, Max: 5.5, Diff: 5.5, Sum: 16.4]
[Termination (ms): 0.1 0.1 0.1 0.0
Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
[Termination Attempts: 1 1 1 1
Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): 9.6 9.6 9.6 0.0
Min: 0.0, Avg: 7.2, Max: 9.6, Diff: 9.6, Sum: 28.8]
[GC Worker End (ms): 5772.4 5772.4 5772.3 5772.3
Min: 5772.3, Avg: 5772.3, Max: 5772.4, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 87.0M(87.0M)->0.0B(142.0M) Survivors: 4096.0K->4096.0K Heap: 160.3M(256.0M)->73.3M(256.0M)]
[Times: user=0.00 sys=0.00, real=0.09 secs]
ALL PAUSES
Total = 0.20 s (avg = 28.04 ms)
(num = 7, std dev = 17.60 ms, max = 59.76 ms)
Young GC Pauses: 7
Mixed GC Pauses: 0
EVACUATION PAUSES
Evacuation Pauses = 0.20 s (avg = 28.04 ms)
(num = 7, std dev = 17.60 ms, max = 59.76 ms)
Root Region Scan Wait = 0.00 s (avg = 0.00 ms)
Parallel Time = 0.19 s (avg = 27.49 ms)
Ext Root Scanning = 0.01 s (avg = 1.37 ms)
SATB Filtering = 0.00 s (avg = 0.00 ms)
Update RS = 0.01 s (avg = 0.72 ms)
Scan RS = 0.02 s (avg = 2.49 ms)
Object Copy = 0.14 s (avg = 19.54 ms)
Termination = 0.01 s (avg = 1.56 ms)
Parallel Other = 0.01 s (avg = 1.81 ms)
Clear CT = 0.00 s (avg = 0.06 ms)
Other = 0.00 s (avg = 0.47 ms)
MISC
Stop World = 0.00 s (avg = 0.17 ms)
(num = 7, std dev = 0.03 ms, max = 0.22 ms)
Yields = 0.00 s (avg = 0.00 ms)
(num = 0, std dev = 0.00 ms, max = 0.00 ms)
-------------- next part --------------
[GC pause (G1 Evacuation Pause) (young), 0.0145999 secs]
[Parallel Time: 14.1 ms, GC Workers: 4]
[GC Worker Start (ms): 3371.2 3371.2 3371.2 3385.2
Min: 3371.2, Avg: 3374.7, Max: 3385.2, Diff: 14.0, Sum: 13498.7]
[Ext Root Scanning (ms): 1.2 1.1 1.5 0.0
Min: 0.0, Avg: 0.9, Max: 1.5, Diff: 1.4, Sum: 3.7]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 1.6 1.5 1.2 0.0
Min: 0.0, Avg: 1.1, Max: 1.6, Diff: 1.6, Sum: 4.3]
[Processed Buffers (ms): 4 5 3 0
Min: 0, Avg: 3, Max: 5, Diff: 5, Sum: 12]
[Scan RS (ms): 4.1 4.2 4.1 0.0
Min: 0.0, Avg: 3.1, Max: 4.2, Diff: 4.2, Sum: 12.4]
[Object Copy (ms): 7.1 7.2 7.2 0.0
Min: 0.0, Avg: 5.4, Max: 7.2, Diff: 7.2, Sum: 21.5]
[Termination (ms): 0.1 0.1 0.1 0.0
Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Termination Attempts (ms): 1 1 1 1
Min: 1, Avg: 1, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): 14.1 14.1 14.1 0.0
Min: 0.0, Avg: 10.6, Max: 14.1, Diff: 14.0, Sum: 42.3]
[GC Worker End (ms): 3385.2 3385.2 3385.2 3385.2
Min: 3385.2, Avg: 3385.2, Max: 3385.2, Diff: 0.0, Sum: 13540.9]
[Code Root Fixup: 0.0 ms]
[Clear CT: 0.0 ms]
[Other: 0.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 47.0M(47.0M)->0.0B(47.0M) Survivors: 4096.0K->4096.0K Heap: 119.9M(256.0M)->73.3M(256.0M)]
[Times: user=0.05 sys=0.00, real=0.09 secs]
ALL PAUSES
Total = 0.15 s (avg = 30.64 ms)
(num = 5, std dev = 9.29 ms, max = 39.83 ms)
Young GC Pauses: 5
Mixed GC Pauses: 0
EVACUATION PAUSES
Evacuation Pauses = 0.15 s (avg = 30.64 ms)
(num = 5, std dev = 9.29 ms, max = 39.83 ms)
Root Region Scan Wait = 0.00 s (avg = 0.00 ms)
Parallel Time = 0.15 s (avg = 30.06 ms)
Ext Root Scanning = 0.01 s (avg = 1.17 ms)
SATB Filtering = 0.00 s (avg = 0.00 ms)
Update RS = 0.00 s (avg = 0.54 ms)
Scan RS = 0.01 s (avg = 2.40 ms)
Object Copy = 0.12 s (avg = 23.42 ms)
Termination = 0.00 s (avg = 0.03 ms)
Parallel Other = 0.01 s (avg = 2.49 ms)
Clear CT = 0.00 s (avg = 0.06 ms)
Other = 0.00 s (avg = 0.50 ms)
MISC
Stop World = 0.00 s (avg = 0.19 ms)
(num = 5, std dev = 0.05 ms, max = 0.25 ms)
Yields = 0.00 s (avg = 0.00 ms)
(num = 0, std dev = 0.00 ms, max = 0.00 ms)
More information about the hotspot-gc-dev
mailing list