Request for review (M): 7178363 G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code

[Vitaly Davidovich]

Bengt,

Sorry, one follow-up after looking at the code again.  In the guard case,
if the VerifyXXX isn't set, then the value will always be 0.0, even in
prior GCs.  Are you saying these flags can be changed dynamically, perhaps
by some management API? If not, then these methods will always produce and
store 0, which seems a bit wasteful.  Did I miss something?

Sent from my phone
On Aug 22, 2012 9:50 AM, "Vitaly Davidovich" <vitalyd at gmail.com> wrote:

> Thanks for the explanation Bengt - all good to me.
>
> Sent from my phone
> On Aug 22, 2012 9:39 AM, "Bengt Rutisson" <bengt.rutisson at oracle.com>
> wrote:
>
>>
>> Hi Vitaly,
>>
>> Thanks for looking at this change too!
>>
>> On 2012-08-22 14:22, Vitaly Davidovich wrote:
>>
>> Hi Bengt,
>>
>> A few minor comments.
>>
>> In g1CollectedHeap.cpp:
>>
>> 1) probably doesn't matter much in its current form, but would it be
>> better to call os::elapsedTime() right before prepare_verify() so that the
>> timing info captures just the verification time and not printing to
>> tty/gclog and constructing the HandleMark? This is in verify().
>>
>>
>> Actually, I think it is good that the extra printing is included in the
>> timing. We want to time the extra cost of turning on the verification, thus
>> we should include the full cost of it.
>>
>>  2) it seems a bit weird to have the "guard" parameter in the verify()
>> method.  Why wouldn't caller just check the guard and then only call if it
>> passes? Not a big deal though, just stylistic.
>>
>>
>> I see your point. As you say, it is just a style question. If I remove
>> the guard parameter to verify() I'd have to add the test to
>> verify_before_gc() and verify_after_gc() and that kind of re-introduces
>> some of the code duplication that I was aiming to remove. If you feel
>> strongly about it I'll change.
>>
>>  3) in verify_before/after(), would it make sense to only record the
>> time if it's not 0.0? I'm thinking that the pointer chasing may possible
>> get a cache miss only to record a 0.  Again, pure speculation.
>>
>>
>> These values are set for each GC. If we don't set them to 0 somewhere we
>> will get the values from the last GC. By always setting the value there is
>> no risk that we get the wrong values.
>>
>>  4) is os::elapsedTime() using a monotonic time source? If not, what
>> would happen if you get a negative value in the timing?
>>
>>
>> os::elapsedTime() is a monotonic time source.
>>
>> Thanks,
>> Bengt
>>
>>  Looks good otherwise.
>>
>> Thanks
>>
>> Sent from my phone
>> On Aug 22, 2012 7:21 AM, "Bengt Rutisson" <bengt.rutisson at oracle.com>
>> wrote:
>>
>>>
>>> Hi again,
>>>
>>> Here is an updated webrev based on comments from John Cuthbertson:
>>> http://cr.openjdk.java.net/~brutisso/7178363/webrev.02/
>>>
>>> Here is a diff compared to the previous webrev:
>>> http://cr.openjdk.java.net/~brutisso/7178363/webrev.01-02-diff/
>>>
>>> Thanks,
>>> Bengt
>>>
>>> On 2012-07-20 14:17, Bengt Rutisson wrote:
>>>
>>>>
>>>> Hi all,
>>>>
>>>> Here is an updated webrev for this change:
>>>> http://cr.openjdk.java.net/~brutisso/7178363/webrev.01/
>>>>
>>>> It turns out the the earlier change for 7178361 had introduced two more
>>>> issues: the heap transition information for the PrintGC output and the
>>>> output for evacuation failures had both been moved in an unintended way.
>>>> The above webrev corrects both of these chagne too. Thanks John Cuthbertson
>>>> for pointing me to the evacuation failure output.
>>>>
>>>> Bengt
>>>>
>>>>
>>>> On 2012-07-19 11:01, Bengt Rutisson wrote:
>>>>
>>>>>
>>>>> 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 --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20120822/0a2a8295/attachment.htm>