RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Max Ockner
max.ockner at oracle.com
Thu Apr 14 16:22:10 UTC 2016
new webrev:
http://cr.openjdk.java.net/~mockner/8151526.05/
- 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