JTReg test failure - zLinux : sun/nio/cs/TestStringCoding.java

[ben-walsh]

Intermittent failure ...

Testing(sm=true) US-ASCII....
STDERR:
java.lang.RuntimeException: getBytes(csn) failed  -> US-ASCII
	at TestStringCoding.testGetBytes(TestStringCoding.java:164)
	at TestStringCoding.main(TestStringCoding.java:82)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:825)

JavaTest Message: Test threw exception: java.lang.RuntimeException: getBytes(csn) failed  -> US-ASCII

... of test https://github.com/ibmruntimes/openj9-openjdk-jdk12/blob/openj9/test/jdk/sun/nio/cs/TestStringCoding.java observed on zLinux.

10x run showing 20% failure rate : consoleText.txt (external)
10x run showing 0% failure rate : consoleText.txt (internal)
100x run showing 3% failure rate : consoleText.txt (internal)
100x run showing 3% failure rate : consoleText.txt (internal)

100x run with -Xint (internal) is in progress - will update this comment with results

[fjeremic]

@dchopra001 can you take a look at this guy? I'm not aware of any recent changes in this area. The test is not too informative. i.e. it does not tell us what the byte arrays contained. Thankfully the test looks easy to modify so you can alter it to print out the failing arrays and that may give us a hint of what went wrong.

[ben-walsh]

The 100x run with -Xint (internal) is progressing extremely slow in comparison to the previous runs - 30+ minutes for each iteration - console log thus far : consoleText.txt
At this rate, we'll likely only get 20 iterations in before the 10 hour job time limit kicks in.
The first 4 iterations have passed but I'm not confident that tells us anything yet, given the observed failure rate without -Xint.

[ben-walsh]

18 complete iterations without any failure from the requested 100x -Xint run (internal) in 10 hours. It was then aborted per the Jenkins job timeout. Final console log : consoleText.txt

[ben-walsh]

@fjeremic @pshipton Let me know if there is anything else you need me to try.

[smlambert]

Excluded via: adoptium/aqa-tests#1031 and adoptium/aqa-tests#1032

[dchopra001]

I've managed to reproduce this at a 100% rate with a local/modified version of the StringCoding test. Here's a sample output of what the two byte arrays look like in a failing run:

Testing(sm=true) US-ASCII.... 
baSC(firstArray):
0 1 2 3 4 5 6 7 8 9 a b c d 3f 10 11 12 13 14 15 16 17 18 19 1a 1b
baNIO(secondArray):
0 1 2 3 4 5 3f 7 8 9 a b c d 3f 10 11 12 13 14 15 16 17 18 19 1a 1b
Exception in thread "main" java.lang.RuntimeException: getBytes(csn) failed  -> US-ASCII
	at TestStringCoding.testGetBytes(TestStringCoding.java:182)
	at TestStringCoding.main(TestStringCoding.java:85)

In the second array we have a 3f instead of 6. A similar pattern is seen among other failures. Instead of an actual failures we see 3f.

I'm trying to narrow the problem down further right now.

[mstoodle]

Any update here @dchopra001 ? Do we have any better understanding of the source of the mysterious 3f ?

[dchopra001]

Status Update

I have the problem narrowed down to the sub optimization that is causing the issue. I am still not sure if this is an optimization or codegen issue. Right now I am leaning towards an edge case being missed in the codegen. More details about the problem below.

During Value Propagation, we identify the icall node inside this block:

