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

Dmitry Fazunenko dmitry.fazunenko at oracle.com
Mon Apr 27 13:32:42 UTC 2015


Hi Bengt,

Updated variant of fix with all your comments addressed:

http://cr.openjdk.java.net/~dfazunen/8073476/webrev.08/

Thanks,
Dima


On 21.04.2015 16:18, Dmitry Fazunenko wrote:
> Bengt,
>
> Thanks for your time!
> A have a question inline:
>
> On 21.04.2015 15:19, Bengt Rutisson wrote:
>>
>> Hi Dima,
>>
>> On 2015-04-21 13:33, Dmitry Fazunenko wrote:
>>> 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!
>>
>> Thanks for making these change. Looks much better to me.
>>
>> A couple of comments:
>>
>> G1CollectedHeap::do_collection() is only used for full GCs. You 
>> probably want to add a call to G1Log::update_level() in 
>> G1CollectedHeap::do_collection_pause_at_safepoint() too to make sure 
>> that it is called for young GCs as well.
>
> agree. good catch!
>
>>
>>
>> I think it looks odd that G1Log::init() and G1Log::update_level() use 
>> different guards for when to take PrintGC and PrintGCDetails into 
>> account.
>>
>>   51 void G1Log::init() {
>>   52   if (G1LogLevel != NULL && G1LogLevel[0] != '\0')
>>
>>   37 void G1Log::update_level() {
>>   38   if (FLAG_IS_DEFAULT(G1LogLevel)) {
>>
>> Is there a difference between (G1LogLevel != NULL && G1LogLevel[0] != 
>> '\0') and (FLAG_IS_DEFAULT(G1LogLevel)) ? Can we use the same guard 
>> in both places?
>
> I though about using the same expression in both cases. The difference 
> in handling the empty value:  -XX:G1LogLevel=
> So, the question,  how this case should be handled:
> - a warning to be printed out and level set to 'none'
> - treated in the same way as 'none'
>
>
>>
>>
>> g1Log.hpp:
>>
>> I don't think this comment helps much:
>>
>> +  // to be invoked on VM start
>>    static void init();
>>
>> The name init() makes it pretty clear to me what the method is 
>> expected to do. I would just leave the comment out.
> I have a bit different vision, but I'm okay to remove the comment
>
>
>>
>> The comment for update_level() talks about where the method should be 
>> called instead of what it does. That is normally not such a good 
>> thing for comments. Better to explain what it does so it can be 
>> called in all places where it is needed in the future.
>>
>> So instead of:
>>
>> +  // to be invoked on GC start or flag values change
>> +  static void update_level();
>>
>> I would prefer:
>>
>> //  Update the log level to reflect runtime changes to manageable flags.
> agree.
>
> Thanks,
> Dima
>
>
>>
>> Thanks,
>> Bengt
>>
>>>
>>> -- 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/20150427/6efaa202/attachment.html>


More information about the hotspot-gc-dev mailing list