RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Max Ockner
max.ockner at oracle.com
Wed Apr 13 19:33:08 UTC 2016
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
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