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

Bengt Rutisson bengt.rutisson at oracle.com
Tue Apr 28 08:30:54 UTC 2015


Hi Dima,

On 27/04/15 18:32, Dmitry Fazunenko wrote:
> 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.

Agreed. But since G1LogLevel will be removed soon I don't think it is 
worth introducing stricter checking for that flag now.

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

I don't think it s very important. But if you want to be on the safe 
side I would suggest making the change to keep the old behavior. I'll 
leave it up to you to decide.

Thanks,
Bengt

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


More information about the hotspot-gc-dev mailing list