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

Bengt Rutisson bengt.rutisson at oracle.com
Tue Apr 21 12:19:43 UTC 2015


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.


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?


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.

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.

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


More information about the hotspot-gc-dev mailing list