RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Marcus Larsson
marcus.larsson at oracle.com
Fri Apr 15 07:54:33 UTC 2016
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