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

Dmitry Fazunenko dmitry.fazunenko at oracle.com
Tue Apr 21 13:18:17 UTC 2015


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/20150421/76d5050a/attachment.html>


More information about the hotspot-gc-dev mailing list