RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Coleen Phillimore
coleen.phillimore at oracle.com
Mon Apr 18 13:33:35 UTC 2016
On 4/15/16 10:37 AM, Marcus Larsson wrote:
> Hi,
>
> On 04/15/2016 04:29 PM, Coleen Phillimore wrote:
>>
>> Max,
>>
>> I got this confused when looking at this because of the names.
>>
>> *+ STEP(395, "(printing log configuration)")*
>> *+ if (_verbose){*
>> *+ st->print_cr("Logging:");*
>> *+ LogConfiguration::describe_no_lock(st);*
>> *+ LogConfiguration::describe_with_lock(st);*
>> *+ st->cr();*
>> *+ }*
>> *+ *
>>
>> I was thinking "wait, you don't want the lock here!"
>>
>> I think describe_no_lock() should be named
>> describe_available_log_levels()
>>
>> describe_with_lock() should be names describe_log_configuration().
>>
>> describe() should call these with the lock for the latter.
>
> In that case, can we make it describe_available() and
> describe_outputs()? The first function doesn't only describe levels.
describe_available() seems better. It seems that describe_outputs()
isn't descriptive, why not describe_[current]_configuration().
Thanks,
Coleen
>
> Thanks,
> Marcus
>
>>
>> Thanks,
>> Coleen
>>
>>
>> On 4/15/16 3:54 AM, Marcus Larsson wrote:
>>> Hi,
>>>
>>> On 04/14/2016 06:22 PM, Max Ockner wrote:
>>>> new webrev:
>>>> http://cr.openjdk.java.net/~mockner/8151526.05/
>>>
>>> logConfiguration.cpp:
>>> unnecessary #include on line 39
>>>
>>> logConfiguration.hpp:
>>> typo in comment, 'ad' -> 'and'
>>>
>>> I don't need to see a new webrev for this. Thanks for fixing!
>>>
>>> Marcus
>>>
>>>> - new describe_* methods are now private
>>>> - VMError is now a friend class in logConfiguration.
>>>>
>>>> Thanks,
>>>> Max
>>>>
>>>> On 4/14/2016 4:30 AM, Marcus Larsson wrote:
>>>>> Hi,
>>>>>
>>>>> On 04/13/2016 09:33 PM, Max Ockner wrote:
>>>>>> Hello,
>>>>>> I have made these changes.
>>>>>> - refactored describe into a portion which uses locking and one
>>>>>> that does not.
>>>>>> - in the print_vm_info function in vmError.cpp, describe() is
>>>>>> used, since this function is called while the program is running.
>>>>>> - in the report function, the describe_no_lock and
>>>>>> describe_with_lock functions are both used without taking a lock.
>>>>>> If it doesnt crash, then fantastic. If it does crash, the error
>>>>>> handler will skip this step anyway.
>>>>>>
>>>>>> webrev: http://cr.openjdk.java.net/~mockner/8151526.04
>>>>>
>>>>> I suggest making the new two functions private in
>>>>> LogConfiguration, and friending VMError, instead of keeping them
>>>>> public. That should reduce confusion about which describe-method
>>>>> to use, and prevent misuse of the describe_with_lock in other places.
>>>>>
>>>>> Otherwise this looks good.
>>>>>
>>>>> Thanks,
>>>>> Marcus
>>>>>
>>>>>>
>>>>>> Thanks,
>>>>>> Max
>>>>>>
>>>>>> On 4/12/2016 1:30 PM, Marcus Larsson wrote:
>>>>>>> Hey,
>>>>>>>
>>>>>>> On 2016-04-12 17:01, Max Ockner wrote:
>>>>>>>> Marcus,
>>>>>>>>
>>>>>>>> I just spoke with Coleen about this. If I attempt to print
>>>>>>>> configuration during a crash without lock and it crashes, the
>>>>>>>> error handler will eat it up and start at the next step. It
>>>>>>>> would be fun to write a locking mechanism, but this seems
>>>>>>>> better to me.
>>>>>>>>
>>>>>>>> I will continue to call describe() from VM.info, but I will
>>>>>>>> refactor the code in describe so that all of the information
>>>>>>>> can be printed easily without taking a lock. For a crash, I'll
>>>>>>>> use the refactored print functions to print all the necessary
>>>>>>>> information without taking a lock. Even if the vm crashes
>>>>>>>> during this step it is not such a bad thing because of the
>>>>>>>> robust error handler.
>>>>>>>
>>>>>>> Alright, that sounds good!
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Marcus
>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> Thanks,
>>>>>>>> Max
>>>>>>>>
>>>>>>>> On 4/12/2016 8:46 AM, Marcus Larsson wrote:
>>>>>>>>> Hi Max,
>>>>>>>>>
>>>>>>>>> On 04/11/2016 07:36 PM, Max Ockner wrote:
>>>>>>>>>> Hello again,
>>>>>>>>>>
>>>>>>>>>> I have looked into this and I see a possible workaround to
>>>>>>>>>> the issue raised by Marcus:
>>>>>>>>>>
>>>>>>>>>> LogConfiguration::describe() takes the ConfigurationLock,
>>>>>>>>>> which
>>>>>>>>>> might be problematic for the error handler. I suppose the
>>>>>>>>>> error
>>>>>>>>>> handler could potentially deadlock if its thread already
>>>>>>>>>> holds
>>>>>>>>>> the lock. Unsure how to resolve this, because skipping to
>>>>>>>>>> take
>>>>>>>>>> the lock means that we might crash due to another thread
>>>>>>>>>> changing the configuration as we read it.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> My proposed solution is this:
>>>>>>>>>>
>>>>>>>>>> If the ConfigurationLock is held by another thread during the
>>>>>>>>>> crash, then I think we could print "Log configuration can not
>>>>>>>>>> be accessed because ConfigurationLock is currently held by
>>>>>>>>>> another thread" or something similar. If the
>>>>>>>>>> ConfigurationLock can be taken by the current thread, then
>>>>>>>>>> print the configuration.
>>>>>>>>>>
>>>>>>>>>> We can accomplish this as follows:
>>>>>>>>>>
>>>>>>>>>> In *logConfiguration.cpp*: Create a ConfigurationLockMaybe
>>>>>>>>>> class extending ConfigurationLock.
>>>>>>>>>>
>>>>>>>>>> class ConfigurationLockMaybe : ConfigurationLock {
>>>>>>>>>> private:
>>>>>>>>>> bool _success;
>>>>>>>>>> public:
>>>>>>>>>> ConfigurationLockMaybe() {
>>>>>>>>>> if (_semaphore.trywait()){_success = true;}
>>>>>>>>>> }
>>>>>>>>>> ~ConfigurationLock() {
>>>>>>>>>> if(_success){_semaphore.signal();}
>>>>>>>>>> }
>>>>>>>>>> bool has_lock(){return _success;}
>>>>>>>>>> };
>>>>>>>>>>
>>>>>>>>>> _semaphore is a static var in ConfigurationLock, so the same
>>>>>>>>>> copy is accessed in child classes.
>>>>>>>>>>
>>>>>>>>>> Another method
>>>>>>>>>> LogConfiguration::describe_on_crash(outputStream* out) can
>>>>>>>>>> use ConfigurationLockMaybe to attempt to print the
>>>>>>>>>> configuration.
>>>>>>>>>>
>>>>>>>>>> In *vmError.cpp*: Replace LogConfiguration::describe with
>>>>>>>>>> LogConfiguration::describe_on_crash.
>>>>>>>>>
>>>>>>>>> Sounds good to me.
>>>>>>>>>
>>>>>>>>> ConfigurationLockMaybe sounds a bit weird but I don't have a
>>>>>>>>> better suggestion.
>>>>>>>>>
>>>>>>>>> Thanks,
>>>>>>>>> Marcus
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Max
>>>>>>>>>>
>>>>>>>>>> On 4/11/2016 10:23 AM, Max Ockner wrote:
>>>>>>>>>>> I missed this before. I'm going to investigate.
>>>>>>>>>>> Max
>>>>>>>>>>>
>>>>>>>>>>> On 4/11/2016 4:19 AM, Marcus Larsson wrote:
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On 04/11/2016 09:00 AM, Thomas Stüfe wrote:
>>>>>>>>>>>>> Hi Max,
>>>>>>>>>>>>>
>>>>>>>>>>>>> On Fri, Apr 8, 2016 at 9:56 PM, Max Ockner
>>>>>>>>>>>>> <max.ockner at oracle.com <mailto:max.ockner at oracle.com>> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>> I forgot to respond to this:
>>>>>>>>>>>>> On 4/1/2016 4:45 AM, Marcus Larsson wrote:
>>>>>>>>>>>>>> Hi,
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On 03/31/2016 08:08 PM, Max Ockner wrote:
>>>>>>>>>>>>>>> (Replies in line)
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On 3/30/2016 9:31 AM, Thomas Stüfe wrote:
>>>>>>>>>>>>>>>> Hi Max,
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Disclaimer: not a (R)eviewer.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Do we really need a list of all tags and all
>>>>>>>>>>>>>>>> decorators?
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Just going by what we currently put in the hs_err
>>>>>>>>>>>>>>> file, I think
>>>>>>>>>>>>>>> this may be the first "Do we really need" we've ever
>>>>>>>>>>>>>>> asked for
>>>>>>>>>>>>>>> this type of change.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> All joking aside, I think it is a good idea to
>>>>>>>>>>>>>>> direct users
>>>>>>>>>>>>>>> toward proper UL usage whenever we have a chance.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Also: I assume what you print is the Log state as
>>>>>>>>>>>>>>>> it is at the
>>>>>>>>>>>>>>>> time the hs-err file is printed. If logging was
>>>>>>>>>>>>>>>> enabled/changed during lifetime of the VM, e.g.
>>>>>>>>>>>>>>>> with jcmd,
>>>>>>>>>>>>>>>> would it be possible to see that? At least a
>>>>>>>>>>>>>>>> warning if
>>>>>>>>>>>>>>>> logging was not enabled from the start on.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Would it be possible? Yes, but I think this would
>>>>>>>>>>>>>>> require a
>>>>>>>>>>>>>>> framework change. It does not look like any marks
>>>>>>>>>>>>>>> are made when
>>>>>>>>>>>>>>> the LogConfiguration changes during runtime, and we
>>>>>>>>>>>>>>> would need
>>>>>>>>>>>>>>> to record that in order to know what to print when
>>>>>>>>>>>>>>> we dump into
>>>>>>>>>>>>>>> hs_err.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Yes, this would required the framework to keep some
>>>>>>>>>>>>>> sort of log
>>>>>>>>>>>>>> of configuration changes. Is there value in knowing
>>>>>>>>>>>>>> that the log
>>>>>>>>>>>>>> configuration changed since startup?
>>>>>>>>>>>>>
>>>>>>>>>>>>> I think it is useful along with other information. An
>>>>>>>>>>>>> example case:
>>>>>>>>>>>>>
>>>>>>>>>>>>> Let's say we are logging a message whenever a lock is
>>>>>>>>>>>>> acquired or
>>>>>>>>>>>>> released. In a subsystem like this, the action which
>>>>>>>>>>>>> dooms the vm
>>>>>>>>>>>>> may not cause an immediate crash. This leaves time for
>>>>>>>>>>>>> logging to
>>>>>>>>>>>>> turn on or off in between the bad action and the
>>>>>>>>>>>>> crash. If you
>>>>>>>>>>>>> don't know when logging was active and when it was
>>>>>>>>>>>>> not, then the
>>>>>>>>>>>>> absence of a particular message does not give you much
>>>>>>>>>>>>> information. You may not see the message that has the
>>>>>>>>>>>>> answer for
>>>>>>>>>>>>> you because it was not logged, though the action may
>>>>>>>>>>>>> have occurred.
>>>>>>>>>>>>>
>>>>>>>>>>>>> However, if we don't have the framework support for
>>>>>>>>>>>>> this then I
>>>>>>>>>>>>> believe it should be added later.
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> This is a good example. A small easy solution, as I
>>>>>>>>>>>>> mentioned before, could be just to distinguish between
>>>>>>>>>>>>> "logging parameters stable since startup" and "logging
>>>>>>>>>>>>> parameters changed at some time". That way you would at
>>>>>>>>>>>>> least know whether to trust the logging output.
>>>>>>>>>>>>>
>>>>>>>>>>>>> But you are right, this can be added later.
>>>>>>>>>>>>
>>>>>>>>>>>> I've filed https://bugs.openjdk.java.net/browse/JDK-8153945
>>>>>>>>>>>> for this.
>>>>>>>>>>>>
>>>>>>>>>>>> Max: Did you see my comments about the ConfigurationLock?
>>>>>>>>>>>> It was an inline reply to your first mail.
>>>>>>>>>>>>
>>>>>>>>>>>> Thanks,
>>>>>>>>>>>> Marcus
>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> Kind Regards, Thomas
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>>>> Max
>>>>>>>>>>>>>>>> Kind Regards, Thomas
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On Tue, Mar 29, 2016 at 9:00 PM, Max Ockner
>>>>>>>>>>>>>>>> <max.ockner at oracle.com
>>>>>>>>>>>>>>>> <mailto:max.ockner at oracle.com>> wrote:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Hello,
>>>>>>>>>>>>>>>> Please review another Unified Logging change.
>>>>>>>>>>>>>>>> They are
>>>>>>>>>>>>>>>> almost done, and we are serious this time.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> bug:
>>>>>>>>>>>>>>>> https://bugs.openjdk.java.net/browse/JDK-8151526
>>>>>>>>>>>>>>>> webrev:
>>>>>>>>>>>>>>>> http://cr.openjdk.java.net/~mockner/8151526.01/
>>>>>>>>>>>>>>>> <http://cr.openjdk.java.net/%7Emockner/8151526.01/>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> LogConfiguration::describe() takes the
>>>>>>>>>>>>>> ConfigurationLock, which
>>>>>>>>>>>>>> might be problematic for the error handler. I suppose
>>>>>>>>>>>>>> the error
>>>>>>>>>>>>>> handler could potentially deadlock if its thread
>>>>>>>>>>>>>> already holds
>>>>>>>>>>>>>> the lock. Unsure how to resolve this, because
>>>>>>>>>>>>>> skipping to take
>>>>>>>>>>>>>> the lock means that we might crash due to another thread
>>>>>>>>>>>>>> changing the configuration as we read it.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>>> Marcus
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> The logging configuration is now printed in
>>>>>>>>>>>>>>>> each hs_err
>>>>>>>>>>>>>>>> file. The output is the same as you would see from
>>>>>>>>>>>>>>>> -Xlog:logging=trace and it is obtained from
>>>>>>>>>>>>>>>> LogConfiguration::describe().
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Below is a sample of the hs_err contents. The
>>>>>>>>>>>>>>>> Logging info
>>>>>>>>>>>>>>>> is printed after VM Arguments and Whitebox, and
>>>>>>>>>>>>>>>> before
>>>>>>>>>>>>>>>> Environment Variables.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> VM Arguments:
>>>>>>>>>>>>>>>> java_command: Kaboom
>>>>>>>>>>>>>>>> java_class_path (initial): .
>>>>>>>>>>>>>>>> Launcher Type: SUN_STANDARD
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Logging:
>>>>>>>>>>>>>>>> Available log levels: off, trace, debug, info,
>>>>>>>>>>>>>>>> warning, error
>>>>>>>>>>>>>>>> Available log decorators: time (t), uptime (u),
>>>>>>>>>>>>>>>> timemillis
>>>>>>>>>>>>>>>> (tm), uptimemillis (um), timenanos (tn),
>>>>>>>>>>>>>>>> uptimenanos (un),
>>>>>>>>>>>>>>>> hostname (hn), pid (p), tid (ti), level (l),
>>>>>>>>>>>>>>>> tags (tg)
>>>>>>>>>>>>>>>> Available log tags: alloc, age, barrier,
>>>>>>>>>>>>>>>> biasedlocking,
>>>>>>>>>>>>>>>> bot, census, classhisto, classresolve, classinit,
>>>>>>>>>>>>>>>> classload, classloaderdata, classunload,
>>>>>>>>>>>>>>>> classpath,
>>>>>>>>>>>>>>>> compaction, cpu, cset, defaultmethods, ergo,
>>>>>>>>>>>>>>>> exceptions,
>>>>>>>>>>>>>>>> exit, freelist, gc, heap, humongous, ihop,
>>>>>>>>>>>>>>>> itables, jni,
>>>>>>>>>>>>>>>> liveness, logging, marking, metaspace, modules,
>>>>>>>>>>>>>>>> monitorinflation, os, phases, plab, promotion,
>>>>>>>>>>>>>>>> preorder,
>>>>>>>>>>>>>>>> protectiondomain, ref, refine, region, remset,
>>>>>>>>>>>>>>>> safepoint,
>>>>>>>>>>>>>>>> safepointcleanup, scavenge, scrub, stacktrace,
>>>>>>>>>>>>>>>> start,
>>>>>>>>>>>>>>>> startuptime, state, stats, stringdedup,
>>>>>>>>>>>>>>>> stringtable,
>>>>>>>>>>>>>>>> survivor, sweep, task, thread, tlab, time,
>>>>>>>>>>>>>>>> verboseverification, verify, vmoperation, vtables
>>>>>>>>>>>>>>>> Log output configuration:
>>>>>>>>>>>>>>>> #0: stdout all=off uptime,level,tags,
>>>>>>>>>>>>>>>> #1: stderr all=warning uptime,level,tags,
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Environment Variables:
>>>>>>>>>>>>>>>> JAVA_HOME=/scratch/mockner/UL/8151526/build/linux-x86_64-normal-server-fastdebug/images/jdk
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> PATH=/home/mockner/tools/webrev:/bin:/usr/bin:/usr/local/bin:/usr/sbin:/home/mockner/bin:/home/mockner/linux/bin
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> SHELL=/bin/bash
>>>>>>>>>>>>>>>> OS=Linux
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>
More information about the hotspot-runtime-dev
mailing list