United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-7141329 JSR 292: Strange values of stack_size in -XX:+TraceMethodHandles output
JDK-7141329 : JSR 292: Strange values of stack_size in -XX:+TraceMethodHandles output

Details
Type:
Bug
Submit Date:
2012-01-31
Status:
Closed
Updated Date:
2012-03-24
Project Name:
JDK
Resolved Date:
2012-03-24
Component:
hotspot
OS:
generic
Sub-Component:
compiler
CPU:
generic
Priority:
P5
Resolution:
Fixed
Affected Versions:
hs23
Fixed Versions:
hs23 (b16)

Related Reports
Backport:
Backport:
Relates:

Sub Tasks

Description
During verification of 7120468, I noticed that stack_size in output can be negative or very big. Before 7120468, it was always zero.

Examples:

MH bound_ref rcx_mh=0xdb7579c8
sp=(0xf6d41ee4+3) stack_size=114797400 bp=0xf6d41ee4
MH bound_ref rcx_mh=0xdb7575b8
sp=(0xf6d41ee0+4) stack_size=0 bp=0xf6d41ee0
MH adapter_retype_only rcx_mh=0xdb757970
sp=(0xf6d41edc+5) stack_size=24978944 bp=0xf6d41edc
MH invokespecial rcx_mh=0xdb757840
sp=(0xf6d41edc+5) stack_size=24978944 bp=0xf6d41edc
MH invokeExact rcx_mh=0xdb74a9a8
sp=(0xf6d41f30+4) stack_size=0 bp=0xf6d41f30
MH bound_ref_direct rcx_mh=0xdb74a9a8
sp=(0xf6d41f30+4) stack_size=0 bp=0xf6d41f30
MH invokeExact rcx_mh=0xdb757e18
sp=(0xf6d41f30+4) stack_size=0 bp=0xf6d41f30
MH bound_ref rcx_mh=0xdb757e18
sp=(0xf6d41f30+4) stack_size=0 bp=0xf6d41f30
MH bound_ref rcx_mh=0xdb757d70
sp=(0xf6d41f2c+5) stack_size=-38467641 bp=0xf6d41f2c
MH bound_ref_direct rcx_mh=0xdb757c18
sp=(0xf6d41f28+6) stack_size=0 bp=0xf6d41f28
MH invokeExact rcx_mh=0xdb7572c0
sp=(0xf6d41ee0+4) stack_size=0 bp=0xf6d41ee0


MH invokeExact rcx_mh=0xdb757e18
sp=(0xf6d41f30+4) stack_size=0 bp=0xf6d41f30
MH bound_ref rcx_mh=0xdb757e18
sp=(0xf6d41f30+4) stack_size=0 bp=0xf6d41f30
MH bound_ref rcx_mh=0xdb757d70
sp=(0xf6d41f2c+5) stack_size=-38467641 bp=0xf6d41f2c
MH bound_ref_direct rcx_mh=0xdb757c18
sp=(0xf6d41f28+6) stack_size=0 bp=0xf6d41f28
MH invokeExact rcx_mh=0xdb7572c0
sp=(0xf6d41ee0+4) stack_size=0 bp=0xf6d41ee0

MH bound_ref rcx_mh=0xdb757e18
sp=(0xf6d41f30+4) stack_size=0 bp=0xf6d41f30
MH bound_ref rcx_mh=0xdb757d70
sp=(0xf6d41f2c+5) stack_size=-38467641 bp=0xf6d41f2c
MH bound_ref_direct rcx_mh=0xdb757c18
sp=(0xf6d41f28+6) stack_size=0 bp=0xf6d41f28
MH invokeExact rcx_mh=0xdb7572c0
sp=(0xf6d41ee0+4) stack_size=0 bp=0xf6d41ee0

                                    

Comments
EVALUATION

Hi JSR292 folks,

This bug has been assigned to me because of 7120468 but it was not introduced by my changes. More exactly, my changes have cause an existing a bug to exhibit a different behavior, easier to catch by the QA.

In short, the simplest fix is to stop dumping last_sp, base_sp, saved_bp
and everything depending on them since they were false and were not fixed by my change.

Unless you just want me to remove all this lines and putback, someone else should take ownership of the bug. In fact, if you'd like the fix soon, a volunteer would be welcome even in that case because I have other priorities right now.

Full explanation:

If you look at previous output, you will see that saved_bp was not correct before my fix (and that the stack_size was always 0):
MH invokespecial rcx_mh=0xe47c9d98 sp=(0xfc61dc1c+-4) stack_size=0 bp=0xfc61dbe0
MH invokeExact rcx_mh=0xe47ceb40 sp=(0xfc61dc1c+-4) stack_size=0 bp=0xfc61dbe0
MH adapter_filter/S0/ref rcx_mh=0xe47ceb40 sp=(0xfc61dc1c+-4) stack_size=0 bp=0xfc61dbe0
MH adapter_retype_only rcx_mh=0xe47caae8 sp=(0xfc61dbe8+-4) stack_size=0 bp=0xfc61dbac
MH invokestatic rcx_mh=0xe47caad0 sp=(0xfc61dbe8+-4) stack_size=0 bp=0xfc61dbac
MH return/ricochet_blob.bounce rcx=0xfc61dbb0 sp=(0xfc61dbec+-12962799) stack_size=0 bp=0xfc61dbb0

That wrong saved_bp is/was used to compute a bad last_sp and a bad base_sp. I did not change that code.

The real bug is that:
- saved_bp is still false
- the computation of last_sp and base_sp is not so trivial, even
 if saved_bp was really the BP of the caller frame (see for
 instance the use of BP in compiled frames).

My changes cause saved_bp to be slightly different. Previously, it was SP after several pushes done in trace_method_handle and an enter call. I moved the enter earlier to create a proper frame. This means that saved_bp is now the same as entry sp, instead of pointing into the new frame. Unfortunately, when mapping a RicochetFrame at the old (bad) saved_bp address, the old code was always finding a stack address (probably saved_regs but I did not check the exact slot). Hence, the test
"Universe::heap()->is_in((address) rfp->saved_args_base())"
always failed, causing base_sp not to be updated and stack_size to be 0.

With my change, rfp->saved_args_base() now falls into the saved registers, which has more random values. Hence, the previous test sometimes succeeds, causing  a bad base_sp to be used and thus arbitrary stack sizes instead of 0. That different erroneous behavior was easier to catch by the QA :-)

As stated above, If I were to do the fix, I would just remove the printing of last_sp, base_sp and stack_size that can be wrong (and hence confusing) in some cases. To get more information, one can set +Verbose and dump the caller frame in a safe manner. The good news is that my new code no longer depends on saved_bp, last_sp and base_sp when dumping verbose information :-)

I would also stop dumping saved_bp. I will not try to fix saved_bp because that would need to be tested and I do not have time for that now :-)

If someone thinks we should not just stop printing this bad info and would instead prefer to have it fixed, he should volunteer for the bug :-)

Bertrand.
                                     
2012-02-10
EVALUATION

http://hg.openjdk.java.net/hsx/hotspot-comp/hotspot/rev/45a1bf98f1bb
                                     
2012-02-13
EVALUATION

http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/45a1bf98f1bb
                                     
2012-02-18
EVALUATION

http://hg.openjdk.java.net/lambda/lambda/hotspot/rev/45a1bf98f1bb
                                     
2012-03-22



Hardware and Software, Engineered to Work Together