RFR(s): 8073476: G1 logging ignores changes to PrintGC* flags via MXBeans

[Dmitry Fazunenko]

Hi Bengt,

thanks for looking.

On 16.04.2015 15:42, Bengt Rutisson wrote:
>
> Hello Dima,
>
> On 2015-04-16 13:40, Dmitry Fazunenko wrote:
>> Hello,
>>
>> Would you review a simple fix in G1.
>>
>> Short description:
>> after introduction G1Log - dynamic changes of PrintGC and 
>> PrintGCDetails flag has no effect anymore, because G1Log looks for 
>> these flags during initialization only. The fix: sync the log level 
>> with the flags values.
>>
>> A huge thanks to Jesper who helped me a lot with my first product fix.
>>
>> Bug: https://bugs.openjdk.java.net/browse/JDK-8073476
>> Webrev: http://cr.openjdk.java.net/~dfazunen/8073476/webrev.06/
>
> Sorry, but I don't really like the way this is solved. With this 
> approach calling G1GCPhaseTimes::print() suddenly has the side effect 
> that it resets the log level. That's quite unexpected for me. 
> Especially if you consider the code path in 
> G1CollectedHeap::log_gc_footer() where we do this:
>
> void G1CollectedHeap::log_gc_footer(double pause_time_sec) {
>   if (!G1Log::fine()) {
>     return;
>   }
>
>   if (G1Log::finer()) {
>     ...
>     g1_policy()->phase_times()->print(pause_time_sec);
>     ...
>   }
>
> If we don't have G1Log::fine() (which is PrintGC) enabled we will 
> never call the print() method and will thus not detect any changes 
> made by the MXBean. If we have G1Log::finer() enabled we enter the 
> logging code, print other things at the "finer" level (which is 
> PrintGCDetails) and then do the call to the print() method where we 
> can suddenly decide that PrintGCDetails no longer is enabled and not 
> do the rest of the logging. So for the same GC we will print some 
> stuff at PrintGCDetails level and some things at another level. Strange.

May it's not clear, but the change will have effect only if PrintGC or 
PrintGCDetails has been changed during execution.
Otherwise, the level will not change.

To me, it's strange, that when I disable PrintGC in G1 I still seeing gc 
log messages...
Or, I can't turn logging on during execution with G1.
This works well for other collectors.

Would it make sense to make PrintGC and PrintGCDetails unmanageable in 
case of g1?


>
>
> I would prefer to have a hook when the MXBean changes the value and 
> only update the level at that point.

Yes, it would be ideal solution. But I haven't found such a mechanism 
supported. And it's unlikely worth adding just for this case.
In my version, the sync will be done more frequently.

>
> Having said that I am not sure that this bug is worth fixing right 
> now. I am currently working on the JEP to make the GC logging use the 
> new unified logging format. That will change all of this and most 
> likely remove the G1Log class all together. So, my suggestion would be 
> to leave this as is for now and instead add the MXBean requirement to 
> the unified logging work.

Yes, I'm aware of unified logging and expect that G1Log class will go 
away someday.
But I would like to be able to disable logging in JDK9, to not see GC 
events occurred at the certain period of time.

Thanks,
Dima


>
> Thanks,
> Bengt
>>
>> Testing:
>> I ran manually the test from the bug report to make sure the change 
>> fixes the problem.
>> A regression test will be delivered separately as a fix of 
>> JDK-8077056 <https://bugs.openjdk.java.net/browse/JDK-8077056>
>>
>> Thanks,
>> Dima 
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20150416/1cb76461/attachment.htm>