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

Dmitry Fazunenko dmitry.fazunenko at oracle.com
Mon Apr 27 16:32:18 UTC 2015


Hi Bengt,

Thanks for catching this.
I think, that giving -XX:G1LogLevel="" should cause the VM start error, 
because empty string is none of legal values.

If you want to treat -XX:G1LogLevel="" as if unset, I can fix as you said.
I think it's not very important, because you are going to rewrite this 
code soon.

Thanks,
Dima




On 27.04.2015 18:55, Bengt Rutisson wrote:
>
> 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/d9f5bccb/attachment-0001.html>


More information about the hotspot-gc-dev mailing list