RFR: 8212825: jfr.dcmd log is not shown

[Yasumasa Suenaga]

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