Topic
19 replies Latest Post - ‏2013-01-18T11:17:58Z by SystemAdmin
EliotMoss
EliotMoss
17 Posts
ACCEPTED ANSWER

Pinned topic Apparent JVMTI ClassFileLoadHook bug

‏2012-07-11T16:28:16Z |
[This was previously posted in a different forum, but it was suggested
I post it here also.]

I am developing a tool that instruments every class file loaded. What
seems to be to be a bug is that there are several classes that the VM
loads (as shown by -verbose:class) but that are not offered to the
ClassFileLoadHook routine that I registered via JVMTI. The truly odd
thing about this is that there are classes presented to the load hook
both before and after the ones that are not presented.

In particular, java/util/IdentityHashMap is offered correctly, but
java/util/IdentityHashMap$1 is not (but is loaded), along with
all other IdentityHashMap$... classes that are loaded. A variety
of other inner classes are offered to the load hook.

It may be relevant that this is occurring when Shutdown is going
about the task of running shutdown hooks, and the application has not
used IdentityHashMap itself.

-version produces the following:
java version "1.6.0"
Java(TM) SE Runtime Environment (build pxa6460sr10fp1-20120321_01(SR10 FP1))
IBM J9 VM (build 2.4, JRE 1.6.0 IBM J9 2.4 Linux amd64-64 jvmxa6460sr10fp1-20120202_101568 (JIT enabled, AOT enabled)
J9VM - 20120202_101568
JIT - r9_20111107_21307ifx1
GC - 20120202_AA)
JCL - 20120320_01

Is there something I can do, or is this a case where the developers need to correct
a deficiency and provide a patch or another release?

