RFR(s): 8073476: G1 logging ignores changes to PrintGC* flags via MXBeans
Dmitry Fazunenko
dmitry.fazunenko at oracle.com
Tue Apr 28 14:19:03 UTC 2015
Hi Bengt and Jesper,
thank you very much for review, I appreciate your time spent.
I think the current version is good enough to be integrated.
-- Dima
On 28.04.2015 11:31, Bengt Rutisson wrote:
> On 27/04/15 18:24, Jesper Wilhelmsson wrote:
>> Bengt Rutisson skrev den 27/4/15 17:55:
>>>
>>> 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
>>
>> Why is this a valid command line? Shouldn't we require correct values
>> for all flags and exit with an error message if options get weird
>> values?
>
> I agree, but as I wrote to Dima, I don't think this is worth fixing now.
>
> Bengt
>
>> /Jesper
>>
>>
>>>
>>> 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
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>
More information about the hotspot-gc-dev
mailing list