United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: 7081938 JSR292: assert(magic_number_2() == MAGIC_NUMBER_2) failed
7081938 : JSR292: assert(magic_number_2() == MAGIC_NUMBER_2) failed

Details
Type:
Bug
Submit Date:
2011-08-22
Status:
Closed
Updated Date:
2012-01-23
Project Name:
JDK
Resolved Date:
2012-01-23
Component:
hotspot
OS:
generic
Sub-Component:
compiler
CPU:
generic
Priority:
P3
Resolution:
Fixed
Affected Versions:
hs22
Fixed Versions:
hs23

Related Reports
Backport:
Duplicate:
Relates:

Sub Tasks

Description
For long time already both C1 and C2 are failing with this assert when -XX:+DeoptimizeALot is used:

http://sqeweb.us.oracle.com/nfs/results/vm/gtee/JDK7/NIGHTLY/VM/2011-08-21/Comp_Baseline/new_unknown_failures.html

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (/tmp/jprt/P1/211217.kvn/source/src/cpu/x86/vm/methodHandles_x86.cpp:414), pid=3411, tid=11
#  assert(magic_number_2() == MAGIC_NUMBER_2) failed: 
#
# JRE version: 7.0-b147
# Java VM: Java HotSpot(TM) Server VM (22.0-b02-internal-201108202112.kvn.7076831-fastdebug compiled mode solaris-x86 )
# Core dump written. Default location: /export/local/54432.JDK7.NIGHTLY.VM+solaris-i586_javase_server_comp_JT_JDK_java_lang/results/workDir/java/lang/invoke/InvokeDynamicPrintArgs/core or core.3411
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.sun.com/bugreport/crash.jsp
#

---------------  T H R E A D  ---------------

Current thread (0x08243000):  VMThread [stack: 0xd4c38000,0xd4cb8000] [id=11]

Stack: [0xd4c38000,0xd4cb8000],  sp=0xd4cb68f0,  free space=506k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x1d8c566]  void VMError::report(outputStream*)+0x902;;  void VMError::report(outputStream*)+0x902
V  [libjvm.so+0x1d8d719]  void VMError::report_and_die()+0x56d;;  void VMError::report_and_die()+0x56d
V  [libjvm.so+0xb1aa26]  void report_vm_error(const char*,int,const char*,const char*)+0x53a;;  void report_vm_error(const char*,int,const char*,const char*)+0x53a
V  [libjvm.so+0x17a38d3]  frame MethodHandles::ricochet_frame_sender(const frame&,RegisterMap*)+0x5db;;  frame MethodHandles::ricochet_frame_sender(const frame&,RegisterMap*)+0x5db
V  [libjvm.so+0xc4d51e]  frame frame::sender_for_ricochet_frame(RegisterMap*)const+0x72;;  frame frame::sender_for_ricochet_frame(RegisterMap*)const+0x72
V  [libjvm.so+0xc5e42a]  frame frame::sender(RegisterMap*)const+0x472;;  frame frame::sender(RegisterMap*)const+0x472
V  [libjvm.so+0xc4cac7]  void frame::deoptimize(JavaThread*)+0x69f;;  void frame::deoptimize(JavaThread*)+0x69f
V  [libjvm.so+0xb63107]  void Deoptimization::deoptimize(JavaThread*,frame,RegisterMap*)+0x1a3;;  void Deoptimization::deoptimize(JavaThread*,frame,RegisterMap*)+0x1a3
V  [libjvm.so+0x1c8a430]  void JavaThread::deoptimize()+0xb70;;  void JavaThread::deoptimize()+0xb70
V  [libjvm.so+0x1db7b28]  void VM_DeoptimizeAll::doit()+0x218;;  void VM_DeoptimizeAll::doit()+0x218
V  [libjvm.so+0x1db738e]  void VM_Operation::evaluate()+0xe2;;  void VM_Operation::evaluate()+0xe2
V  [libjvm.so+0x1db5680]  void VMThread::loop()+0x788;;  void VMThread::loop()+0x788
V  [libjvm.so+0x1db4889]  void VMThread::run()+0xc1;;  void VMThread::run()+0xc1
V  [libjvm.so+0x18de923]  java_start+0x6fb;;  java_start+0x6fb
C  [libc.so.1+0xa7b30]  _thr_setup+0x4e;;  _thr_setup+0x4e
C  [libc.so.1+0xa7e20]  __moddi3+0x60;;  _lwp_start+0x0

VM_Operation (0xd4985bd0): DeoptimizeAll, mode: safepoint, requested by thread 0x0882a400

                                    

Comments
EVALUATION

See main CR
                                     
2011-10-28
EVALUATION

http://hg.openjdk.java.net/hsx/hotspot-comp/hotspot/rev/0abefdb54d21
                                     
2011-10-11
EVALUATION

It's possible that this bug results in crashes or program failures with a product build when the extra_slots in collect/filter/fold adapters is > 0.
                                     
2011-10-10
EVALUATION

(dbx) p psf()

