RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Max Ockner
max.ockner at oracle.com
Tue Apr 12 15:01:35 UTC 2016
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.
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