RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Marcus Larsson
marcus.larsson at oracle.com
Tue Apr 12 17:30:03 UTC 2016
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