RFR: 8212825: jfr.dcmd log is not shown

[Yasumasa Suenaga]

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