RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Marcus Larsson
marcus.larsson at oracle.com
Fri Apr 15 14:37:30 UTC 2016
Hi,
On 04/15/2016 04:29 PM, Coleen Phillimore wrote:
>
> Max,
>
> I got this confused when looking at this because of the names.
>
> *+ STEP(395, "(printing log configuration)")*
> *+ if (_verbose){*
> *+ st->print_cr("Logging:");*
> *+ LogConfiguration::describe_no_lock(st);*
> *+ LogConfiguration::describe_with_lock(st);*
> *+ st->cr();*
> *+ }*
> *+ *
>
> I was thinking "wait, you don't want the lock here!"
>
> I think describe_no_lock() should be named
> describe_available_log_levels()
>
> describe_with_lock() should be names describe_log_configuration().
>
> describe() should call these with the lock for the latter.
In that case, can we make it describe_available() and
describe_outputs()? The first function doesn't only describe levels.
Thanks,
Marcus
>
> Thanks,
> Coleen
>
>
> On 4/15/16 3:54 AM, Marcus Larsson wrote:
>> Hi,
>>
>> On 04/14/2016 06:22 PM, Max Ockner wrote:
>>> new webrev:
>>> http://cr.openjdk.java.net/~mockner/8151526.05/
>>
>> logConfiguration.cpp:
>> unnecessary #include on line 39
>>
>> logConfiguration.hpp:
>> typo in comment, 'ad' -> 'and'
>>
>> I don't need to see a new webrev for this. Thanks for fixing!
>>
>> Marcus
>>
>>> - 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