I can provide the application class I am running (it's quite small) if that would
help. The instrumentation tool is bigger, but I could probably strip it down and
show the same problem if that is necessary to proceed.

Regards -- Eliot Moss
Professor, Computer Science
University of Massachusetts
Updated on 2013-01-18T11:17:58Z at 2013-01-18T11:17:58Z by SystemAdmin
  • SystemAdmin
    SystemAdmin
    2736 Posts
    ACCEPTED ANSWER

    Re: Apparent JVMTI ClassFileLoadHook bug

    ‏2012-07-16T07:47:51Z  in response to EliotMoss
    Mentioned classes are getting loaded out side the defined phase of the event,
    http://docs.oracle.com/javase/7/docs/platform/jvmti/jvmti.html#ClassFileLoadHook
    Phase: "sent during the primordial, start or live phase"

    classes like java/util/IdentityHashMap$1 & others getting loaded on a thread end/termination context, so jvm disabled/not generated the event on loading these classes.
    • EliotMoss
      EliotMoss
      17 Posts
      ACCEPTED ANSWER

      Re: Apparent JVMTI ClassFileLoadHook bug

      ‏2012-07-16T19:57:19Z  in response to SystemAdmin
      Actually, I believe it is still in the live phase.
      One of my best arguments for that is that the hook is
      called for various classes loaded after the ones
      for which the hook is not called. That is what made
      it so mysterious. The VMDead call has not arrived
      yet, though we are indeed "close" to shutting down
      since this happens during the running of the
      Java shutdown hooks.

      A related mystery pertains to the thread that runs
      those hooks. It is spawned early and simply hangs
      around waiting for the right time to do its thing.
      I instrument the classes of that thread that runs
      the shutdown hooks, but some of my instrumentation
      calls seem not to come through, which is really odd.
      For example, I instrument entry and exit of methods,
      and for some of these I get the exit but not the
      entry. I don't see how that can happen, but it appears
      to.

      But for the moment, let's stick with the odd case of
      several methods not present to the load hook during the
      live phase.

      Thanks for engaging my questions -- Eliot
  • WenHsinChang
    WenHsinChang
    4 Posts
    ACCEPTED ANSWER

    Re: Apparent JVMTI ClassFileLoadHook bug

    ‏2012-07-17T04:31:02Z  in response to EliotMoss
    Hello Eliot,

    I will take your offer to provide the application class and the jvmti agent you have implemented.

    Without further investigation. I'm as confused as you are with the issue you have described.

    Please provide the necessary resources and steps on how you produced/observed the issue. In the mean time, I will
    search through code base to see if any similar defect has already been reported/fixed.
    • EliotMoss
      EliotMoss
      17 Posts
      ACCEPTED ANSWER

      Re: Apparent JVMTI ClassFileLoadHook bug

      ‏2012-07-17T08:22:20Z  in response to WenHsinChang
      Thank you, Wen Hsin!

      I will work on packaging it up in a way that demonstrates the issue while making it as simple as I can for you to run it and debug. I am traveling and at a conference, so I am not sure exactly how long this will take (and the Internet connection does not seem 100% reliable either).

      Regards -- Eliot
    • EliotMoss
      EliotMoss
      17 Posts
      ACCEPTED ANSWER

      Re: Apparent JVMTI ClassFileLoadHook bug

      ‏2012-07-17T14:59:53Z  in response to WenHsinChang
      Ok, I attach a zip file with the agent, etc.,
      showing the problem.

      Instructions:

      On a Linux system (preferably 64 bit), unzip.
      Edit src/Makefile.local to point to your J9 installation.
      In src, run: make clean all install
      In testing, edit runHello also to refer to your J9 installation.
      In testing, run: ./runHello
      Then, in testing, run: uninstrumented hello.err

      This should show the classes that are uninstrumented.
      java/lang/J9VMInternals is not surprising (though maybe
      it could be instrumented as well), but the others are
      exactly the inner classes of IdentityHashMap and I have
      not discerned anything distinguishing to explain the
      matter.

      By looking at the hello.err output and looking in main.cpp
      and ETCallBackHandler.cpp you should find where the messages
      are printed, etc., which may help. The Makefile is set to
      compile with -g, which may also help :-) ...

      I use gnu make and gcc when building (no IBM tools outside
      of J9).

      Regards, and thanks for the help -- Eliot Moss
      • WenHsinChang
        WenHsinChang
        4 Posts
        ACCEPTED ANSWER

        Re: Apparent JVMTI ClassFileLoadHook bug

        ‏2012-07-17T18:33:31Z  in response to EliotMoss
        Hello,

        I've confirmed ParamS' statement. The class load events are not reported because the thread is dying. Event though JVMTI is still in live phase, a stopped thread will stop reporting events (unless the event is either VM Death or Thread end).

        The list of classes as printed by ./unintialized hello.err are all loaded from the same thread.

        To see this, I've appened -Xtrace:minimal={j9vm{entry},j9vm{exit},j9jvmti.328-329},output=trace.trc to java commandline. This will create a a trace.trc file that can be formatted via
        $>java com.ibm.jvm.trace.TraceFormat trace.trc.

        Looking into the formatted trace, it is not hard to see that all the listed class (with the exception of jva/lang/J9VMInternals) are loaded by the same thread. Therefore, this explains the behavior for classes being reported even through they're loaded after the classes that aren't reported.

        I've instrumented the VM to print out some debug message and noticed the state of thread in question is stopped, which prevents the loaded class hook event to fire.

        The other way is to hook a thread end event. This will confirm that thread end event has occured, which will prevents all other events on the thread to be reported.
        • EliotMoss
          EliotMoss
          17 Posts
          ACCEPTED ANSWER

          Re: Apparent JVMTI ClassFileLoadHook bug

          ‏2012-07-18T06:40:57Z  in response to WenHsinChang
          First, thank you very much for the time and care you have taken
          to investigate this issue.

          You have provided an explanation of what we are seeing, but
          I am not convinced that the behavior is what we should desire,
          that is, I am not yet convinced that it is correct. Why not
          report the class load events to the hook and allow the classes
          to be instrumented? What happens during shutdown is not necessarily
          irrelevant to whatever measurement or observation one is trying
          to achieve with instrumentation. Furthermore, there is not really
          any good way I see to declare "game over" until VMDeath arrives,
          so where do I end my trace consistently?

          Is there something in the JVMTI specification on which you base
          the correctness of this behavior? Or do you agree that it is
          not desired and something that might be fixed in the future?

          Regards -- EM
          • WenHsinChang
            WenHsinChang
            4 Posts
            ACCEPTED ANSWER

            Re: Apparent JVMTI ClassFileLoadHook bug

            ‏2012-07-18T13:55:29Z  in response to EliotMoss
            Hello Eliot,

            http://docs.oracle.com/javase/6/docs/platform/jvmti/jvmti.html#ThreadEnd

            This is the description for JVMTI Thread End event. It states "No events are generated on a thread after its thread end event.".

            It is expected that all events on a dying thread are suppressed. I believe this is to narrow timing window of possible race conditions where user code may ended
            up referring to a dead/non-existing Java thread if events are continuously reported on a terminating thread.

            As such, since it is clearly stated in the JVMTI spec, unless we have a case where the events are not being reported before thread end event was generated,
            there will be no change to this behavior. However, I'm investigating if thread end event are sent prematurily. I would expect a dying thread to be clean up after itself, not loading
            6 other classes while it is dying.. I will update this thread when I have more info.
            • EliotMoss
              EliotMoss
              17 Posts
              ACCEPTED ANSWER

              Re: Apparent JVMTI ClassFileLoadHook bug

              ‏2012-07-18T14:15:29Z  in response to WenHsinChang
              Ok, I understand better what you mean.

              However, I observe that ClassFileLoadHook does not have any thread
              arguments, and I think it should therefore be considered an event
              of the VM, not an event of a particular thread (though of
              course some thread's activity is presumably the root cause of the
              loading, except perhaps for some primordial classes loaded before
              any "real" threads are started (such as java/lang/Object)).

              I would argue that any event that does not include the generating
              thread as one of the event's arguments should not be considered an
              event of the thread ....

              Perhaps we need to seek clarification from the jvmti specification
              writers, though I fear that might take some time. I might try to
              see where I can ask that question and get a definitive answer.

              Regards -- Eliot
              • SystemAdmin
                SystemAdmin
                2736 Posts
                ACCEPTED ANSWER

                Re: Apparent JVMTI ClassFileLoadHook bug

                ‏2012-07-19T08:05:40Z  in response to EliotMoss
                I wrote a simple agent which registers for class_load, vm_death & thread_end. It clearly showcases the behaviour & confirms that JVM works as per the JVMTI spec.

                class_load_event handler: prints the class name along with thread id.
                <pthread_id>.<classname>
                thread_end handler: prints the thread id with msg
                <pthread_id>."Thread End event triggered"
                VM Death handler: print the thread id with msg
                <pthread_id>."VM Death Event triggerd>"

                Output from the program "java -agentpath:./myagent.so -version"
                (only few lines from last)
                *-1219871888.*java/nio/channels/GatheringByteChannel
                class load: java/nio/channels/GatheringByteChannel
                *-1219871888.*java/nio/channels/ScatteringByteChannel
                class load: java/nio/channels/ScatteringByteChannel
                java version "1.6.0"
                Java(TM) SE Runtime Environment (build pxi3260sr10fp1-20120321_01(SR10 FP1))
                IBM J9 VM (build 2.4, JRE 1.6.0 IBM J9 2.4 Linux x86-32 jvmxi3260sr10fp1-20120202_101568 (JIT enabled, AOT enabled)
                J9VM - 20120202_101568
                JIT - r9_20111107_21307ifx1
                GC - 20120202_AA)
                JCL - 20120320_01
                *-1219871888.*Thread End event <<<<<<<<<<<<<<<<<<<<<< Thread goes into termination
                class load: java/util/AbstractList$SimpleListIterator
                class load: java/util/IdentityHashMap$1
                class load: java/util/IdentityHashMap$IdentityHashMapIterator <<<<<<<< these classes loaded by the thread -1219871888.
                class load: java/util/IdentityHashMap$1$1 <<<<<<<< class_load hook not triggered as these classes loaded after Thread event
                class load: java/util/IdentityHashMap$IdentityHashMapEntry
                *-1789965456.*com/ibm/tools/attach/javaSE/AttachHandler$1
                class load: com/ibm/tools/attach/javaSE/AttachHandler$1
                -1789965456.java/util/Arrays
                -1788499088.Thread End event
                class load: java/util/Arrays
                -1790833808.Thread End event
                -1790231696.Thread End event
                -1789965456.java/lang/Thread$State
                class load: java/lang/Thread$State
                -1789965456.Thread End event
                class load: java/io/DeleteOnExitHook
                class load: java/util/LinkedHashSet
                class load: java/util/LinkedHashMap$1
                class load: java/util/LinkedHashMap$AbstractMapIterator
                class load: java/util/LinkedHashMap$KeyIterator
                class load: java/util/ListIterator
                class load: java/util/AbstractList$FullListIterator
                -1219871888.Death Event triggered <<<<<<<<<< VM Death Event

                So, the reason for some classes not being reported is the classes are loaded after the thread end event.
                *-1219871888.*Thread End event <<<<<<<<<<<<<<<<<<<<<< thread end event reported by thread. then it loads set of classes which are used for its termination logic. (those classes are not reported).

                "No events are generated on a thread after its thread end event." from JVMTI spec.
                • EliotMoss
                  EliotMoss
                  17 Posts
                  ACCEPTED ANSWER

                  Re: Apparent JVMTI ClassFileLoadHook bug

                  ‏2012-07-19T10:16:59Z  in response to SystemAdmin
                  Again, I appreciate your work on this.

                  We agree on the situation: Somehow the thread causes some classes to be loaded after the thread's "main" routine is done, which means the thread is considered to the dead.

                  What we're talking at crossed purposes about is what the spec means, in particular the part you quote:

                  "No events are generated on a thread after its thread end event." from JVMTI spec.

                  My contention is that these classfile loading actions are not events "on" this thread. They are indeed somehow caused by action of the thread, but I argue that ClassFileLoadHook events are not events "on" any particular thread -- they are events of the VM (as a whole). My support for this argument is the fact that ClassFileLoadHook does not report the thread that caused the loading.

                  Furthermore, achieving uniform agent-level bytecode rewriting pretty much demands presenting all loaded classes to ClassFileLoadHook (unless there is some other really good reason, which might exist for the J9 JVM internals class that we see is intentionally skipped). There is, as far as I can see, no really good argument from a semantics standpoint to omit any classes, even those whose loading is caused by a thread after its main is complete.

                  I will proceed to test against the Oracle JVM and see what it does ...

                  Again thanks, and regards -- Eliot MOss
                  • SystemAdmin
                    SystemAdmin
                    2736 Posts
                    ACCEPTED ANSWER

                    Re: Apparent JVMTI ClassFileLoadHook bug

                    ‏2012-07-19T10:47:49Z  in response to EliotMoss
                    http://docs.oracle.com/javase/7/docs/platform/jvmti/jvmti.html#EventSection.

                    "Except where stated otherwise, events are delivered on the thread that caused the event. Events are sent at the time they occur. The specification for each event includes the set of phases in which it can be sent; if an event triggering activity occurs during another phase, no event is sent."

                    I think the above statement addresses our doubt. In our case, the class_load event(though we consider it as generic/VM scope event) is expected to be reported by a thread, but the thread is not at correct state to report it.
                  • EliotMoss
                    EliotMoss
                    17 Posts
                    ACCEPTED ANSWER

                    Re: Apparent JVMTI ClassFileLoadHook bug

                    ‏2012-07-19T12:43:18Z  in response to EliotMoss
                    Running the same trivial Hello program on the HotSpot JVM, instrumenting only to inform of VM phase changes, class loading, ClassFileLoadHook, and ThreadEnd events, produces the following result:

                    1) Every class file that the VM loads is offered at the ClaasFleLoadHook

                    2) No thread loads a class after its ThreadEnd event

                    So this does not resolve our disagreement of interpretation.

                    I will get in touch with the Oracle folks and the spec writers to see if we can clear up the different interpretations of the spec.

                    Regards -- Eliot Moss
  • WenHsinChang
    WenHsinChang
    4 Posts
    ACCEPTED ANSWER

    Re: Apparent JVMTI ClassFileLoadHook bug

    ‏2012-08-17T20:57:43Z  in response to EliotMoss
    Unfortunatly, I'm nowhere closer to resolve this behavior.

    As pointed out by Params, the non-reported classes are loaded only during JVM shutdown. These class are loaded after Thread End (before VM Death) to avoid potential racing conditions .
    While the behavior is lexically compliant to JVMTI spec, I agree with Eliot that it probably defies what spec really meant.

    I'm still investigating possible solutions.
    • EliotMoss
      EliotMoss
      17 Posts
      ACCEPTED ANSWER

      Re: Apparent JVMTI ClassFileLoadHook bug

      ‏2012-08-20T21:38:45Z  in response to WenHsinChang
      Thanks for continuing to work on this. Not knowing the
      internals of the VM, I can't see why this would be difficult
      to do, though perhaps the concern is using a supposedly
      dead thread to report the loading of a class ... Anyway,
      it will be helpful to me when it's resolved :-) ...

      Regards -- Eliot Moss
      • SystemAdmin
        SystemAdmin
        2736 Posts
        ACCEPTED ANSWER

        Re: Apparent JVMTI ClassFileLoadHook bug

        ‏2012-08-30T05:36:47Z  in response to EliotMoss
        Hi,
        Thank you for reporting the issue. We have identified the fix & integrated it into our next service refresh release(1.7SR4). The release date is not confirmed yet. We will update you once the date is confirmed. Also you can find the details here, https://www.ibm.com/developerworks/java/jdk/linux/download.html
        Thank you once again.
        Param
        • EliotMoss
          EliotMoss
          17 Posts
          ACCEPTED ANSWER

          Re: Apparent JVMTI ClassFileLoadHook bug

          ‏2012-08-31T02:32:22Z  in response to SystemAdmin
          Perfect! Thanks again!

          Sincerely -- Eliot
        • EliotMoss
          EliotMoss
          17 Posts
          ACCEPTED ANSWER

          Re: Apparent JVMTI ClassFileLoadHook bug

          ‏2013-01-18T01:55:40Z  in response to SystemAdmin
          Some wonderings about this:

          • Will the fix also appear in the 1.6 stream (in SR13, i.e., the next update)?
          • Any rough idea when the next SR will be out?
          • I have noticed that at least one class is loaded early in the VM but not
          offered to ClassFileLoadHook for bytecode rewriting, namely
          java/lang/NullPointerException. Is this the same problem or a different one?
          Put another way, will your patch make NullPointerException available to the
          hook?

          Regards, and Happy New Year (belated) -- Eliot Moss
          • SystemAdmin
            SystemAdmin
            2736 Posts
            ACCEPTED ANSWER

            Re: Apparent JVMTI ClassFileLoadHook bug

            ‏2013-01-18T11:17:58Z  in response to EliotMoss
            Will the fix also appear in the 1.6 stream (in SR13, i.e., the next update)?
            Yes, It is targeted for 1.6 SR13.
            Any rough idea when the next SR will be out?
            1.6SR13 is targeted(tentative) to be out by end of Feb 2013.
            I have noticed that at least one class is loaded early in the VM but not offered?
            Do you mean VM initialization phase. It so, it is should be different one. I will verify this one & confirm.