34822 n149n     BBStart <block_16>                                                                  [     0x3ff66aefe50] bci=[-1,142,194] rc=0 vc=702 vn=- li=- udi=- nc=0
 34823 n161n     treetop                                                                             [     0x3ff66af0210] bci=[-1,155,194] rc=0 vc=702 vn=- li=- udi=- nc=1
 34824 n160n       icall  sun/nio/cs/US_ASCII$Encoder.encodeASCII([CII[BI)I[#477  final special Method] [flags 0x20500 0x0 ] ()  [     0x3ff66af01c0] bci=[-1,155,194] rc=2 vc=702 vn=- li=- udi=- nc=6 flg=0x20
 34825 n152n         aload  this<'this' parm Lsun/nio/cs/US_ASCII$Encoder;>[#442  Parm] [flags 0x40000107 0x0 ] (X!=0 sharedMemory )  [     0x3ff66aeff40] bci=[-1,142,194] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x4
 34826 n153n         aload  sa<auto slot 3>[#447  Auto] [flags 0x7 0x0 ]                             [     0x3ff66aeff90] bci=[-1,143,194] rc=1 vc=702 vn=- li=- udi=- nc=0
 34827 n154n         iload  sp<auto slot 4>[#452  Auto] [flags 0x3 0x0 ] (cannotOverflow )           [     0x3ff66aeffe0] bci=[-1,144,194] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34828 n157n         isub                                                                            [     0x3ff66af00d0] bci=[-1,150,194] rc=1 vc=702 vn=- li=- udi=- nc=2
 34829 n155n           iload  sl<auto slot 5>[#455  Auto] [flags 0x3 0x0 ] (cannotOverflow )         [     0x3ff66af0030] bci=[-1,146,194] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34830 n156n           iload  sp<auto slot 4>[#452  Auto] [flags 0x3 0x0 ] (cannotOverflow )         [     0x3ff66af0080] bci=[-1,148,194] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34831 n158n         aload  da<auto slot 6>[#462  Auto] [flags 0x7 0x0 ]                             [     0x3ff66af0120] bci=[-1,151,194] rc=1 vc=702 vn=- li=- udi=- nc=0
 34832 n159n         iload  dp<auto slot 7>[#467  Auto] [flags 0x3 0x0 ] (cannotOverflow )           [     0x3ff66af0170] bci=[-1,153,194] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34833 n162n     istore  n<auto slot 9>[#478  Auto] [flags 0x3 0x0 ]                                 [     0x3ff66af0260] bci=[-1,158,194] rc=0 vc=702 vn=- li=- udi=- nc=1
 34834 n160n       ==>icall
 34835 n166n     istore  sp<auto slot 4>[#452  Auto] [flags 0x3 0x0 ]                                [     0x3ff66af03a0] bci=[-1,165,195] rc=0 vc=702 vn=- li=- udi=- nc=1
 34836 n165n       iadd                                                                              [     0x3ff66af0350] bci=[-1,164,195] rc=1 vc=702 vn=- li=- udi=- nc=2
 34837 n163n         iload  sp<auto slot 4>[#452  Auto] [flags 0x3 0x0 ] (cannotOverflow )           [     0x3ff66af02b0] bci=[-1,160,195] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34838 n164n         iload  n<auto slot 9>[#478  Auto] [flags 0x3 0x0 ] (cannotOverflow )            [     0x3ff66af0300] bci=[-1,162,195] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34839 n170n     istore  dp<auto slot 7>[#467  Auto] [flags 0x3 0x0 ]                                [     0x3ff66af04e0] bci=[-1,172,196] rc=0 vc=702 vn=- li=- udi=- nc=1
 34840 n169n       iadd                                                                              [     0x3ff66af0490] bci=[-1,171,196] rc=1 vc=702 vn=- li=- udi=- nc=2
 34841 n167n         iload  dp<auto slot 7>[#467  Auto] [flags 0x3 0x0 ] (cannotOverflow )           [     0x3ff66af03f0] bci=[-1,167,196] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34842 n168n         iload  n<auto slot 9>[#478  Auto] [flags 0x3 0x0 ] (cannotOverflow )            [     0x3ff66af0440] bci=[-1,169,196] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34843 n175n     ificmpge --> block_22 BBStart at n15n ()                                            [     0x3ff66af0670] bci=[-1,178,198] rc=0 vc=702 vn=- li=- udi=- nc=2 flg=0x20
 34844 n171n       iload  sp<auto slot 4>[#452  Auto] [flags 0x3 0x0 ] (cannotOverflow )             [     0x3ff66af0530] bci=[-1,174,198] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34845 n172n       iload  sl<auto slot 5>[#455  Auto] [flags 0x3 0x0 ] (cannotOverflow )             [     0x3ff66af0580] bci=[-1,176,198] rc=1 vc=702 vn=- li=- udi=- nc=0 flg=0x1000
 34846 n150n     BBEnd </block_16> =====                                                             [     0x3ff66aefea0] bci=[-1,178,198] rc=0 vc=701 vn=- li=- udi=- nc=0

And inline it into an arraytranslate node. After tracing this optimization the trees show the following new arraytranslate post inlining (the tracing doesn't say much else about the inlining):

 38718 n4178n    BBStart <block_301>                                                                 [     0x3ff66efe9b0] bci=[-1,155,194] rc=0 vc=0 vn=- li=- udi=- nc=0
 38719 n4127n    treetop                                                                             [     0x3ff66d2d9b0] bci=[-1,155,194] rc=0 vc=702 vn=- li=- udi=- nc=1
 38720 n4153n      arraytranslate  <arraytranslate>[#381  helper Method] [flags 0x400 0x0 ] (char2byteXlate byteArrayXlate tableBackedByRawStorage )  [     0x3ff66efe1e0] bci=[-1,155,194] rc=2 vc=0 vn=- li=- udi=- nc=6 flg=0xa020
 38721 n4157n        aladd                                                                           [     0x3ff66efe320] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=2
 38722 n4144n          aload  <temp slot 53>[#750  Auto] [flags 0x7 0x0 ]                            [     0x3ff66d2df00] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38723 n4156n          ladd                                                                          [     0x3ff66efe2d0] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=2
 38724 n4155n            lmul                                                                        [     0x3ff66efe280] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=2
 38725 n4146n              i2l                                                                       [     0x3ff66d2dfa0] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=1
 38726 n4145n                iload  <temp slot 52>[#749  Auto] [flags 0x10003 0x0 ]                  [     0x3ff66d2df50] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38727 n4154n              lconst 2                                                                  [     0x3ff66efe230] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38728 n4152n            lconst 8                                                                    [     0x3ff66efe190] bci=[-1,155,194] rc=2 vc=0 vn=- li=- udi=- nc=0
 38729 n4159n        aladd                                                                           [     0x3ff66efe3c0] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=2
 38730 n4149n          aload  da<auto slot 6>[#462  Auto] [flags 0x7 0x0 ]                           [     0x3ff66efe0a0] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38731 n4158n          ladd                                                                          [     0x3ff66efe370] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=2
 38732 n4151n            i2l                                                                         [     0x3ff66efe140] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=1
 38733 n4150n              iload  dp<auto slot 7>[#467  Auto] [flags 0x3 0x0 ]                       [     0x3ff66efe0f0] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38734 n4152n            ==>lconst 8
 38735 n4160n        aconst NULL                                                                     [     0x3ff66efe410] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38736 n4161n        iconst 255                                                                      [     0x3ff66efe460] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38737 n4148n        i2l                                                                             [     0x3ff66efe050] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=1
 38738 n4147n          iload  <temp slot 51>[#748  Auto] [flags 0x10003 0x0 ]                        [     0x3ff66efe000] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38739 n4162n        iconst 127                                                                      [     0x3ff66efe4b0] bci=[-1,155,194] rc=1 vc=0 vn=- li=- udi=- nc=0
 38740 n4188n    istore  <temp slot 55>[#752  Auto] [flags 0x3 0x0 ]                                 [     0x3ff66efecd0] bci=[-1,155,194] rc=0 vc=0 vn=- li=- udi=- nc=1
 38741 n4153n      ==>arraytranslate
 38742 n4190n    asynccheck  jitCheckAsyncMessages[#22  helper Method] [flags 0x400 0x0 ]            [     0x3ff66efed70] bci=[-1,155,194] rc=0 vc=0 vn=- li=- udi=- nc=0
 38743 n4179n    BBEnd </block_301> =====                                                            [     0x3ff66efea00] bci=[-1,155,194] rc=0 vc=0 vn=- li=- udi=- nc=0

I'm looking into the instructions generated right now to see if we perhaps missed an edge case.

@andrewcraik FYI - I don't think this is related to optimizer but tagging you just in case you notice something in the trees above or have any other insight regarding the opt.

[fjeremic]

@dchopra001 are you able to hop in the debugger and validate what the JIT is doing at the codegen level? We will evaluate arraytranslate into some form of TRTO (translate) instruction or similar which uses a precomputed static table to do the translation. It's possible we have a codegen bug there assuming the optimizer transformed the trees correctly.