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

[Marcus Larsson]

On 2015-09-10 17:53, Rachel Protacio wrote:
> 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?

Yes that's correct. I'm not sure how this could be simplified further, I 
think the clutter might be necessary. The last example is typically how 
I imagined more involved logging would work. The macros are a 
convenience for quick and simple logging. If you have an idea of how to 
improve the this I'm happy to consider it.

Thanks,
Marcus

>
>>
>>>
>>> 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
>>>
>>
>