RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Marcus Larsson
marcus.larsson at oracle.com
Mon Apr 18 13:43:53 UTC 2016
On 04/18/2016 03:33 PM, Coleen Phillimore wrote:
>
>
> On 4/15/16 10:37 AM, Marcus Larsson wrote:
>> 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.
>
> describe_available() seems better. It seems that describe_outputs()
> isn't descriptive, why not describe_[current]_configuration().
I just figured we could skip the "configuration" part of it since we're
already in the scope of LogConfiguration::. I'm fine with
describe_[current]_configuration(), it's no big deal.
Thanks,
Marcus
>
> Thanks,
> Coleen
>>
>> 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