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

Bengt Rutisson bengt.rutisson at oracle.com
Mon Apr 27 15:55:17 UTC 2015


Hi Dima,

On 2015-04-27 15:32, Dmitry Fazunenko wrote:
> Hi Bengt,
>
> Updated variant of fix with all your comments addressed:
>
> http://cr.openjdk.java.net/~dfazunen/8073476/webrev.08/

Thanks! Looks much better.

One small detail. You have changed the behavior of this command line:

-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel="" -XX:+PrintGCDetails

Before your change this would result in the log level being "finer" due 
to the PrintGCDetails flag. But after your change we will get log level 
None.

It is not an interesting use case in my mind, but an easy fix would be 
to introduce a state variable in G1Log to track whether we should look 
at PrintGC* flags.

So, in G1Log::init() you could do something like:

   _log_level_flag_used = G1LogLevel != NULL && G1LogLevel[0] != '\0';
   if (_log_level_flag_used) {

   } else
     update_level();
   }


And update_level() would also look at the stat flag instead of checking 
FLAG_IS_DEFAULT(G1LogLevel). That way init() and update_level() would be 
consistent and we would keep the same behavior as before your change.

What do you think?

Thanks,
Bengt



>
> 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/f499f2f2/attachment-0001.html>


More information about the hotspot-gc-dev mailing list