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

[Ioi Lam]

I have two issues:

[1] There's a limit of 512 characters:

void Log<T0, T1, T2, T3, T4, GuardTag>::vwrite(const char* fmt, va_list 
args) {
   char buf[LogBufferSize];
   static const size_t LogBufferSize = 512;

I would need to log the names of loaded classes, which could be much 
longer. Would it be possible to add a new function like

   LogHandle(classload) log;
   log.puts<LogLevel::Info>("a very very very long string ..........");

[2] Although the Log::write function is declared with ATTRIBUTE_PRINTF, 
it doesn't seem to do the checking.

   static void write(const char* fmt, ...) ATTRIBUTE_PRINTF(1, 2);

I added these

void LogConfiguration::post_initialize() {
   assert(LogConfiguration_lock != NULL, "Lock must be initialized 
before post-initialization");
   LogDiagnosticCommand::registerCommand();
   LogHandle(logging) log;
   log.info("Log configuration fully initialized.");
+ log_info(logging)("hello %s");
+ tty->print_cr("hello %s");

I get a warning on the tty->print_cr line but not on the 
log_info(logging) line.

**NOTICE** Dtrace support disabled: This JDK does not support SDT probes
/home/iklam/jdk/ul/hotspot/src/share/vm/logging/logConfiguration.cpp: In 
static member function `static void LogConfiguration::post_initialize()':
/home/iklam/jdk/ul/hotspot/src/share/vm/logging/logConfiguration.cpp:52:27: 
error: format `%s' expects a matching `char*' argument [-Werror=format=]
    tty->print_cr("hello %s");
                            ^
cc1plus: all warnings being treated as errors
make[4]: *** [logConfiguration.o] Error 1

My gcc is

$ gcc -v
Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/usr/lib/gcc/x86_64-linux-gnu/4.8/lto-wrapper
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Ubuntu 
4.8.2-19ubuntu1' --with-bugurl=file:///usr/share/doc/gcc-4.8/README.Bugs 
--enable-languages=c,c++,java,go,d,fortran,objc,obj-c++ --prefix=/usr 
--program-suffix=-4.8 --enable-shared --enable-linker-build-id 
--libexecdir=/usr/lib --without-included-gettext --enable-threads=posix 
--with-gxx-include-dir=/usr/include/c++/4.8 --libdir=/usr/lib 
--enable-nls --with-sysroot=/ --enable-clocale=gnu 
--enable-libstdcxx-debug --enable-libstdcxx-time=yes 
--enable-gnu-unique-object --disable-libmudflap --enable-plugin 
--with-system-zlib --disable-browser-plugin --enable-java-awt=gtk 
--enable-gtk-cairo 
--with-java-home=/usr/lib/jvm/java-1.5.0-gcj-4.8-amd64/jre 
--enable-java-home 
--with-jvm-root-dir=/usr/lib/jvm/java-1.5.0-gcj-4.8-amd64 
--with-jvm-jar-dir=/usr/lib/jvm-exports/java-1.5.0-gcj-4.8-amd64 
--with-arch-directory=amd64 
--with-ecj-jar=/usr/share/java/eclipse-ecj.jar --enable-objc-gc 
--enable-multiarch --disable-werror --with-arch-32=i686 --with-abi=m64 
--with-multilib-list=m32,m64,mx32 --with-tune=generic 
--enable-checking=release --build=x86_64-linux-gnu 
--host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.8.2 (Ubuntu 4.8.2-19ubuntu1)

Thanks
- Ioi

On 9/9/15 12:33 AM, Marcus Larsson wrote:
> Hi,
>
> On 2015-09-08 22:53, Ioi Lam wrote:
>> Also, is it possible to combine the output of two tags into a single 
>> file, like this?
>>
>>      -Xlog:gc:file=out.txt -Xlog:comp:file=out.txt
>>
>> this way, I can have both GC and Compiler logs that's in an 
>> (approximate) temporal order. The alternatives are:
>>
>> - write both to stdout -- but I need to filter out junk that I don't 
>> want
>> - write to different files -- but I lose the relative ordering 
>> between the two sets of logs
>>
>> From the current patch, it seems like if I assign the same file name 
>> to two tags, fopen() will be called twice and the result will be 
>> platform dependent.
>>
>> - Ioi
>
> This is indeed possible! The syntax for configuring this would be 
> -Xlog:gc,comp:file=out.txt. Configuring logging for the same output 
> multiple times only overrides/replaces the previous configuration. The 
> second fopen will not happen, because the log configuration will 
> notice the output already exists and simply reconfigure the existing 
> output.
>
> Thanks,
> Marcus
>
>>
>> On 9/8/15 1:26 PM, Ioi Lam wrote:
>>> Hi Marcus,
>>>
>>> I am eagerly waiting for this to implement a new logging feature in 
>>> the VM. How much testing has been done on this patch? I can see only 
>>> two locations where any logs are bring generated:
>>>
>>> +    log_error(logging)("%s", errbuf);
>>> +    log_error(logging)("Could not open log file '%s' (%s).\n", 
>>> _file_name, strerror(errno));
>>>
>>> Do you have a follow-on patch that's already in work to test the 
>>> various functionalists of the Unified JVM Logging framework? I am 
>>> asking so that I can know how much surprise to expect when I start 
>>> using it.
>>>
>>> Thanks
>>> - Ioi
>>>
>>>
>>> On 9/7/15 6: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
>>>
>>
>