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

[Marcus Larsson]

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(...).

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


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
>