RFR: 8212825: jfr.dcmd log is not shown

[Yasumasa Suenaga]

2018年10月31日(水) 3:29 Erik Gahlin <erik.gahlin at oracle.com>:
>
> 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.

Thanks! I'm waiting for your webrev.

Yasumasa

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