JDK-8265795 : vmTestbase/nsk/jvmti/AttachOnDemand/attach022/TestDescription.java fails when running with JEP 416
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jvmti
  • Affected Version: 17
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2021-04-22
  • Updated: 2024-11-19
  • Resolved: 2021-11-22
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 18
18 b26Fixed
Related Reports
Relates :  
JDK-8271820 - Implementation of JEP 416: Reimplement Core Reflection with Method Handle
Description
vmTestbase/nsk/jvmti/AttachOnDemand/attach022/TestDescription.java fails when running with a proposed fix for JDK-6824466  (https://github.com/mlchung/jdk/tree/method-invoke-4)

TargetApp (stdout): The following fake exception stacktrace is for failure analysis. 
TargetApp (stdout): nsk.share.Fake_Exception_for_RULE_Creation: (attach022Agent00.cpp:75) ERROR: unexpected taggedObjectsCounter: 0 (expected value is 10)
TargetApp (stdout): 	at nsk_lvcomplain(nsk_tools.cpp:172)
TargetApp (stdout): # ERROR: attach022Agent00.cpp, 75: ERROR: unexpected taggedObjectsCounter: 0 (expected value is 10)
TargetApp (stdout): - aod.cpp, 253: Agent NativeAgent-0 finished (success: 0)
TargetApp (stdout): Agent 'NativeAgent-0' finished execution (finishedSuccessfully: false)
TargetApp (stdout): # ERROR: Agent 'NativeAgent-0 finished with error status
TargetApp (stdout): The following stacktrace is for failure analysis.
TargetApp (stdout): nsk.share.TestFailure: Agent 'NativeAgent-0 finished with error status
TargetApp (stdout): 	at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432)
TargetApp (stdout): 	at nsk.share.Log.complain(Log.java:403)
TargetApp (stdout): 	at nsk.share.aod.TargetApplicationWaitingAgents.setStatusFailed(TargetApplicationWaitingAgents.java:275)
TargetApp (stdout): 	at nsk.share.aod.TargetApplicationWaitingAgents.agentFinished(TargetApplicationWaitingAgents.java:173)
TargetApp (stdout): 	at nsk.jvmti.AttachOnDemand.attach022.attach022Target.shutdownAgent(Native Method)
TargetApp (stdout): 	at nsk.jvmti.AttachOnDemand.attach022.attach022Target.targetApplicationActions(attach022Target.java:52)
TargetApp (stdout): 	at nsk.share.aod.TargetApplicationWaitingAgents.runTargetApplication(TargetApplicationWaitingAgents.java:354)
TargetApp (stdout): 	at nsk.jvmti.AttachOnDemand.attach022.attach022Target.main(attach022Target.java:59)
TargetApp (stdout): # ERROR: Error happened during agent work, see error messages for details
TargetApp (stdout): Waiting for agents finishing
TargetApp (stdout): All agents finished execution
TargetApp (stdout): Signal received: 'finish'
TargetApp (stdout): # ERROR: Error happened during TargetApplication execution (see error messages for details)
TargetApp (stdout): The following stacktrace is for failure analysis.
TargetApp (stdout): nsk.share.TestFailure: Error happened during TargetApplication execution (see error messages for details)
TargetApp (stdout): 	at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432)
TargetApp (stdout): 	at nsk.share.Log.complain(Log.java:403)
TargetApp (stdout): 	at nsk.share.aod.TargetApplicationWaitingAgents.exitAsFailed(TargetApplicationWaitingAgents.java:289)
TargetApp (stdout): 	at nsk.share.aod.TargetApplicationWaitingAgents.runTargetApplication(TargetApplicationWaitingAgents.java:386)
TargetApp (stdout): 	at nsk.jvmti.AttachOnDemand.attach022.attach022Target.main(attach022Target.java:59)
TargetApp (stdout): # ERROR: Stop execution
Comments
Changeset: 33e2a518 Author: Leonid Mesnik <lmesnik@openjdk.org> Date: 2021-11-22 17:11:34 +0000 URL: https://git.openjdk.java.net/jdk/commit/33e2a518ebcd50e76c559512539fd7c864fd2407
22-11-2021
[~dholmes] Thank you for the explanation about the problem with reflection. I'll check the usage of unsafe and check how post_vm_object_alloc in Unsafe_AllocateInstance works.
18-11-2021
> I believe it is needed to add post_vm_object_alloc directly into Unsafe_AllocateInstance. I tend to agree that is where the event generation should occur as it is a VM allocation point. That said we would also need to check the other callers of this to ensure these events are actually appropriate - and even so it may surprise other tests. > The absence of an event for inflation path in inflation path for reflection is a separate issue. It is JDK 17 below only. Just to be clear if reflection spins up bytecode to do this then there should not be a VMObjectAlloc event. The point I am raising is that the test is assuming it should expect and event from reflection, when in fact that will depend on the nature of the reflection (at least before the switch to MH).
18-11-2021
I believe it is needed to add post_vm_object_alloc directly into Unsafe_AllocateInstance. The absence of an event for inflation path in inflation path for reflection is a separate issue. It is JDK 17 below only.
17-11-2021
Looks like MH to invoke a constructor is missing to generate JVM TI VMObjectAlloc event. MH uses Unsafe::allocateInstance to allocate an object before invoking the constructor. See https://github.com/openjdk/jdk/blob/master/src/java.base/share/classes/java/lang/invoke/DirectMethodHandle.java#L277
16-11-2021
Thanks [~lmesnik] (I was grepping for the wrong search string). So that would be the native accessor path right? So for the inflation path there would be no event. I'm failing to discover where in the MH code it actually does the allocation before invoking the constructor's MH ??
16-11-2021
The reflection generates the event in the JVM_NewInstanceFromConstructor. And I think that MH just never generated it. Need to add the simple test which generate object and check events to ensure.
16-11-2021
Is it the case that construction via MethodHandles has never generated ObjectAlloc events? If so that seems a bug in the original provision of MethodHandles. The spec is quite clear: " Some methods might not have associated bytecodes and are not native methods, they instead are executed directly by the VM. These methods should send this event." If MH don't use bytecodes then they should always have sent this event when allocating the object. That said, I don't see where the old reflection implementation would generate this event either. And if the reflection implementation spun bytecode then it would not generate this event.
16-11-2021
It seems that VMObjectAlloc should be generated when an object is constructed using MethodHandle. There are no bytecodes used in this case. Also, the spec for https://docs.oracle.com/en/java/javase/16/docs/specs/jvmti.html#VMObjectAlloc might be updated to make it clearer.
16-11-2021
The attach002a failure does appear to be the same issue. The test is allocating a InterruptedException using Class.newInstance(): InterruptedException e = InterruptedException.class.newInstance(); It should be getting an ObjectAlloc event for it, but the event is not showing up in the log. The event is what triggers the RedefineClass of InterruptedException. Since that is never happening, the test fails when it detects that InterruptedException was not redefined.
13-10-2021
The test creates 10 instances of nsk.jvmti.AttachOnDemand.attach022.ClassForAllocationEventsTest. You can see it doing this in the log with 10 lines like the following: TargetApp (stdout): Create instance of nsk.jvmti.AttachOnDemand.attach022.ClassForAllocationEventsTest However, it also expects 10 ObjectAlloc events for these instances, but these are not showing up in the log. You see them for a few other allocations such as: TargetApp (stdout): - attach022Agent00.cpp, 131: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) Since these 10 ObjectAlloc events are never received, the object tagging of these objects is never done, thus the failure message: TargetApp (stdout): # ERROR: attach022Agent00.cpp, 75: ERROR: unexpected taggedObjectsCounter: 0 (expected value is 10) Maybe reflective allocations are no longer triggering the ObjectAlloc event. This is the code that prints the first log message above and allocates the object: private void allocateObject() throws InstantiationException, IllegalAccessException { log.display("Create instance of " + ClassForAllocationEventsTest.class.getName()); ClassForAllocationEventsTest.class.newInstance(); } I'm not sure why newInstance() is used here rather than just "new". Would be interesting to see if the bug goes away when using "new".
13-10-2021
vmTestbase/nsk/jvmti/AttachOnDemand/attach002a/TestDescription.java fails. The issue might be related. TargetApp (stdout): - attach002aAgent00.cpp, 126: NativeAgent-0: initialization was done TargetApp (stdout): - aod.cpp, 199: Agent NativeAgent-0 is loaded TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): Agent 'NativeAgent-0' was loaded TargetApp (stdout): All expected agents connected TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: [Ljava/lang/reflect/Constructor;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: [Ljava/lang/Class;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/reflect/Constructor;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: [Ljava/lang/Class;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/reflect/Constructor;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/String;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: [B) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): InterruptedException.getMessage(): 'Test InterruptedException' Agent was loaded Detaching from the VM 'sun.tools.attach.AttachProviderImpl@541e4ee8: 15624' Sending signal: 'finish' TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): # ERROR: InterruptedException.getMessage() returns unexpected value (expected is 'attach002a: redefined version'), probably class wasn't redefined TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/String;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: [B) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/String;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: [B) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/String;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: [B) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): The following stacktrace is for failure analysis. TargetApp (stdout): nsk.share.TestFailure: InterruptedException.getMessage() returns unexpected value (expected is 'attach002a: redefined version'), probably class wasn't redefined TargetApp (stdout): at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432) TargetApp (stdout): at nsk.share.Log.complain(Log.java:403) TargetApp (stdout): at nsk.share.aod.TargetApplicationWaitingAgents.setStatusFailed(TargetApplicationWaitingAgents.java:275) TargetApp (stdout): at nsk.jvmti.AttachOnDemand.attach002a.attach002aTarget.targetApplicationActions(attach002aTarget.java:44) TargetApp (stdout): at nsk.share.aod.TargetApplicationWaitingAgents.runTargetApplication(TargetApplicationWaitingAgents.java:354) TargetApp (stdout): at nsk.jvmti.AttachOnDemand.attach002a.attach002aTarget.main(attach002aTarget.java:51) TargetApp (stdout): Waiting for agents finishing TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): - attach002aAgent00.cpp, 63: NativeAgent-0: ObjectAlloc event received (object class: Ljava/lang/invoke/MemberName;) TargetApp (stdout): # ERROR: Agents didn't finish in 300000ms, stop execution (attached agents number: 1, finished agents number: 0) TargetApp (stdout): The following stacktrace is for failure analysis. TargetApp (stdout): nsk.share.TestFailure: Agents didn't finish in 300000ms, stop execution (attached agents number: 1, finished agents number: 0) TargetApp (stdout): at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432) TargetApp (stdout): at nsk.share.Log.complain(Log.java:403) TargetApp (stdout): at nsk.share.aod.TargetApplicationWaitingAgents.exitAsFailed(TargetApplicationWaitingAgents.java:289) TargetApp (stdout): at nsk.share.aod.TargetApplicationWaitingAgents.waitAgentsFinishing(TargetApplicationWaitingAgents.java:264) TargetApp (stdout): at nsk.share.aod.TargetApplicationWaitingAgents.runTargetApplication(TargetApplicationWaitingAgents.java:368) TargetApp (stdout): at nsk.jvmti.AttachOnDemand.attach002a.attach002aTarget.main(attach002aTarget.java:51) TargetApp (stdout): # ERROR: Stop execution TargetApp (stdout): TargetApp (stdout): TargetApp (stdout): #> TargetApp (stdout): #> SUMMARY: Following errors occured TargetApp (stdout): #> during test execution: TargetApp (stdout): #> TargetApp (stdout): # ERROR: InterruptedException.getMessage() returns unexpected value (expected is 'attach002a: redefined version'), probably class wasn't redefined TargetApp (stdout): # ERROR: Agents didn't finish in 300000ms, stop execution (attached agents number: 1, finished agents number: 0) TargetApp (stdout): # ERROR: Stop execution
27-04-2021