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

Dmitry Fazunenko dmitry.fazunenko at oracle.com
Tue Apr 21 11:33:43 UTC 2015


Hi Bengt,

This is modified fixed based on your comments:
http://cr.openjdk.java.net/~dfazunen/8073476/webrev.07/

Thanks for your assistance and good ideas!

-- Dima


On 20.04.2015 11:34, Bengt Rutisson wrote:
>
> 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: <http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20150421/fdfe8b46/attachment-0001.html>


More information about the hotspot-gc-dev mailing list