RFR (L): 8046148: JEP 158 Unified JVM Logging

Wed Sep 16 22:18:32 UTC 2015

Hi Kirk,

I think Max answered that we had similar concern.  We'll have lots of 
logging tags for the runtime actions that need to be logged and maybe a 
sub-tag design would work better.  But given the current state of the 
runtime code (I can't speak for GC but you'll see how GC has been 
adapted to this framework soon), the levels do make sense for us also.

Take the case of PrintVtables - we have some code under PrintVtables and 
some other code under PrintVtables && Verbose.

Having the levels defined (there are only 3) allows us granularity to 
get this output or a more verbose output by command line.   We hate 
having to add Verbose and/or Wizard mode to get more logging 
information.  This unified logging approach makes more sense in this 
context.

For the most part, I see this logging as a step forward that cleans up 
the code that we have, but doesn't significantly change the 
functionality as we're adapting it.  We are planning on deprecating many 
(most?) of the nonproduct command line options, which helps with my 
concern with the proliferation of options that we have to spend time and 
support.

I think there will be ways to improve this and we can add RFE's for what 
we find.  Again, I think this is a step in the right direction for the 
product.  I realize that the GC log changes will cause you pain, and I'm 
not crazy about blanks in the log lines, but I think this will evolve to 
something that turns out very nice.

Thanks,
Coleen

On 9/16/15 5:51 PM, Kirk Pepperdine wrote:
> Hi Coleen,
>
> My initial concerns with the JEP and this concern remains is that logging levels should be removed from the specification and that they be replaced with tags that make sense to the work that you are doing. Instead of seeing you define the tags you’d like, we are witnessing a proliferation of logging levels.
>
> I do apologize on bring this point up but I believe this JEP could be improved to avoid some of the problems that I keep running into with the existing logging frameworks that this work seems to want to repeat.
>
> Kind regards,
> Kirk Pepperdine
>
>> On Sep 16, 2015, at 9:59 PM, Coleen Phillimore <coleen.phillimore at oracle.com> wrote:
>>
>> Hi Marcus,
>>
>> I had to have someone tell me how the templates work so that the log_is_enabled(Debug, etc) statements are efficient.  My initial concern was that it would be expensive to test for logging in place of some runtime Trace flags which evaluate to constant 'false' in product mode.
>>
>> If this still turns out to be a problem, we may ask for an RFE to add a flag_is_enabled(Develop, <tag>) or similar macro that evaluates to a constant false in product mode.  Also, I think it might be helpful to have more than one Develop level if we want certain logging flags to not be available in product mode, ie DevelopInfo, DevelopDebug and DevelopTrace.   But we can file RFEs for things we may need while doing the runtime logging.
>>
>> In http://cr.openjdk.java.net/~mlarsson/8046148/webrev.01/src/share/vm/logging/logTagSet.hpp.html
>>
>> Can you add to the comment at 103 that explains the magic that instantiates _tagset to be the static variable that holds the settings for each combination of tags found in the source code?  So that is_level is only a static test.
>>
>> And here:
>>
>> http://cr.openjdk.java.net/~mlarsson/8046148/webrev.01/src/share/vm/logging/logTagSet.cpp.html
>>
>> The constructor for LogTagSet is a static constructor that links all the static combinations of tags settings together so that they can be initialized with the values for the logging options on the command line.
>>
>> I don't need to see the comments.  I think this change is ready for integration.
>>
>> Thanks,
>> Coleen
>>
>> On 9/15/15 5:36 AM, Marcus Larsson wrote:
>>> Hi,
>>>
>>> Here is the updated version of the patch, including the feedback and suggestions from Coleen, David and Ioi.
>>>
>>> Incremental webrev:
>>> http://cr.openjdk.java.net/~mlarsson/8046148/webrev.00-01/
>>>
>>> Full webrev:
>>> http://cr.openjdk.java.net/~mlarsson/8046148/webrev.01/
>>>
>>> Changes include:
>>> * New NMT tag 'mtLogging' used by UL
>>> * Added storage allocation classes for all new classes
>>> * Added Log::puts<Level>(const char*) for plain string messages of any length
>>> * Fixed broken printf-attribute on Log::write functions
>>> * Moved VM startup timestamp to after os::init
>>> * Formatting and code style changes
>>>
>>> Thanks,
>>> Marcus
>>>
>>>
>>> On 2015-09-07 15:33, Marcus Larsson wrote:
>>>> Hi,
>>>>
>>>> Please review the following patch adding the unified logging framework to hotspot.
>>>>
>>>> JEP:
>>>> https://bugs.openjdk.java.net/browse/JDK-8046148
>>>>
>>>> Webrev:
>>>> http://cr.openjdk.java.net/~mlarsson/8046148/webrev.00/
>>>>
>>>> See the JEP description for a general overview of the new feature. Below are some notes on the implementation.
>>>>
>>>> The patch adds the new 'share/vm/logging' subdirectory containing the unified logging framework. The main entry point is log.hpp, which contains the necessary macros and definitions to use the framework.
>>>>
>>>> Log tags are defined/listed in logTag.hpp, and are passed as template arguments to the Log class. Every combination of tags used in a log call has a corresponding LogTagSet instance, which keeps a track of all the outputs it should write the log message to (and their levels). Having tags as template arguments allows mapping directly from a set of tags to the LogTagSet instance, which means that the overhead for disabled logging should be low. Currently each log message can be tagged with up to 5 tags, but this can be increased if ever required (and with C++11's variadic templates the limit can be removed completely).
>>>>
>>>> The LogConfiguration class keeps track of configured outputs (stdout, stderr, and possible file outputs). Configuration is done either by command line arguments (-Xlog) or by DCMD. Both methods will in turn use the LogConfiguration class to perform the parsing & configuration. This configuration includes iterating over all LogTagSet instances and updating them accordingly. The LogTagLevelExpression class is used to represent the selection of tags and levels for a given configuration request (the "what"-expression).
>>>>
>>>> The LogDecorators class contains a selection of decorators. Instances of this class is kept in LogTagSet to track what decorators to use (this is the union of all decorators used by its outputs). Each log call will create a LogDecorations instance (note: different classes), which will contain the actual decoration strings for the log message. These decorations are used for each output the tagset is set to log on, and are then discarded.
>>>>
>>>> The LogPrefix class allows messages of specific sets of tags to be prefixed. The prefix should supply a printf-style format with argument. (This allows GC logging to prefix messages of certain tagsets with GCId.) Prefixes are implemented using template specializations based on the specified tags, with the general/unspecialized case giving an empty prefix.
>>>>
>>>> The LogOutput class defines the interface for all types of log outputs. LogFileStreamOutput corresponds to FILE* stream based log outputs. LogFileOutput builds on this and adds the file management and log rotation support.
>>>>
>>>> A simple jtreg test is included in this patch. Additional tests will be added at a later stage.
>>>>
>>>> Thanks,
>>>> Marcus