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

[Rachel Protacio]

On 9/10/2015 5:04 AM, Marcus Larsson wrote:
> Hi,
>
> On 2015-09-09 17:37, Rachel Protacio wrote:
>> Hi!
>>
>> For runtime logging, there are many locations where it is necessary 
>> to have a block led by a conditional checking whether the 
>> debug/info/trace logging is enabled with the appropriate tag. Would 
>> it be possible to add macros to logging/log.hpp such as
>>
>>    #define log_debug_is_enabled(...) log_is_enabled(Debug, __VA_ARGS__)
>>    #define log_trace_is_enabled(...) log_is_enabled(Trace, __VA_ARGS__)
>>
>> etc.? If they are added to your framework patch, that will help Max 
>> and me as we write our logging code.
>
> It could be done, but I think we should go either with the 
> log_is_enabled(level, tags) macro, or individual macros for each log 
> level like you suggest, and not both. My intention has been to 
> minimize the number of macros introduced with this patch to reduce the 
> risk for namespace issues. I can see that having the separate macros 
> helps readability a little, so if we're okay with the increased number 
> of macros this seems like a good idea to me.
>
> If we agree to go with separate macros I suggest we shorten the names 
> and use macros like log_is_debug(...), log_is_trace(...).
Oh, I see what you're saying. On second thought, I'm fine with using 
log_is_enabled(Level, tags) - I think it is equally clear. However, I 
would like to bring up one other point. In the block-code situations, it 
is currently necessary to write code that looks like

    if (log_is_enabled(Debug, <tags>)) {
         <code>
         log_debug(<tags>)("Logging statement to print");
    }

Which redundantly executes log_is_enabled() in the third line. Honestly, 
I'm okay with that. The issue is that in cases where it is necessary to 
pass the logging output stream to another function, the code ends up 
looking like

    if (log_is_enabled(Debug, <tags>)) {
         <code>
         ResourceMark rm;
         print_on(LogHandle(<tags>)::debug_stream());
    }

or even

    LogHandle(<tags>) log;
    if (log.is_debug()) {
         <code>
         ResourceMark rm;
         print_on(log.debug_stream());
    }

Is that correct? Neither seems ideal since they add extra clutter to the 
code and all these three examples are somewhat inconsistent with each 
other. Is there a cleaner way of doing this that is already in the code 
or that could be added?

>
>>
>> Additionally, the print format for the logging was not immediately 
>> intuitive. For example, as I'm working on the safepoint logging, I 
>> might have an output line like
>>
>>    [0.655s][debug  ][safepoint] Safepoint synchronization initiated. 
>> (20)
>>
>> Are the spaces after debug intended to line up the tags with each 
>> other (since the longest one is warning, it seems to fit)? If so, is 
>> that meant for readability? And what happens if the number of seconds 
>> goes into double digits - won't the alignment be off?
>>
>
> Yes, decorators are padded to avoid jagged logs and help readability. 
> Since the levels are known beforehand, a fixed padding is used for 
> that decorator. For other decorators such as tags or timestamps, the 
> padding will grow to the size of the longest (so far) seen decoration. 
> This means the decorator prefix length will either stay the same or 
> increase, but never decrease. After a while it should stabilize around 
> some fitting length and not grow significantly.
>
> For example:
> [0.655s][debug  ][safepoint] Safepoint synchronization initiated. (20)
> [0.656s][debug  ][safepoint, some_other_tag] Safepoint synchronization 
> initiated. (20)
> [0.657s][debug  ][safepoint,               ] Safepoint synchronization 
> initiated. (20)
> [10.657s][debug  ][safepoint,               ] Safepoint 
> synchronization initiated. (20) \
Ok, thanks for clarifying.
Rachel
>
>
> Thanks,
> Marcus
>
>>
>> Thanks,
>> Rachel
>>
>> On 9/7/2015 9:33 AM, 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
>>
>