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

Marcus Larsson marcus.larsson at oracle.com
Thu Sep 10 09:04:49 UTC 2015

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 logdebugisenabled(...) logisenabled(Debug, VAARGS) #define logtraceisenabled(...) logisenabled(Trace, VAARGS) 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

More information about the hotspot-dev mailing list