A customer reported serious issue that long integer value changes in sudden.
BEHAVIOR :
The followings are actual examples at customer site.
Decimal : 30045 -> 129042292438365
Hex. : 000000000000755D -> 0000755D0000755D
That seem the lower 4 byte are copied to the upper 4 bytes...
The long integer value are used for price and number of service point in e-commerce.
That's very serious for customers.
CONFIGURATION :
JRE : 1.3.1_06 Server
OS : Windows 2000/2003
REPRODUCING :
1) Compile attached programs.
2) Launch "java -server jikkena"
(When constructor is called 2000 or 3000 times, the problem occurs.)
REPRODUCIBILITY:
Intermittently
REPORTS from CUSTOMER INVESTIGATION :
- This issue occurs in all the 1.3.1, from fcs to _016
- This issue does not occur in 1.4.0fcs, and has not occurred in 1.4.x.
- Deopt. seems to occur at WPITPointData::<init>, otherwise this issue
might cause Deopt.
- This issue does not occur in 1.4.0/1.4.1/1.4.2/5.0 and Deopt. not occur
in those versions.
- We enabled TraceDeoptimization in product VM with modification for VM.
When the problem occurs, the following message shows up. (When the problem
does not occur, TraceDeoptimization log does not appear.)
-- TraceDeoptimization log --
Deoptimization: deoptimize frame (pc=0x9bbb5b, sp=0x7f98c)
- frames stored in vframeArray(0x2f78d30)
- turned (nmethod*)0x9ba090 into a non_entrant nmethod
Deoptimization: unpacking vframeArray(0x2f78d30)
>> {method} '<init>' '(Ljava/lang/String;Ljava/lang/String;Ljava/lang/Stri
ng;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava
-------------------------
/lang/String;Ljava/lang/String;Ljava/lang/String;JJJJLjava/lang/String;Ljava/lan
g/String;Ljava/lang/String;)V' in 'WPITPointData'
- As to the attached test programs, jikkena.java is the same to actual program.
WPITPointData.java is reduced to the minimum size. If the WPITPointData.java
is reduced smaller, the problem come not to occur.(Deopt. also not occur)
- The following is the log when the test program is executed.
Before the problem occurs, java.io class is compiled(compiling target method is changed),
Then the problem occurs.
--------------
.....
[LOG1] inType=inType,inHatuP=1,inSiyoP=2401,inPkin=4294967297,inPsu=0
[LOG2] inType=inType,inHatuP=1,inSiyoP=2401,inPkin=4294967297,inPsu=0
[LOG1] inType=inType,inHatuP=1,inSiyoP=2402,inPkin=4294967297,inPsu=0
[LOG2] inType=inType,inHatuP=1,inSiyoP=2402,inPkin=4294967297,inPsu=0
14 ! java.io.BufferedWriter::flushBuffer (53 bytes)
15 ! java.io.PrintStream::newLine (73 bytes)
[LOG1] inType=inType,inHatuP=4294967297,inSiyoP=10320806414691,inPkin=4294967297
,inPsu=0
[LOG2] inType=inType,inHatuP=4294967297,inSiyoP=10320806414691,inPkin=4294967297
,inPsu=0
exit2
---------------
=========================================================================
Customer has sent addtional information.
---- Additional information --->
We investigate the test programs.
(1) .hotspot_compiler
We specify .hotspot_compiler as follows.
exclude WPITPointData <init>
The timing when the problem occurs becomes a little bit later.
However, when jikkena#main is compiled, the same problem occurs.
We can workaround by adding the following line to .hotspot_compiler
exclude jikkena main
but can not do considering to the operation at our customers site.
(2) Information gotten in debugger
We have found out the code which breaks argument data
when main calls WPITointData.<init>.
We confirm how the code breaks data in debugger.
The following source code is the protion where main calls WPITointData.init.
for (inSiyoP = 0; inSiyoP > -1; inSiyoP++) {
WPITPointData data = new WPITPointData(
"inType", "inCustno", "inNYmdl", "inCkbn",
"inGno", "inMiseno", "inNDen", "inMotoNYmdl",
"inMotoDen", "inMotoPsrvcno",
inHatuP, inSiyoP, inPkin, inPsu,
"inPgid", "inTanto", "inWsno");
}
WPITointData.<init> expects the argument data should be stacked as follows.
----
#r000 ECX : parm 0: WPITPointData:NotNull *
#r005 EDX : parm 1: java/lang/String *
#r061 ESP+308: parm 21: java/lang/String *
#r060 ESP+304: parm 20: java/lang/String *
#r059 ESP+300: parm 19: java/lang/String *
#r058 ESP+296: parm 18: half
#r057 ESP+292: parm 17: long
#r056 ESP+288: parm 16: half
#r055 ESP+284: parm 15: long
#r054 ESP+280: parm 14: half
#r053 ESP+276: parm 13: long
#r052 ESP+272: parm 12: half
#r051 ESP+268: parm 11: long
#r050 ESP+264: parm 10: java/lang/String *
#r049 ESP+260: parm 9: java/lang/String *
#r048 ESP+256: parm 8: java/lang/String *
#r047 ESP+252: parm 7: java/lang/String *
#r046 ESP+248: parm 6: java/lang/String *
#r045 ESP+244: parm 5: java/lang/String *
#r044 ESP+240: parm 4: java/lang/String *
#r043 ESP+236: parm 3: java/lang/String *
#r042 ESP+232: parm 2: java/lang/String *
# -- Old ESP -- Framesize: 232 --
#r041 ESP+228: return address
#r040 ESP+224: pad2, in_preserve
#r039 ESP+220: Lock 13
........
-------
The following is the first part of compiled WPITointData.<init> code.
the arguments is broken in push/pop operations between 00A19EE4
and 00A19F31.
---
00A19EA2 sub esp,0E4h
00A19EB2 mov dword ptr [esp-0F1Ch],eax
00A19EB9 mov dword ptr [esp+0A4h],esi
00A19EC0 mov dword ptr [esp+0A0h],edi
00A19EC7 mov dword ptr [esp+9Ch],ebp
00A19ECE push dword ptr [esp+124h]
00A19ED5 pop dword ptr [esp+58h]
00A19ED9 push dword ptr [esp+128h]
00A19EE0 pop dword ptr [esp+5Ch]
00A19EE4 push dword ptr [esp+11Ch] <----
00A19EEB pop dword ptr [esp+120h]
00A19EF2 push dword ptr [esp+120h]
00A19EF9 pop dword ptr [esp+124h]
00A19F00 push dword ptr [esp+114h]
00A19F07 pop dword ptr [esp+118h]
00A19F0E push dword ptr [esp+118h]
00A19F15 pop dword ptr [esp+11Ch]
00A19F1C push dword ptr [esp+10Ch]
00A19F23 pop dword ptr [esp+110h]
00A19F2A push dword ptr [esp+110h]
00A19F31 pop dword ptr [esp+114h] <----
00A19F38 mov dword ptr [esp+54h],edx
00A19F3C mov dword ptr [esp+10Ch],ecx
00A19F43 mov eax,142B4F70h
----
2 pairs of push/pop operation between 00A19ECE and 00A19EE0,
which get variable "inPsu" from the interpreter frame to <init>
frame, are correct code.
However, 3 pairs of push/pop operations between 00A19EE4 and
00A19F31 seem incorrect. Those seems breaks the frames whcih
interpreter has stacked.
The following shows the status of stack.
The left side shows the status when main(interpreter) calls
WPITointData.<init> and stops at the 1st line of <init>.
The right side shows the status when push/pop between 00A19EE4
and 00A19F31 are executed.
esp+
0xef8 0006F980 44 53 A0 00 return addr
0xefc 0006F984 58 81 35 14 "inCustno" 58 81 35 14
0x0f0 0006F988 90 81 35 14 90 81 35 14
0x0f4 0006F98C C0 81 35 14 F0 81 35 14
0x0f8 0006F994 28 82 35 14 28 82 35 14
0x0fc 0006F998 58 82 35 14 58 82 35 14
0x100 0006F99C 98 82 35 14 98 82 35 14
0x104 0006F9A0 D0 82 35 14 D0 82 35 14
0x108 0006F9A4 10 83 35 14 "inMotoPsrvcno" 10 83 35 14
0x10c 0006F9A8 01 00 00 00 inHatuP 01 00 00 00
0x110 0006F9AC 00 00 00 00 01 00 00 00 inHatsuP
0x114 0006F9B0 C5 1D 00 00 inSiyoP 01 00 00 00
0x118 0006F9B4 00 00 00 00 C5 1D 00 00 inSiyoP
0x11c 0006F9B8 01 00 00 00 inPkin C5 1D 00 00
0x120 0006F9BC 01 00 00 00 01 00 00 00 inPkin
0x124 0006F9C0 00 00 00 00 inPsu 01 00 00 00
0x128 0006F9C4 00 00 00 00 00 00 00 00
0x12c 0006F9C8 40 83 35 14 40 83 35 14
Because Compiled <init> code understand, inHatusuP=0x6F9AC, inSiyoP=0x6F9B4,and inPkin=0x6F9BC, message is printed as follows.
[LOG1] inType=inType,inHatuP=4294967297,inSiyoP=32731945770437,
inPkin=4294967297,inPsu=0
FYI:
The following list is the compiled code of WPITointData.<init> when the test program works good.
0xa05ccc: subl 0x7c,%esp
0xa05cd2: movl %eax,-3972(%esp,1)
0xa05cd9: movl %esi,72(%esp,1)
0xa05cdd: movl %edi,68(%esp,1)
0xa05ce1: movl %ebp,64(%esp,1)
0xa05ce5: movl 188(%esp,1),%ebp
0xa05cec: movl 192(%esp,1),%edi
0xa05cf3: movl %ebp,16(%esp,1)
0xa05cf7: movl %edi,20(%esp,1)
0xa05cfb: movl 180(%esp,1),%ebp
0xa05d02: movl 184(%esp,1),%edi
0xa05d09: movl %ebp,56(%esp,1)
0xa05d0d: movl %edi,60(%esp,1)
0xa05d11: movl 172(%esp,1),%ebp
0xa05d18: movl 176(%esp,1),%edi
0xa05d1f: movl %ebp,48(%esp,1)
0xa05d23: movl %edi,52(%esp,1)
0xa05d27: movl 164(%esp,1),%ebp
0xa05d2e: movl 168(%esp,1),%edi
0xa05d35: movl %ebp,40(%esp,1)
0xa05d39: movl %edi,44(%esp,1)
0xa05d3d: movl %edx,180(%esp,1)
0xa05d44: movl %ecx,176(%esp,1)
0xa05d4b: movl 0x2bd790,%edi
The new test case arrived. I could resproduce in 1.3.1_16.
REPRODUCE:
1) Place the attached .hotspot_compiler and longtest.java to the same dir.
2) compile longtest.java
3) Invoke "java -server -Xcomp longtest"
----->
K:\shares2\bid6353457-Incorrect-long-value>java -server -showversion -Xcomp longtest
CompilerOracle: exclude longtest x
java version "1.3.1_16"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.1_16-b06)
Java HotSpot(TM) Server VM (build 1.3.1_16-b06, compiled mode)
### Excluding compile: longtest::x
0x100000001
<----
The longtest.java just try to convert one of argumanet(long) to hexString.
The value of targeteed argument is 1L, the result should be 0x1,
but the result is 0x100000001.
This behavior can always be reproduced.
NOTE:
The options, -Xcomp and .hotspot_compiler are not used in actual application of
licensee. Their application faces with this behavior without those options.
BEHAVIOR :
The followings are actual examples at customer site.
Decimal : 30045 -> 129042292438365
Hex. : 000000000000755D -> 0000755D0000755D
That seem the lower 4 byte are copied to the upper 4 bytes...
The long integer value are used for price and number of service point in e-commerce.
That's very serious for customers.
CONFIGURATION :
JRE : 1.3.1_06 Server
OS : Windows 2000/2003
REPRODUCING :
1) Compile attached programs.
2) Launch "java -server jikkena"
(When constructor is called 2000 or 3000 times, the problem occurs.)
REPRODUCIBILITY:
Intermittently
REPORTS from CUSTOMER INVESTIGATION :
- This issue occurs in all the 1.3.1, from fcs to _016
- This issue does not occur in 1.4.0fcs, and has not occurred in 1.4.x.
- Deopt. seems to occur at WPITPointData::<init>, otherwise this issue
might cause Deopt.
- This issue does not occur in 1.4.0/1.4.1/1.4.2/5.0 and Deopt. not occur
in those versions.
- We enabled TraceDeoptimization in product VM with modification for VM.
When the problem occurs, the following message shows up. (When the problem
does not occur, TraceDeoptimization log does not appear.)
-- TraceDeoptimization log --
Deoptimization: deoptimize frame (pc=0x9bbb5b, sp=0x7f98c)
- frames stored in vframeArray(0x2f78d30)
- turned (nmethod*)0x9ba090 into a non_entrant nmethod
Deoptimization: unpacking vframeArray(0x2f78d30)
>> {method} '<init>' '(Ljava/lang/String;Ljava/lang/String;Ljava/lang/Stri
ng;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava
-------------------------
/lang/String;Ljava/lang/String;Ljava/lang/String;JJJJLjava/lang/String;Ljava/lan
g/String;Ljava/lang/String;)V' in 'WPITPointData'
- As to the attached test programs, jikkena.java is the same to actual program.
WPITPointData.java is reduced to the minimum size. If the WPITPointData.java
is reduced smaller, the problem come not to occur.(Deopt. also not occur)
- The following is the log when the test program is executed.
Before the problem occurs, java.io class is compiled(compiling target method is changed),
Then the problem occurs.
--------------
.....
[LOG1] inType=inType,inHatuP=1,inSiyoP=2401,inPkin=4294967297,inPsu=0
[LOG2] inType=inType,inHatuP=1,inSiyoP=2401,inPkin=4294967297,inPsu=0
[LOG1] inType=inType,inHatuP=1,inSiyoP=2402,inPkin=4294967297,inPsu=0
[LOG2] inType=inType,inHatuP=1,inSiyoP=2402,inPkin=4294967297,inPsu=0
14 ! java.io.BufferedWriter::flushBuffer (53 bytes)
15 ! java.io.PrintStream::newLine (73 bytes)
[LOG1] inType=inType,inHatuP=4294967297,inSiyoP=10320806414691,inPkin=4294967297
,inPsu=0
[LOG2] inType=inType,inHatuP=4294967297,inSiyoP=10320806414691,inPkin=4294967297
,inPsu=0
exit2
---------------
=========================================================================
Customer has sent addtional information.
---- Additional information --->
We investigate the test programs.
(1) .hotspot_compiler
We specify .hotspot_compiler as follows.
exclude WPITPointData <init>
The timing when the problem occurs becomes a little bit later.
However, when jikkena#main is compiled, the same problem occurs.
We can workaround by adding the following line to .hotspot_compiler
exclude jikkena main
but can not do considering to the operation at our customers site.
(2) Information gotten in debugger
We have found out the code which breaks argument data
when main calls WPITointData.<init>.
We confirm how the code breaks data in debugger.
The following source code is the protion where main calls WPITointData.init.
for (inSiyoP = 0; inSiyoP > -1; inSiyoP++) {
WPITPointData data = new WPITPointData(
"inType", "inCustno", "inNYmdl", "inCkbn",
"inGno", "inMiseno", "inNDen", "inMotoNYmdl",
"inMotoDen", "inMotoPsrvcno",
inHatuP, inSiyoP, inPkin, inPsu,
"inPgid", "inTanto", "inWsno");
}
WPITointData.<init> expects the argument data should be stacked as follows.
----
#r000 ECX : parm 0: WPITPointData:NotNull *
#r005 EDX : parm 1: java/lang/String *
#r061 ESP+308: parm 21: java/lang/String *
#r060 ESP+304: parm 20: java/lang/String *
#r059 ESP+300: parm 19: java/lang/String *
#r058 ESP+296: parm 18: half
#r057 ESP+292: parm 17: long
#r056 ESP+288: parm 16: half
#r055 ESP+284: parm 15: long
#r054 ESP+280: parm 14: half
#r053 ESP+276: parm 13: long
#r052 ESP+272: parm 12: half
#r051 ESP+268: parm 11: long
#r050 ESP+264: parm 10: java/lang/String *
#r049 ESP+260: parm 9: java/lang/String *
#r048 ESP+256: parm 8: java/lang/String *
#r047 ESP+252: parm 7: java/lang/String *
#r046 ESP+248: parm 6: java/lang/String *
#r045 ESP+244: parm 5: java/lang/String *
#r044 ESP+240: parm 4: java/lang/String *
#r043 ESP+236: parm 3: java/lang/String *
#r042 ESP+232: parm 2: java/lang/String *
# -- Old ESP -- Framesize: 232 --
#r041 ESP+228: return address
#r040 ESP+224: pad2, in_preserve
#r039 ESP+220: Lock 13
........
-------
The following is the first part of compiled WPITointData.<init> code.
the arguments is broken in push/pop operations between 00A19EE4
and 00A19F31.
---
00A19EA2 sub esp,0E4h
00A19EB2 mov dword ptr [esp-0F1Ch],eax
00A19EB9 mov dword ptr [esp+0A4h],esi
00A19EC0 mov dword ptr [esp+0A0h],edi
00A19EC7 mov dword ptr [esp+9Ch],ebp
00A19ECE push dword ptr [esp+124h]
00A19ED5 pop dword ptr [esp+58h]
00A19ED9 push dword ptr [esp+128h]
00A19EE0 pop dword ptr [esp+5Ch]
00A19EE4 push dword ptr [esp+11Ch] <----
00A19EEB pop dword ptr [esp+120h]
00A19EF2 push dword ptr [esp+120h]
00A19EF9 pop dword ptr [esp+124h]
00A19F00 push dword ptr [esp+114h]
00A19F07 pop dword ptr [esp+118h]
00A19F0E push dword ptr [esp+118h]
00A19F15 pop dword ptr [esp+11Ch]
00A19F1C push dword ptr [esp+10Ch]
00A19F23 pop dword ptr [esp+110h]
00A19F2A push dword ptr [esp+110h]
00A19F31 pop dword ptr [esp+114h] <----
00A19F38 mov dword ptr [esp+54h],edx
00A19F3C mov dword ptr [esp+10Ch],ecx
00A19F43 mov eax,142B4F70h
----
2 pairs of push/pop operation between 00A19ECE and 00A19EE0,
which get variable "inPsu" from the interpreter frame to <init>
frame, are correct code.
However, 3 pairs of push/pop operations between 00A19EE4 and
00A19F31 seem incorrect. Those seems breaks the frames whcih
interpreter has stacked.
The following shows the status of stack.
The left side shows the status when main(interpreter) calls
WPITointData.<init> and stops at the 1st line of <init>.
The right side shows the status when push/pop between 00A19EE4
and 00A19F31 are executed.
esp+
0xef8 0006F980 44 53 A0 00 return addr
0xefc 0006F984 58 81 35 14 "inCustno" 58 81 35 14
0x0f0 0006F988 90 81 35 14 90 81 35 14
0x0f4 0006F98C C0 81 35 14 F0 81 35 14
0x0f8 0006F994 28 82 35 14 28 82 35 14
0x0fc 0006F998 58 82 35 14 58 82 35 14
0x100 0006F99C 98 82 35 14 98 82 35 14
0x104 0006F9A0 D0 82 35 14 D0 82 35 14
0x108 0006F9A4 10 83 35 14 "inMotoPsrvcno" 10 83 35 14
0x10c 0006F9A8 01 00 00 00 inHatuP 01 00 00 00
0x110 0006F9AC 00 00 00 00 01 00 00 00 inHatsuP
0x114 0006F9B0 C5 1D 00 00 inSiyoP 01 00 00 00
0x118 0006F9B4 00 00 00 00 C5 1D 00 00 inSiyoP
0x11c 0006F9B8 01 00 00 00 inPkin C5 1D 00 00
0x120 0006F9BC 01 00 00 00 01 00 00 00 inPkin
0x124 0006F9C0 00 00 00 00 inPsu 01 00 00 00
0x128 0006F9C4 00 00 00 00 00 00 00 00
0x12c 0006F9C8 40 83 35 14 40 83 35 14
Because Compiled <init> code understand, inHatusuP=0x6F9AC, inSiyoP=0x6F9B4,and inPkin=0x6F9BC, message is printed as follows.
[LOG1] inType=inType,inHatuP=4294967297,inSiyoP=32731945770437,
inPkin=4294967297,inPsu=0
FYI:
The following list is the compiled code of WPITointData.<init> when the test program works good.
0xa05ccc: subl 0x7c,%esp
0xa05cd2: movl %eax,-3972(%esp,1)
0xa05cd9: movl %esi,72(%esp,1)
0xa05cdd: movl %edi,68(%esp,1)
0xa05ce1: movl %ebp,64(%esp,1)
0xa05ce5: movl 188(%esp,1),%ebp
0xa05cec: movl 192(%esp,1),%edi
0xa05cf3: movl %ebp,16(%esp,1)
0xa05cf7: movl %edi,20(%esp,1)
0xa05cfb: movl 180(%esp,1),%ebp
0xa05d02: movl 184(%esp,1),%edi
0xa05d09: movl %ebp,56(%esp,1)
0xa05d0d: movl %edi,60(%esp,1)
0xa05d11: movl 172(%esp,1),%ebp
0xa05d18: movl 176(%esp,1),%edi
0xa05d1f: movl %ebp,48(%esp,1)
0xa05d23: movl %edi,52(%esp,1)
0xa05d27: movl 164(%esp,1),%ebp
0xa05d2e: movl 168(%esp,1),%edi
0xa05d35: movl %ebp,40(%esp,1)
0xa05d39: movl %edi,44(%esp,1)
0xa05d3d: movl %edx,180(%esp,1)
0xa05d44: movl %ecx,176(%esp,1)
0xa05d4b: movl 0x2bd790,%edi
The new test case arrived. I could resproduce in 1.3.1_16.
REPRODUCE:
1) Place the attached .hotspot_compiler and longtest.java to the same dir.
2) compile longtest.java
3) Invoke "java -server -Xcomp longtest"
----->
K:\shares2\bid6353457-Incorrect-long-value>java -server -showversion -Xcomp longtest
CompilerOracle: exclude longtest x
java version "1.3.1_16"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.1_16-b06)
Java HotSpot(TM) Server VM (build 1.3.1_16-b06, compiled mode)
### Excluding compile: longtest::x
0x100000001
<----
The longtest.java just try to convert one of argumanet(long) to hexString.
The value of targeteed argument is 1L, the result should be 0x1,
but the result is 0x100000001.
This behavior can always be reproduced.
NOTE:
The options, -Xcomp and .hotspot_compiler are not used in actual application of
licensee. Their application faces with this behavior without those options.
- relates to
-
JDK-4480951 JCK14, api/java_rmi, x86, b71, merlin, c2Xcomp, 10 tests failed
- Closed