RFR: 8212825: jfr.dcmd log is not shown

[Erik Gahlin]

On 2018-10-30 03:24, Yasumasa Suenaga wrote:
>>    http://cr.openjdk.java.net/~ysuenaga/JDK-8212825/webrev.01/
> This change has been run jdk/jdk/jfr jtreg tests.
> jdk/jfr/api/event/TestShouldCommit.java is failed. But I don't think
> this failure is caused by this change.
>
> I've posted this change to submit repo.
>
>
> Yasumasa
>
>
> 2018年10月30日(火) 11:16 Yasumasa Suenaga <yasuenag at gmail.com>:
>> Hi Erik,
>>
>>>    LogTag(int tagId) {
>>>       id = tagId;
>>> + // This will initialize the JVM Logger
>>> +    JVMSupport.tryToInitializeJVM();
>>>    }
>> I tried to do so, but I saw NPE as below because LogTag::values() had
>> not been initialized yet:
I didn't think of that.

The bug seems to be a duplicate of JDK-8209960, or they are at least 
closely related.
https://bugs.openjdk.java.net/browse/JDK-8209960

I like to fix the issue by doing the initialization in the Logger class 
instead. I can send out a webrev later in the week.

I have another fix that I like to integrate first.

Erik

>> -----------
>> [0.099s][info ][exceptions] Exception <a
>> 'java/lang/NullPointerException'{0x000000062a860c78}>
>> (0x000000062a860c78)
>> thrown [/home/ysuenaga/OpenJDK/jdk/src/hotspot/share/interpreter/linkResolver.cpp,
>> line 1356]
>> for thread 0x00007f5d1801a800
>> [0.099s][info ][exceptions] Exception <a
>> 'java/lang/NullPointerException'{0x000000062a860c78}>
>>   thrown in interpreter method <{method} {0x00007f5ce1422ee8} 'values'
>> '()[Ljdk/jfr/internal/LogTag;' in 'jdk/jfr/internal/LogTag'>
>>   at bci 3 for thread 0x00007f5d1801a800 (main)
>> [0.099s][info ][exceptions] Exception <a
>> 'java/lang/NullPointerException'{0x000000062a860c78}>
>>   thrown in interpreter method <{method} {0x00007f5ce1444db8}
>> '<clinit>' '()V' in 'jdk/jfr/internal/JVM'>
>>   at bci 23 for thread 0x00007f5d1801a800 (main)
>> -----------
>>
>> So I updated new webrev. Could you check it again?
>>
>>    http://cr.openjdk.java.net/~ysuenaga/JDK-8212825/webrev.01/
>>
>>
>> Thanks,
>>
>> Yasumasa
>>
>>
>> 2018年10月29日(月) 23:38 Erik Gahlin <erik.gahlin at oracle.com>:
>>> Hi Yasumasa,
>>>
>>> Thanks for filing the bug. Instead of making the call to
>>> JVM.getJVM().isAvailable() in DcmdStart, could you try to add this to
>>> the constructor of the LogTag class.
>>>
>>>    LogTag(int tagId) {
>>>       id = tagId;
>>> + // This will initialize the JVM Logger
>>> +    JVMSupport.tryToInitializeJVM();
>>>    }
>>>
>>> and add this empty method to the JVMSupport class
>>>
>>> + public void tryToInitializeJVM() {
>>> + }
>>>
>>> This will make sure the logger is always initialized before the LogTag
>>> class is used. This will fix similar bugs in the other DCmds classes and
>>> perhaps elsewhere as well.
>>>
>>> Run the tests in test\jdk\jdk\jfr to make sure the fix doesn't break
>>> functionality.
>>>
>>> Thanks
>>> Erik
>>>
>>>> Hi Erik,
>>>>
>>>> I filed this issue as JDK-8212825, and I uploaded webrev.
>>>> Could you review it?
>>>>
>>>>    http://cr.openjdk.java.net/~ysuenaga/JDK-8212825/webrev.00/
>>>>
>>>>
>>>> Thanks,
>>>>
>>>> Yasumasa
>>>>
>>>>
>>>> On 2018/10/24 0:17, Erik Gahlin wrote:
>>>>> Hi Yasumasa,
>>>>>
>>>>> Please file a bug. Markus and I will not have time to look at this
>>>>> week (CodeOne), but I will check it out next week. Ping me if I forget.
>>>>>
>>>>> Thanks
>>>>> Erik
>>>>>
>>>>>
>>>>>> On 23 Oct 2018, at 08:10, Yasumasa Suenaga <yasuenag at gmail.com> wrote:
>>>>>>
>>>>>> Hi all,
>>>>>>
>>>>>> I tried to check arguments of -XX:StartFlightRecording via
>>>>>> -Xlog:jfr+dcmd=debug , but I couldn't.
>>>>>>
>>>>>> jfr.dcmd log will be shown from DCmdStart::execute, but I think it
>>>>>> has two problems:
>>>>>>
>>>>>>    1. Log level will be not set before showing log.
>>>>>>       LogTag::tagSetLevel is used to decide to show the log. But it
>>>>>> will be set in
>>>>>>       JNI code which is called by JVM::<clinit>. JVM class is not
>>>>>> loaded when
>>>>>>       DCmdStart::execute tries to show log.
>>>>>>
>>>>>>    2. `settings` might be null, so NPE will occur when
>>>>>> DCmdStart::execute tries to
>>>>>>       show log.
>>>>>>
>>>>>> IMHO they can be fixed with following patch. Can I file this problem
>>>>>> to JBS and send a webrev?
>>>>>> (I'm a Committer of jdk project)
>>>>>>
>>>>>>
>>>>>> ---------------------
>>>>>> diff -r eadd0abbfdf4
>>>>>> src/jdk.jfr/share/classes/jdk/jfr/internal/dcmd/DCmdStart.java
>>>>>> --- a/src/jdk.jfr/share/classes/jdk/jfr/internal/dcmd/DCmdStart.java
>>>>>> Tue Oct 23 13:24:36 2018 +0200
>>>>>> +++ b/src/jdk.jfr/share/classes/jdk/jfr/internal/dcmd/DCmdStart.java
>>>>>> Wed Oct 24 00:10:05 2018 +0900
>>>>>> @@ -34,6 +34,7 @@
>>>>>> import java.util.Arrays;
>>>>>> import java.util.HashMap;
>>>>>> import java.util.Map;
>>>>>> +import java.util.Objects;
>>>>>>
>>>>>> import jdk.jfr.FlightRecorder;
>>>>>> import jdk.jfr.Recording;
>>>>>> @@ -81,9 +82,12 @@
>>>>>>        */
>>>>>>       @SuppressWarnings("resource")
>>>>>>       public String execute(String name, String[] settings, Long
>>>>>> delay, Long duration, Boolean disk, String path, Long maxAge, Long
>>>>>> maxSize, Boolean dumpOnExit, Boolean pathToGcRoots) throws
>>>>>> DCmdException {
>>>>>> +        if (!JVM.getJVM().isAvailable()) {
>>>>>> +            throw new DCmdException("JFR is not available");
>>>>>> +        }
>>>>>>           if (LogTag.JFR_DCMD.shouldLog(LogLevel.DEBUG)) {
>>>>>>               Logger.log(LogTag.JFR_DCMD, LogLevel.DEBUG, "Executing
>>>>>> DCmdStart: name=" + name +
>>>>>> -                    ", settings=" + Arrays.asList(settings) +
>>>>>> +                    ", settings=" +
>>>>>> Arrays.asList(Objects.requireNonNullElse(settings, new String[0])) +
>>>>>>                       ", delay=" + delay +
>>>>>>                       ", duration=" + duration +
>>>>>>                       ", disk=" + disk+
>>>>>> ---------------------
>>>>>>
>>>>>>
>>>>>> Thanks,
>>>>>>
>>>>>> Yasumasa