"Executing psf"
 for thread: "main" prio=3 tid=0x0807bc00 nid=0x2 waiting on condition [0xfdd5d000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x0807bc00  [0x 2] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

[Describe stack]
  1. C frame (sp=0xfdd5df34 unextended sp=0xfdd5df34, fp=0xfdd5e048, pc=0xfbaab315)
     RuntimeStub (0xfbaab208): resolve_opt_virtual_call

  2. Deoptimized frame (sp=0xfdd5e050 unextended sp=0xfdd5e050, fp=0xfdd5e0c4, pc=0xfbd6eb00)
     nmethod  45539 1134             java.lang.invoke.InvokeGeneric::dispatchWithConversion (28 bytes)


  3. Ricochet frame (sp=0xfdd5e080 unextended sp=0xfdd5e080, fp=0xfdd5e0c4, pc=0xfbaaacde)
     RicochetBlob


  4. Compiled frame (sp=0xfdd5e0d0 unextended sp=0xfdd5e0f0, fp=0xfdd5e0f0, pc=0xfbd667cc)
     nmethod  45539 1117   !         java.lang.invoke.CallSite::makeSite (274 bytes)


  5. Compiled frame (sp=0xfdd5e1a0 unextended sp=0xfdd5e1a0, fp=0xfdd5e220, pc=0xfbd61500)
     nmethod  45539 1108             java.lang.invoke.MethodHandleNatives::makeDynamicCallSite (12 bytes)


  6. C frame (sp=0xfdd5e1d0 unextended sp=0xfdd5e1d0, fp=0xfdd5e220, pc=0xfba003b1)
(~Stub::call_stub)
     BufferBlob (0xfba00288) used for StubRoutines (1)
                                     
2011-10-07
SUGGESTED FIX

diff -r eba73e0c7780 src/cpu/x86/vm/methodHandles_x86.hpp
--- a/src/cpu/x86/vm/methodHandles_x86.hpp
+++ b/src/cpu/x86/vm/methodHandles_x86.hpp
@@ -132,7 +132,10 @@ class RicochetFrame {
   intptr_t* sender_link() const         { return _sender_link; }
   address   sender_pc() const           { return _sender_pc; }
 
-  intptr_t* extended_sender_sp() const  { return saved_args_base(); }
+  intptr_t* extended_sender_sp() const {
+    // The extended sender SP is above the current RicochetFrame.
+    return (intptr_t*) (((address) this) + sizeof(RicochetFrame));
+  }
 
   intptr_t  return_value_slot_number() const {
     return adapter_conversion_vminfo(conversion());
                                     
2011-10-07
EVALUATION

MethodHandles::ricochet_frame_sender uses RicochetFrame::extended_sender_sp to create the frame for the ricochet frame:

  return frame(f->extended_sender_sp(), f->exact_sender_sp(), f->sender_link(), f->sender_pc());

extended_sender_sp returns the _saved_args_base:

  intptr_t* extended_sender_sp() const  { return saved_args_base(); }

In a debug VM there is another slot pushed below the saved_args_base in _adapter_opt_collect/filter/fold; this is MAGIC_NUMBER_2.

The fix is to adjust extended_sender_sp in a debug VM.
                                     
2011-10-07
EVALUATION

It reproduces with a debug VM running C1:

(dbx) fr 8
Current function is MethodHandles::RicochetFrame::verify
  414     assert(magic_number_2() == MAGIC_NUMBER_2, err_msg(PTR_FORMAT " == " PTR_FORMAT, magic_number_2(), MAGIC_NUMBER_2));
(dbx) p this
this = 0xfdd9e0ac
(dbx) p *this
*this = {
    _continuation      = 0xfbf425ab
    _saved_target      = 0xe7b36508
    _saved_args_layout = (nil)
    _saved_args_base   = 0xfdd9e0d0
    _conversion        = -209914
    _exact_sender_sp   = 0xfdd9e0f0
    _sender_link       = 0xfdd9e0f0
    _sender_pc         = 0xfbf6650c "\x8b\xe5\x83\xf8"
}
(dbx) p findpc((long) this->_sender_pc)

"Executing findpc"
fbf6650c: Compiled {method} 'makeSite' '(Ljava/lang/invoke/MethodHandle;Ljava/lang/String;Ljava/lang/invoke/MethodType;Ljava/lang/Object;Ljava/lang/invoke/MemberName;I)Ljava/lang/invoke/CallSite;' in 'java/lang/invoke/CallSite'  = (CodeBlob*)0xfbf65d88
findpc((long ) this->_sender_pc) = (void)
(dbx) p ps()
 for thread: "main" prio=3 tid=0x0807bc00 nid=0x2 waiting on condition [0xfdd9d000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x0807bc00  [0x 2] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

 1 - frame( sp=0xfdd9e050, unextended_sp=0xfdd9e050, fp=0xfdd9e0c4, pc=0xfbf6e840)
java.lang.invoke.InvokeGeneric.dispatchWithConversion(InvokeGeneric.java:118)
 2 - frame( sp=0xfdd9e0d0, unextended_sp=0xfdd9e0f0, fp=0xfdd9e0f0, pc=0xfbf6650c)
java.lang.invoke.CallSite.makeSite(CallSite.java:306)
 3 - frame( sp=0xfdd9e1a0, unextended_sp=0xfdd9e1a0, fp=0xfdd9e220, pc=0xfbf61240)
java.lang.invoke.MethodHandleNatives.makeDynamicCallSite(MethodHandleNatives.java:305)
C frame (sp=0xfdd9e1d0 unextended sp=0xfdd9e1d0, fp=0xfdd9e220, pc=0xfbc003b1)
(~Stub::call_stub)
     BufferBlob (0xfbc00288) used for StubRoutines (1)

 4 - frame( sp=0xfdd9e55c, unextended_sp=0xfdd9e55c, fp=0xfdd9e584, pc=0xfbc14248)
test.java.lang.invoke.InvokeDynamicPrintArgs.main(InvokeDynamicPrintArgs.java:57)
C frame (sp=0xfdd9e58c unextended sp=0xfdd9e590, fp=0xfdd9e5c0, pc=0xfbc003b1)
(~Stub::call_stub)
     BufferBlob (0xfbc00288) used for StubRoutines (1)

 5 - frame( sp=0xfdd9ea70, unextended_sp=0xfdd9ea70, fp=0x00000000, pc=0xfbf3b49a)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 6 - frame( sp=0xfdd9eaa0, unextended_sp=0xfdd9eaa0, fp=0xfdd9eb94, pc=0xfbf3acb0)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
 7 - frame( sp=0xfdd9eb20, unextended_sp=0xfdd9eb20, fp=0xfdd9eb94, pc=0xfbf3a7d0)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 8 - frame( sp=0xfdd9eb50, unextended_sp=0xfdd9eb50, fp=0xfdd9eb94, pc=0xfbc03826)
java.lang.reflect.Method.invoke(Method.java:473)
 9 - frame( sp=0xfdd9eb9c, unextended_sp=0xfdd9eba0, fp=0xfdd9ebe4, pc=0xfbc032a8)
indify.Indify.runApplication(Indify.java:158)
10 - frame( sp=0xfdd9ebec, unextended_sp=0xfdd9ec00, fp=0xfdd9ec34, pc=0xfbc0343b)
indify.Indify.run(Indify.java:127)
11 - frame( sp=0xfdd9ec3c, unextended_sp=0xfdd9ec50, fp=0xfdd9ec84, pc=0xfbc0343b)
indify.Indify.main(Indify.java:106)
ps() = (void)
(dbx) p -f "%x" magic_number_1()
magic_number_1() = feed03e
(dbx) p -f "%x" magic_number_2() 
magic_number_2() = fbf67180
(dbx) p sizeof(RicochetFrame)
sizeof(class MethodHandles::RicochetFrame ) = 32
(dbx) x this - 1 / 64   
0xfdd9e08c:      0x00000029 0xfbcaacde 0xe7b35b08 0xe7b36248
0xfdd9e09c:      0xe7b362c0 0x00000000 0xfbf472ed 0x0feed03e
0xfdd9e0ac:      0xfbf425ab 0xe7b36508 0x00000000 0xfdd9e0d0
0xfdd9e0bc:      0xfffccc06 0xfdd9e0f0 0xfdd9e0f0 0xfbf6650c
0xfdd9e0cc:      0xfbf67180 0xe7b3c200 0xe7b358d8 0xe7b3c288
0xfdd9e0dc:      0xe7b3c2b8 0xe7b35b08 0xe7b36248 0x0000002a
0xfdd9e0ec:      0xe7b367c8 0xe7b3c288 0xe7b358d8 0xe7b3c200
0xfdd9e0fc:      0xfdd9e11c 0xfe15df96 0xe7b3c268 0xfe475d7e
0xfdd9e10c:      0xfe4761ee 0xfecbad78 0xfe4761e9 0xfdd9e158
0xfdd9e11c:      0xfe476291 0xfdd9e1f4 0x0000000c 0xe7b35b08
0xfdd9e12c:      0xe7b3c288 0xe7b02dd8 0xe7b3c2b8 0xfecbad78
0xfdd9e13c:      0xe7b3c200 0xe7b3c200 0x00000005 0xe7b3c228
0xfdd9e14c:      0x00000001 0xe7b35a28 0x080c0756 0xfdd9e170
0xfdd9e15c:      0xfe475e5c 0xfdd9e1f4 0x0000000c 0xfecbad78
0xfdd9e16c:      0xfe475e39 0xfdd9e1b0 0xfe7322ea 0x00000000
0xfdd9e17c:      0xfdd9e190 0xfe0f9ba1 0xfdd9e1f4 0xfbf6650c
(dbx) p events()
[Last 50 events in the event buffer]
-<thd>-<elapsed sec>-<description>---------------------
  3   25            | Deoptimization (pc=0xfbf6650c, sp=0xfdd9e0f0)
<snip>

The content of the stack slot of magic_number_2() points at the deopt MH handler of the compiled method CallSite.makeSite:

[Deopt MH Handler Code]
  0xfbf67180: push   $0xfbf67180        ;   {section_word}
  0xfbf67185: jmp    0xfbcac200         ;   {runtime_call}
                                     
2011-09-06



Hardware and Software, Engineered to Work Together