RFR: 8151526: Print -Xlog configuration in the hs_err_pid file
Max Ockner
max.ockner at oracle.com
Mon Apr 18 15:24:15 UTC 2016
http://cr.openjdk.java.net/~mockner/8151526.06/
- Renamed describe_no_lock => describe_available
- Renamed describe_with_lock => describe_current_configuration
- Removed unnecessary import of vmError in logConfiguration.cpp
- Fixed typo in comment in logConfiguration.hpp
- hs_err file now only uses describe_current_configuration, which was
the original intent of this enhancement. VM info still uses describe().
Thanks,
Max
On 4/18/2016 9:43 AM, Marcus Larsson wrote:
>
>
> 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