RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Max Ockner
max.ockner at oracle.com
Mon Apr 11 17:36:55 UTC 2016
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.
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