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

Mon Apr 20 08:34:19 UTC 2015

Hi Dima,

On 2015-04-17 15:51, Dmitry Fazunenko wrote:
> 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;
>     }
>
Oh, I missed that you had changed fine() to call level(). This means 
that all calls to G1Log interface has side effects. I don't like that at 
all.

>>
>> 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.

I think what you need to do is to extend the Flag class with an update() 
method and call the method in WriteableFlags::set_flag().

>
>> 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!

Yes, it is much cleaner.

>
>>
>>>
>>>>
>>>> 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?

I would be ok with it, but I'm pretty convinced unified logging will 
make it in to JDK9 so if you can wait for it that might be better.

Thanks,
Bengt

>
> 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/20150420/e20e82fd/attachment.htm>