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

[Dmitry Fazunenko]

Bengt,

Please find comments inline.

On 17.04.2015 9:43, Bengt Rutisson wrote:
>
> Hi Dima,
>
> On 2015-04-16 15:36, Dmitry Fazunenko wrote:
>> 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.
>
> I understand that, but what I was saying with the example above is 
> that you will not get the desired effect if you change PrintGC or 
> PrintGCDetails at runtime. If they are disabled, and then turn them on 
> at runtime you will not enter the update code because of this check at 
> the start of the log_gc_footer() method:
>
>   if (!G1Log::fine()) {
>     return;
>   }
>
>
> Similarly turning them off at runtime will start to have an effect in 
> the middle of a GC. Which is probably not the effect you are looking for.
fine() invokes level(), level() invokes update(), so G1::fine() will 
return the up to date value:

    inline static bool fine() {
-    return _level >= LevelFine;
+    return level() >= LevelFine;
    }


    static LogLevel level() {
+    // PringGC and PrintGCDetails are dynamic flags
+    // _level should be in sync with the latest values
+    update_level();
      return _level;
    }


>
> This is why making the level() getter having the side effect of 
> changing the log level is a bad idea. You have no control over when 
> that happens.

It must be up to those who change flags at runtime.
But the following code should work:

MXBean.set(PrintGC, false);
System.gc();
MXBean.set(PrintGC, true);

>
>>
>> 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 think they can be manageble but their changed states need to be 
> handled more explicitly.
>
>>
>>
>>>
>>>
>>> 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.
>
> The sync is done very frequently. Actually way too often in my view.
>
> I would prefer that you investigate the hook in the MXBean change so 
> we know how much work that would be. 

It was my first intention, but I haven't found a way how to implement it.

> If that is not possible I think a better solution is to call 
> G1Log::update_level() *once* at the start of a GC. That way the log 
> level is always consistent throughout the GC.

Yes, this is a good idea!

>
>>
>>>
>>> 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.
>
> Can you explain more why this is important to fix right now? Unified 
> logging is targeted for JDK 9.

What I heard about unified logging is that there is no guarantee that it 
will happen in JDK9 time frame.
I need the feature now to develop tests based on analysis of logs: I 
want to start logging not from begging, but after some steps.

Will you be okay if G1Log::update_level() is invoked once per GC?

Thanks,
Dima

>
> Thanks,
> Bengt
>
>>
>> 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/20150417/ecd79460/attachment.htm>