ParallelStreamsLoadTest_special_J9_24 hang/timeout at 100%

pshipton commented 3 years ago

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0/10 ParallelStreamsLoadTest_special_J9_24 variation: Mode107-OSRG JVM_OPTIONS: -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation There are 3 core files https://140-211-168-230-openstack.osuosl.org/artifactory/ci-eclipse-openj9/Test/Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0/10/system_test_output.tar.gz

LT  15:57:20.024 - Completed 100.0%. Number of tests started=2
LT  15:57:40.540 - Completed 100.0%. Number of tests started=2 (+0)
LT  15:58:00.024 - Completed 100.0%. Number of tests started=2 (+0)
...
LT  16:55:00.073 - Completed 100.0%. Number of tests started=2 (+0)
LT  16:55:19.979 - Completed 100.0%. Number of tests started=2 (+0)
LT  16:55:40.026 - Completed 100.0%. Number of tests started=2 (+0)
STF 16:55:53.387 - Heartbeat: Process LT  is still running
STF 16:55:55.449 - **FAILED** Process LT  has timed out
STF 16:55:55.449 - Collecting dumps for: LT

First core shows these interesting threads:

  thread id: 14080
   registers:
    gs     = 0x0000002b   fs     = 0x00000053   es     = 0x0000002b   ds     = 0x0000002b
    edi    = 0x436a0630   esi    = 0x436add48   ebx    = 0x7155f3c8   edx    = 0x00000000
    ecx    = 0x00000000   eax    = 0x00000000   ebp    = 0x49a6eb14   eip    = 0x7709c38c
    cs     = 0x00000023   flags  = 0x00000202   esp    = 0x49a6eaf8   ss     = 0x0000002b
   native stack sections:
    0x49a6eaf4 to 0x49a70000 (length 0x150c)
   native stack frames:
    bp: 0x49a6eb14 pc: 0x7709c38c C:\Windows\System32\ntdll.dll::NtQueryPerformanceCounter+0xc
    bp: 0x49a6eb98 pc: 0x7137c9fd F:\Users\jenkins\workspace\Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0\openjdkbinary\j2sdk-image\jre\bin\default\j9prt29.dll::j9port_isCompatible+0xa44d
    bp: 0x7125ec98 pc: 0x712dc90a F:\Users\jenkins\workspace\Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0\openjdkbinary\j2sdk-image\jre\bin\default\j9trc29.dll::JVM_OnUnload+0x621a
   properties:
    Affinity=0x00000000000000FF                CreateTime=132572086201027120
    CreateTime_Formatted=2021/02/07 16:57:00   DumpError=0x00000000
    DumpFlags=0x00000000                       ExitStatus=0x00000103
    ExitTime=0                                 KernelTime=30770937500
    StartAddress=0x7163BFB4                    UserTime=2567187500
    priority=0                                 priorityClass=32
   associated Java thread: 
    name:          load-0
    Thread object: java/lang/Thread @ 0x1e0b290
    Native info:   !j9vmthread 0x436a0100  !stack 0x436a0100
    Daemon:        false
    ID:            25 (0x19)
    Priority:      5
    Thread.State:  RUNNABLE 
    JVMTI state:   ALIVE RUNNABLE 
    Java stack frames: 
     bp: 0x47fcd7d4  method: void java/util/regex/Pattern$Start.<init>(java.util.regex.Pattern$Node)  source: Pattern.java:3465
      objects: 0x15243f00 0x15243de8 0x15243f10 0x15243de8 0x15243f10
     bp: 0x47fcd818  method: void java/util/regex/Pattern.compile()  source: Pattern.java:1722
      objects: 0x15243cb8 0x15243f00 0x15243cb8 0x15243f00 0x15243cb8
     bp: 0x47fcd860  method: void java/util/regex/Pattern.<init>(String, int)  source: Pattern.java:1352
      objects: 0x3674ec8 0x15243cb8
     bp: 0x47fcd874  method: java.util.regex.Pattern java/util/regex/Pattern.compile(String)  source: Pattern.java:1028
      objects: 0x3674ec8 0x15243cb8 0x15243cb8
     bp: 0x47fcd8d8  method: String java/lang/String.replaceAll(String, String)  source: String.java:3589
      objects: 0x184cee8 0x3674ec8 0x1523e1a8 0x184cee8
     bp: 0x47fcd9bc  method: java.util.ArrayList net/adoptopenjdk/test/streams/support/Line.getWords()  source: Line.java:62
      objects: 0x1ad1d18 0x1523e3a8 0x1523e3a8 0x1523e6f0 0x1523e6f0 0x1523e6f0 0x1523e6f0 0x1523e188 0x1523e1a8 0x1523e320 0x1523e3a8 0x1523e3a8 0x1523e320 0x1ad1d28
     bp: 0x00000000  method: java.util.stream.Stream net/adoptopenjdk/test/streams/TestParallelStreamOperations.lambda$null$25(net.adoptopenjdk.test.streams.support.Line)  source: TestParallelStreamOperations.java:311
      objects: <no objects in this frame>
     bp: 0x47fcd9e4  method: Object net/adoptopenjdk/test/streams/TestParallelStreamOperations$$Lambda$59/0x00000000.apply(Object)  source: null:<data unavailable>
      objects: 0x1ad1d18 0x14432558 0x1ad1d18
     bp: 0x47fcda18  method: void java/util/stream/ReferencePipeline$7$1.accept(Object)  source: ReferencePipeline.java:269
      objects: 0x1ad1d18 0x109571b8 0x109571b8
     bp: 0x47fcda50  method: void java/util/ArrayList$ArrayListSpliterator.forEachRemaining(java.util.function.Consumer)  source: ArrayList.java:1384
      objects: 0x109571b8 0x10957048 0x1ad1d18 0x5440050 0x1a529f0
     bp: 0x00000000  method: void java/util/stream/AbstractPipeline.copyInto(java.util.stream.Sink, java.util.Spliterator)  source: AbstractPipeline.java:497
      objects: <no objects in this frame>
     bp: 0x47fcda88  method: java.util.stream.Sink java/util/stream/AbstractPipeline.wrapAndCopyInto(java.util.stream.Sink, java.util.Spliterator)  source: AbstractPipeline.java:487
      objects: 0x10957048 0x109571a0 0x10957098 0x109571b8 0x109571b8 0x10957098 0x10957098 0x109571b8
     bp: 0x47fcdaa8  method: Object java/util/stream/ReduceOps$ReduceOp.evaluateSequential(java.util.stream.PipelineHelper, java.util.Spliterator)  source: ReduceOps.java:708
      objects: 0x10957048 0x10957098 0x10957180 0x10957098
     bp: 0x47fcdac0  method: Object java/util/stream/AbstractPipeline.evaluate(java.util.stream.TerminalOp)  source: AbstractPipeline.java:241
      objects: 0x10957098 0x10957180
     bp: 0x47fcdadc  method: Object java/util/stream/ReferencePipeline.collect(java.util.stream.Collector)  source: ReferencePipeline.java:566
      objects: <no objects in this frame>
     bp: 0x47fcdb44  method: void net/adoptopenjdk/test/streams/TestParallelStreamOperations.lambda$testCommonWord$27()  source: TestParallelStreamOperations.java:312
      objects: 0x1a529f0 0x59ae0c0 0x50d09d0 0x4a96f00 0x4a96f18 0x106c5d88 0x110f20e0 0xf2513c8
     bp: 0x47fcdb50  method: void net/adoptopenjdk/test/streams/TestParallelStreamOperations$$Lambda$39/0x00000000.run()  source: null:<data unavailable>
      objects: 0x4ee7350
     bp: 0x47fcdb8c  method: void net/adoptopenjdk/test/streams/TestParallelStreamOperations.runTest(net.adoptopenjdk.test.streams.TestParallelStreamOperations$LimitedTest)  source: TestParallelStreamOperations.java:343
      objects: 0x4ee7350 0x4835810
     bp: 0x47fcdb9c  method: void net/adoptopenjdk/test/streams/TestParallelStreamOperations.testCommonWord()  source: TestParallelStreamOperations.java:244
      objects: 0x4835810
     bp: 0x47fcdbd0  method: Object sun/reflect/NativeMethodAccessorImpl.invoke0(reflect.Method, Object, Object[])  (Native Method)
      objects: 0x1da9178 0x4835810 0x4835840
     bp: 0x47fcdc3c  method: Object sun/reflect/NativeMethodAccessorImpl.invoke(Object, Object[])  source: NativeMethodAccessorImpl.java:62
      objects: 0x4835840 0x4835810 0x50c6278
     bp: 0x47fcdc5c  method: Object sun/reflect/DelegatingMethodAccessorImpl.invoke(Object, Object[])  source: DelegatingMethodAccessorImpl.java:43
      objects: 0x4835840 0x4835810 0x50c6290
     bp: 0x00000000  method: Object java/lang/reflect/Method.invoke(Object, Object[])  source: Method.java:498
      objects: <no objects in this frame>
     bp: 0x47fcdc88  method: Object org/junit/runners/model/FrameworkMethod$1.runReflectiveCall()  source: FrameworkMethod.java:50
      objects: 0x4835850 0x1da1a40 0x50c6290 0x4835840 0x4835810
     bp: 0x47fcdcc0  method: Object org/junit/internal/runners/model/ReflectiveCallable.run()  source: ReflectiveCallable.java:12
      objects: 0x4835850
     bp: 0x00000000  method: Object org/junit/runners/model/FrameworkMethod.invokeExplosively(Object, Object[])  source: FrameworkMethod.java:47
      objects: <no objects in this frame>
     bp: 0x47fcdcec  method: void org/junit/internal/runners/statements/InvokeMethod.evaluate()  source: InvokeMethod.java:17
      objects: 0x4835820 0x4835850 0x4835810 0x1ddadd0 0x4835840
     bp: 0x47fcdd28  method: void org/junit/runners/ParentRunner.runLeaf(org.junit.runners.model.Statement, org.junit.runner.Description, org.junit.runner.notification.RunNotifier)  source: ParentRunner.java:325
      objects: 0x191a590 0x198c508 0x4835820 0x1d12918 0x4835830 0x4835830 0x4835830
     bp: 0x00000000  method: void org/junit/runners/BlockJUnit4ClassRunner.runChild(org.junit.runners.model.FrameworkMethod, org.junit.runner.notification.RunNotifier)  source: BlockJUnit4ClassRunner.java:78
      objects: <no objects in this frame>
     bp: 0x47fcdd54  method: void org/junit/runners/BlockJUnit4ClassRunner.runChild(Object, org.junit.runner.notification.RunNotifier)  source: BlockJUnit4ClassRunner.java:57
      objects: 0x191a590 0x1ddadd0 0x1d12918 0x1d12918 0x198c508 0x1ddadd0 0x1d12918
     bp: 0x47fcdd60  method: void org/junit/runners/ParentRunner$3.run()  source: ParentRunner.java:290
      objects: 0x48357f8
     bp: 0x47fcdd70  method: void org/junit/runners/ParentRunner$1.schedule(Runnable)  source: ParentRunner.java:71
      objects: 0x48357f8 0x1d23f20
     bp: 0x47fcddbc  method: void org/junit/runners/ParentRunner.runChildren(org.junit.runner.notification.RunNotifier)  source: ParentRunner.java:288
      objects: 0x191a590 0x1d12918 0x48357f8 0x1d23f20 0x1ddadd0 0x19f9690 0x1d23f20 0x19f9690
     bp: 0x00000000  method: void org/junit/runners/ParentRunner.access$000(org.junit.runners.ParentRunner, org.junit.runner.notification.RunNotifier)  source: ParentRunner.java:58
      objects: <no objects in this frame>
     bp: 0x47fcddd0  method: void org/junit/runners/ParentRunner$2.evaluate()  source: ParentRunner.java:268
      objects: 0x19f8e48 0x191a590 0x1d12918
     bp: 0x47fcde1c  method: void org/junit/runners/ParentRunner.run(org.junit.runner.notification.RunNotifier)  source: ParentRunner.java:363
      objects: 0x191a590 0x1d12918 0x19f8e48 0x19f8d98 0x191a590 0x19f8d98 0x19f8d98
     bp: 0x47fcde38  method: void org/junit/runners/Suite.runChild(org.junit.runner.Runner, org.junit.runner.notification.RunNotifier)  source: Suite.java:128
      objects: 0x1c52738 0x1d12918 0x191a590
     bp: 0x47fcde50  method: void org/junit/runners/Suite.runChild(Object, org.junit.runner.notification.RunNotifier)  source: Suite.java:27
      objects: 0x1c52738 0x1d12918 0x191a590
     bp: 0x47fcde60  method: void org/junit/runners/ParentRunner$3.run()  source: ParentRunner.java:290
      objects: 0x19f5df0
     bp: 0x47fcde74  method: void org/junit/runners/ParentRunner$1.schedule(Runnable)  source: ParentRunner.java:71
      objects: 0x190ac68 0x19f5df0
     bp: 0x47fcde98  method: void org/junit/runners/ParentRunner.runChildren(org.junit.runner.notification.RunNotifier)  source: ParentRunner.java:288
      objects: 0x1c52738 0x191a590 0x190ac68 0x19d2e50 0x1d12918
     bp: 0x47fcdeac  method: void org/junit/runners/ParentRunner.access$000(org.junit.runners.ParentRunner, org.junit.runner.notification.RunNotifier)  source: ParentRunner.java:58
      objects: 0x1c52738 0x191a590
     bp: 0x47fcdebc  method: void org/junit/runners/ParentRunner$2.evaluate()  source: ParentRunner.java:268
      objects: 0x19bdad8
     bp: 0x47fcded8  method: void org/junit/runners/ParentRunner.run(org.junit.runner.notification.RunNotifier)  source: ParentRunner.java:363
      objects: 0x1c52738 0x191a590 0x19bbda0 0x19bdad8
     bp: 0x47fcdef8  method: org.junit.runner.Result org/junit/runner/JUnitCore.run(org.junit.runner.Runner)  source: JUnitCore.java:137
      objects: 0x19059d8 0x1c52738 0x1933208 0x1941510
     bp: 0x47fcdf0c  method: org.junit.runner.Result org/junit/runner/JUnitCore.run(org.junit.runner.Request)  source: JUnitCore.java:115
      objects: 0x19059d8 0x190ef30
     bp: 0x47fcdf44  method: net.adoptopenjdk.loadTest.adaptors.AdaptorInterface$ResultStatus net/adoptopenjdk/loadTest/adaptors/JUnitAdaptor.executeTest()  source: JUnitAdaptor.java:130
      objects: 0x1d71778 0x1d71778 0x18b7358 0x18c3fa8 0x18c3fc0 0x18c55c8 0x19059d8 0x190ef30
     bp: 0x47fcdfa8  method: void net/adoptopenjdk/loadTest/LoadTestRunner$2.run()  source: LoadTestRunner.java:182
      objects: 0x1e04648 0x1e0cb78 0x1e0eb58 0x1892bd0 0x1d71778
     bp: 0x47fce054  method: void java/util/concurrent/ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker)  source: ThreadPoolExecutor.java:1149
      objects: 0x1e0b258 0x1dfbda0 0x1e04648 0x1e0b290 0x1dfbda0
     bp: 0x47fce064  method: void java/util/concurrent/ThreadPoolExecutor$Worker.run()  source: ThreadPoolExecutor.java:624
      objects: 0x1e0b258
     bp: 0x47fce074  method: void java/lang/Thread.run()  source: Thread.java:823
      objects: 0x1e0b290

  thread id: 9904
   registers:
    gs     = 0x0000002b   fs     = 0x00000053   es     = 0x0000002b   ds     = 0x0000002b
    edi    = 0x000002b4   esi    = 0x7125ec98   ebx    = 0x00000048   edx    = 0x00000004
    ecx    = 0x7c4afed4   eax    = 0x480c60bc   ebp    = 0x4369df00   eip    = 0x479f707f
    cs     = 0x00000023   flags  = 0x00000206   esp    = 0x480c60f4   ss     = 0x0000002b
   native stack sections:
    0x49ac0000 to 0x49b00000 (length 0x40000)
   native stack frames:
   properties:
    Affinity=0x00000000000000FF                CreateTime=132572086203683382
    CreateTime_Formatted=2021/02/07 16:57:00   DumpError=0x00000000
    DumpFlags=0x00000000                       ExitStatus=0x00000103
    ExitTime=0                                 KernelTime=30476875000
    StartAddress=0x7163BFB4                    UserTime=2491093750
    priority=0                                 priorityClass=32
   associated Java thread: 
    name:          load-1
    Thread object: java/lang/Thread @ 0x187dc70
    Native info:   !j9vmthread 0x4369df00  !stack 0x4369df00
    Daemon:        false
    ID:            26 (0x1a)
    Priority:      5
    Thread.State:  RUNNABLE 
    JVMTI state:   ALIVE RUNNABLE 
    Java stack frames: 
     bp: 0x480c6128  method: boolean java/util/regex/Pattern$Start.match(java.util.regex.Matcher, int, CharSequence)  source: Pattern.java:3469
      objects: 0x1523cd58 0x152420c0 0x15242088
     bp: 0x00000000  method: boolean java/util/regex/Matcher.search(int)  source: Matcher.java:1248
      objects: <no objects in this frame>
     bp: 0x480c6164  method: boolean java/util/regex/Matcher.find()  source: Matcher.java:637
      objects: 0xdddddddd 0x711fb938 0x152420c0
     <corrupt data encountered>

Next two cores show the following:

  thread id: 14080
   registers:
    gs     = 0x0000002b   fs     = 0x00000053   es     = 0x0000002b   ds     = 0x0000002b
    edi    = 0x436a0630   esi    = 0x436add48   ebx    = 0x7155f3c8   edx    = 0x00000000
    ecx    = 0x00000000   eax    = 0x00000000   ebp    = 0x49a6eec4   eip    = 0x7709c38c
    cs     = 0x00000023   flags  = 0x00000202   esp    = 0x49a6eea8   ss     = 0x0000002b
   native stack sections:
    0x49a6eea4 to 0x49a70000 (length 0x115c)
   native stack frames:
    bp: 0x49a6eec4 pc: 0x7709c38c C:\Windows\System32\ntdll.dll::NtQueryPerformanceCounter+0xc
    bp: 0x49a6ef4c pc: 0x7137c9fd F:\Users\jenkins\workspace\Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0\openjdkbinary\j2sdk-image\jre\bin\default\j9prt29.dll::j9port_isCompatible+0xa44d
    bp: 0x7125ec98 pc: 0x712dc90a F:\Users\jenkins\workspace\Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0\openjdkbinary\j2sdk-image\jre\bin\default\j9trc29.dll::JVM_OnUnload+0x621a
   properties:
    Affinity=0x00000000000000FF                CreateTime=132572086201027120
    CreateTime_Formatted=2021/02/07 16:57:00   DumpError=0x00000000
    DumpFlags=0x00000000                       ExitStatus=0x00000103
    ExitTime=0                                 KernelTime=31290312500
    StartAddress=0x7163BFB4                    UserTime=2615937500
    priority=0                                 priorityClass=32
   associated Java thread: 
    name:          load-0
    Thread object: java/lang/Thread @ 0x1e0b280
    Native info:   !j9vmthread 0x436a0100  !stack 0x436a0100
    Daemon:        false
    ID:            25 (0x19)
    Priority:      5
    Thread.State:  RUNNABLE 
    JVMTI state:   ALIVE RUNNABLE 
    Java stack frames: 
     <corrupt data encountered>

  thread id: 9904
   registers:
    gs     = 0x0000002b   fs     = 0x00000053   es     = 0x0000002b   ds     = 0x0000002b
    edi    = 0x4369e430   esi    = 0x436b6568   ebx    = 0x7155f3c8   edx    = 0x00000000
    ecx    = 0x00000000   eax    = 0x00000000   ebp    = 0x49aff4a4   eip    = 0x7709c38c
    cs     = 0x00000023   flags  = 0x00000206   esp    = 0x49aff488   ss     = 0x0000002b
   native stack sections:
    0x49aff484 to 0x49b00000 (length 0xb7c)
   native stack frames:
    bp: 0x49aff4a4 pc: 0x7709c38c C:\Windows\System32\ntdll.dll::NtQueryPerformanceCounter+0xc
    bp: 0x49aff528 pc: 0x7137c9fd F:\Users\jenkins\workspace\Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0\openjdkbinary\j2sdk-image\jre\bin\default\j9prt29.dll::j9port_isCompatible+0xa44d
    bp: 0x7125ec98 pc: 0x712dc90a F:\Users\jenkins\workspace\Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_0\openjdkbinary\j2sdk-image\jre\bin\default\j9trc29.dll::JVM_OnUnload+0x621a
   properties:
    Affinity=0x00000000000000FF                CreateTime=132572086203683382
    CreateTime_Formatted=2021/02/07 16:57:00   DumpError=0x00000000
    DumpFlags=0x00000000                       ExitStatus=0x00000103
    ExitTime=0                                 KernelTime=30996250000
    StartAddress=0x7163BFB4                    UserTime=2542968750
    priority=0                                 priorityClass=32
   associated Java thread: 
    name:          load-1
    Thread object: java/lang/Thread @ 0x187dc30
    Native info:   !j9vmthread 0x4369df00  !stack 0x4369df00
    Daemon:        false
    ID:            26 (0x1a)
    Priority:      5
    Thread.State:  RUNNABLE 
    JVMTI state:   ALIVE RUNNABLE 
    Java stack frames: 
     <corrupt data encountered>

pshipton commented 3 years ago

@lumpfish is it possible to first attempt using jcmd to get javacore files and system dump files? The cores acquired via procdump.exe aren't in a good state.

@gacholio the first core isn't too bad, are you able to see why it's hung?

gacholio commented 3 years ago

Looking at the java stacks, this doesn't look like a hang - the load threads are running:

    !stack 0x42a6eb00   !j9vmthread 0x42a6eb00  !j9thread 0x0135bb38    tid 0x206c (8300) // main

<42a6eb00>  !j9method 0x43606DBC   java/lang/Thread.sleep(JI)V
<42a6eb00>  !j9method 0x43606DAC   java/lang/Thread.sleep(J)V
<42a6eb00>  !j9method 0x47F8E8FC   net/adoptopenjdk/loadTest/LoadTestRunner.run()J
<42a6eb00>  !j9method 0x4378BD10   net/adoptopenjdk/loadTest/LoadTest.runLoadTest()J
<42a6eb00>  !j9method 0x4378BCF0   net/adoptopenjdk/loadTest/LoadTest.main([Ljava/lang/String;)V
<42a6eb00>                          JNI call-in frame
<42a6eb00>                          Native method frame

    !stack 0x436a0100   !j9vmthread 0x436a0100  !j9thread 0x436955c8    tid 0x3700 (14080) // load-0

<436a0100>  !j9method 0x438C388C   java/util/regex/Pattern$Start.<init>(Ljava/util/regex/Pattern$Node;)V
<436a0100>  !j9method 0x438C02A0   java/util/regex/Pattern.compile()V
<436a0100>  !j9method 0x438C0220   java/util/regex/Pattern.<init>(Ljava/lang/String;I)V
<436a0100>  !j9method 0x438C0170   java/util/regex/Pattern.compile(Ljava/lang/String;)Ljava/util/regex/Pattern;
...

    !stack 0x4369df00   !j9vmthread 0x4369df00  !j9thread 0x4369583c    tid 0x26b0 (9904) // load-1

<4369df00>  !j9method 0x438C389C   java/util/regex/Pattern$Start.match(Ljava/util/regex/Matcher;ILjava/lang/CharSequence;)Z
<4369df00>  !j9method 0x438C4314   java/util/regex/Matcher.search(I)Z
<4369df00>  !j9method 0x438C41F4   java/util/regex/Matcher.find()Z
Feb 08, 2021 12:52:27 PM com.ibm.j9ddr.vm29.events.DefaultEventListener corruptData
WARNING: CorruptDataException thrown walking stack. walkThread = 0x4369DF00
com.ibm.j9ddr.AddressedCorruptDataException: Invalid JIT return address

The second thread is likely running in JITted code, so the stack can't be walked.

The other two cores show both load threads in JITted code, so they seem to have progressed since the first core.

gacholio commented 3 years ago

@pshipton Do you have a download link for the SDK that was in use?

pshipton commented 3 years ago

https://140-211-168-230-openstack.osuosl.org/artifactory/ci-eclipse-openj9/Build_JDK8_x86-32_windows_Personal/739/OpenJ9-JDK8-x86-32_windows-20210207-092927.tar.gz

pshipton commented 3 years ago

and the debug image if that helps https://140-211-168-230-openstack.osuosl.org/artifactory/ci-eclipse-openj9/Build_JDK8_x86-32_windows_Personal/739//debug-image.tar.gz

gacholio commented 3 years ago

In java.exe_210207_165625.dmp, the native stacks of the two load threads are:

  24  Id: 14cc.3700 Suspend: 0 Teb: fee70000 Unfrozen
ChildEBP RetAddr  
WARNING: Stack unwind information not available. Following frames may be wrong.
49a6eec4 7137c9fd ntdll!NtQueryPerformanceCounter+0xc
*** WARNING: Unable to verify checksum for j9trc29.dll
49a6eed4 712dbeec j9prt29!omrtime_hires_clock+0xd [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\omr\port\win32\omrtime.c @ 206]
49a6ef4c 712dc90a j9trc29!traceV+0x13c [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 1582]
49a6ef80 712d9346 j9trc29!logTracePoint+0x3a [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2069]
49a6efa8 712d770f j9trc29!doTracePoint+0xd6 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2207]
49a6efc0 71059e9f j9trc29!javaTrace+0x3f [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trcengine.c @ 1311]
49a6efe4 71059a01 j9jit29!getPendingStackHeight+0x19f [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 592]
49a6f028 71059cda j9jit29!initializeOSRFrame+0x41 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2118]
49a6f054 710561ed j9jit29!initializeOSRBuffer+0x1ea [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2209]
49a6f1d0 710660f0 j9jit29!induceOSROnCurrentThread+0x2cd [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2294]
49a6f1e4 71055002 j9jit29!old_slow_jitInduceOSRAtCurrentPC+0x80 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\cnathelp.cpp @ 3016]
49a6f270 714453f4 j9jit29!jitInduceOSRAtCurrentPC+0x62 [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\codert_vm\xnathelp.asm @ 6812]
49a6f2f0 714450d8 j9vm29!sidecarInvokeReflectMethodImpl+0x2f4 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1187]
49a6f308 706d6ab4 j9vm29!sidecarInvokeReflectMethod+0x38 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1331]
*** WARNING: Unable to verify checksum for java.dll
49a6f320 704b2b30 jclse29!JVM_InvokeMethod_Impl+0x54 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\sunvmi\sunvmi.c @ 356]
49a6f334 714e17c4 java_704b0000!Java_sun_reflect_NativeMethodAccessorImpl_invoke0+0x15 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\jdk\src\share\native\sun\reflect\nativeaccessors.c @ 34]
49a6f350 714e0fb3 j9vm29!ffi_call_win32+0x48 [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\libffi\win32.asm @ 971]
49a6f388 714107fc j9vm29!ffi_raw_call+0x63 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\libffi\x86\ffi.c @ 933]
49a6f5f8 713fd32d j9vm29!VM_DebugBytecodeInterpreterFull::run+0x134bc
49a6f6dc 71445fc5 j9vm29!debugBytecodeLoopFull+0x7d

  25  Id: 14cc.26b0 Suspend: 0 Teb: fee6d000 Unfrozen
ChildEBP RetAddr  
WARNING: Stack unwind information not available. Following frames may be wrong.
49aff0b4 7137c9fd ntdll!NtQueryPerformanceCounter+0xc
49aff0c4 712dbeec j9prt29!omrtime_hires_clock+0xd [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\omr\port\win32\omrtime.c @ 206]
49aff13c 712dc90a j9trc29!traceV+0x13c [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 1582]
49aff170 712d9346 j9trc29!logTracePoint+0x3a [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2069]
49aff198 712d770f j9trc29!doTracePoint+0xd6 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2207]
49aff1b0 710583d4 j9trc29!javaTrace+0x3f [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trcengine.c @ 1311]
49aff5f0 7105703c j9jit29!performDecompile+0x74 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 782]
49aff764 71057342 j9jit29!jitDecompileMethod+0x7c [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 507]
49aff774 71055c5a j9jit29!c_jitDecompileAtCurrentPC+0x22 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2381]
49aff810 714453f4 j9jit29!jitDecompileAtCurrentPC+0x1a [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\codert_vm\xnathelp.asm @ 8241]
49aff890 714450d8 j9vm29!sidecarInvokeReflectMethodImpl+0x2f4 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1187]
49aff8a8 706d6ab4 j9vm29!sidecarInvokeReflectMethod+0x38 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1331]
49aff8c0 704b2b30 jclse29!JVM_InvokeMethod_Impl+0x54 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\sunvmi\sunvmi.c @ 356]
49aff8d4 714e17c4 java_704b0000!Java_sun_reflect_NativeMethodAccessorImpl_invoke0+0x15 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\jdk\src\share\native\sun\reflect\nativeaccessors.c @ 34]
49aff8f0 714e0fb3 j9vm29!ffi_call_win32+0x48 [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\libffi\win32.asm @ 971]
49aff928 714107fc j9vm29!ffi_raw_call+0x63 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\libffi\x86\ffi.c @ 933]
49affb98 713fd32d j9vm29!VM_DebugBytecodeInterpreterFull::run+0x134bc
49affc78 71445fc5 j9vm29!debugBytecodeLoopFull+0x7d
49affccc 7148b8c1 j9vm29!runJavaThread+0x1b5 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 645]
49affce0 7138603f j9vm29!javaProtectedThreadProc+0xa1 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\vmthread.c @ 2100]

Which indicate that OSR is occurring (as it should be in the given test mode).

gacholio commented 3 years ago

Stacks from java.exe_210207_165655.dmp:

  24  Id: 14cc.3700 Suspend: 0 Teb: fee70000 Unfrozen
ChildEBP RetAddr  
WARNING: Stack unwind information not available. Following frames may be wrong.
49a6eec4 7137c9fd ntdll!NtQueryPerformanceCounter+0xc
*** WARNING: Unable to verify checksum for j9trc29.dll
49a6eed4 712dbeec j9prt29!omrtime_hires_clock+0xd [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\omr\port\win32\omrtime.c @ 206]
49a6ef4c 712dc90a j9trc29!traceV+0x13c [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 1582]
49a6ef80 712d9346 j9trc29!logTracePoint+0x3a [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2069]
49a6efa8 712d770f j9trc29!doTracePoint+0xd6 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2207]
49a6efc0 71059e9f j9trc29!javaTrace+0x3f [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trcengine.c @ 1311]
49a6efe4 71059a01 j9jit29!getPendingStackHeight+0x19f [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 592]
49a6f028 71059cda j9jit29!initializeOSRFrame+0x41 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2118]
49a6f054 710561ed j9jit29!initializeOSRBuffer+0x1ea [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2209]
49a6f1d0 710660f0 j9jit29!induceOSROnCurrentThread+0x2cd [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2294]
49a6f1e4 71055002 j9jit29!old_slow_jitInduceOSRAtCurrentPC+0x80 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\cnathelp.cpp @ 3016]
49a6f270 714453f4 j9jit29!jitInduceOSRAtCurrentPC+0x62 [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\codert_vm\xnathelp.asm @ 6812]
49a6f2f0 714450d8 j9vm29!sidecarInvokeReflectMethodImpl+0x2f4 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1187]
49a6f308 706d6ab4 j9vm29!sidecarInvokeReflectMethod+0x38 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1331]
*** WARNING: Unable to verify checksum for java.dll
49a6f320 704b2b30 jclse29!JVM_InvokeMethod_Impl+0x54 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\sunvmi\sunvmi.c @ 356]
49a6f334 714e17c4 java_704b0000!Java_sun_reflect_NativeMethodAccessorImpl_invoke0+0x15 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\jdk\src\share\native\sun\reflect\nativeaccessors.c @ 34]
49a6f350 714e0fb3 j9vm29!ffi_call_win32+0x48 [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\libffi\win32.asm @ 971]
49a6f388 714107fc j9vm29!ffi_raw_call+0x63 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\libffi\x86\ffi.c @ 933]
49a6f5f8 713fd32d j9vm29!VM_DebugBytecodeInterpreterFull::run+0x134bc
49a6f6dc 71445fc5 j9vm29!debugBytecodeLoopFull+0x7d

  25  Id: 14cc.26b0 Suspend: 0 Teb: fee6d000 Unfrozen
ChildEBP RetAddr  
WARNING: Stack unwind information not available. Following frames may be wrong.
49aff4a4 7137c9fd ntdll!NtQueryPerformanceCounter+0xc
49aff4b4 712dbeec j9prt29!omrtime_hires_clock+0xd [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\omr\port\win32\omrtime.c @ 206]
49aff528 712dc90a j9trc29!traceV+0x13c [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 1582]
49aff55c 712d9346 j9trc29!logTracePoint+0x3a [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2069]
49aff584 712d770f j9trc29!doTracePoint+0xd6 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trclog.c @ 2207]
49aff59c 71058b77 j9trc29!javaTrace+0x3f [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\rastrace\trcengine.c @ 1311]
49aff5bc 71483251 j9jit29!decompileMethodFrameIterator+0xa7 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 620]
49aff5d4 7105b23f j9vm29!walkFrame+0x181 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\swalk.c @ 486]
49aff5ec 714834d3 j9jit29!jitWalkStackFrames+0x23f [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\jswalk.c @ 249]
49aff604 71057028 j9vm29!walkStackFrames+0x253 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\swalk.c @ 335]
49aff764 71057342 j9jit29!jitDecompileMethod+0x68 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 505]
49aff774 71055c5a j9jit29!c_jitDecompileAtCurrentPC+0x22 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\codert_vm\decomp.cpp @ 2381]
49aff810 714453f4 j9jit29!jitDecompileAtCurrentPC+0x1a [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\codert_vm\xnathelp.asm @ 8241]
49aff890 714450d8 j9vm29!sidecarInvokeReflectMethodImpl+0x2f4 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1187]
49aff8a8 706d6ab4 j9vm29!sidecarInvokeReflectMethod+0x38 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\vm\callin.cpp @ 1331]
49aff8c0 704b2b30 jclse29!JVM_InvokeMethod_Impl+0x54 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\sunvmi\sunvmi.c @ 356]
49aff8d4 714e17c4 java_704b0000!Java_sun_reflect_NativeMethodAccessorImpl_invoke0+0x15 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\jdk\src\share\native\sun\reflect\nativeaccessors.c @ 34]
49aff8f0 714e0fb3 j9vm29!ffi_call_win32+0x48 [F:\Users\jenkins\workspace\Build_JDK8_x86-32_windows_Personal\build\windows-x86-normal-server-release\vm\libffi\win32.asm @ 971]
49aff928 714107fc j9vm29!ffi_raw_call+0x63 [f:\users\jenkins\workspace\build_jdk8_x86-32_windows_personal\build\windows-x86-normal-server-release\vm\libffi\x86\ffi.c @ 933]
49affb98 713fd32d j9vm29!VM_DebugBytecodeInterpreterFull::run+0x134bc

gacholio commented 3 years ago

Looking at thread 25 in the two cores, the thread has clearly progressed (it does not appear to be looping in the decompiler):

> !j9sfjitresolveframe 0x4801DC14
J9SFJITResolveFrame at 0x4801dc14 {
  Fields for J9SFJITResolveFrame:
        0x0: class J9Object* savedJITException = !j9object 0x00000000
        0x4: U32 specialFrameFlags = 0x00E80000 (15204352)
        0x8: U32 parmCount = 0x00000000 (0)
        0xc: void* returnAddress = !j9x 0x4972283D
        0x10: U32* taggedRegularReturnSP = !j9x 0x4801DC2A
}
> !jitmetadatafrompc 0x4972283D
J9JITExceptionTable at 0x49CEF100 {
    struct J9UTF8* className = !j9utf8 0x46077EDC   // java/util/regex/Pattern$Start
    struct J9UTF8* methodName = !j9utf8 0x45EFC368   // <init>
    struct J9UTF8* methodSignature = !j9utf8 0x460777FA   // (Ljava/util/regex/Pattern$Node;)V
...

> !j9sfjitresolveframe 0x4801DA88
J9SFJITResolveFrame at 0x4801da88 {
  Fields for J9SFJITResolveFrame:
        0x0: class J9Object* savedJITException = !j9object 0x00000000
        0x4: U32 specialFrameFlags = 0x00E80000 (15204352)
        0x8: U32 parmCount = 0x00000000 (0)
        0xc: void* returnAddress = !j9x 0x479F6F15
        0x10: U32* taggedRegularReturnSP = !j9x 0x4801DA9E
}
> !jitmetadatafrompc 0x479F6F15
J9JITExceptionTable at 0x48C0CAC0 {
    struct J9UTF8* className = !j9utf8 0x46077EDC   // java/util/regex/Pattern$Start
    struct J9UTF8* methodName = !j9utf8 0x45FECF1A   // match
    struct J9UTF8* methodSignature = !j9utf8 0x46077D78   // (Ljava/util/regex/Matcher;ILjava/lang/CharSequence;)Z
...

gacholio commented 3 years ago

So from what I can see, this is not a hang as such - it may just be running very slowly, or perhaps running on a sick machine.

gacholio commented 3 years ago

Snap trace for thread 25 extracted from core 625 shows lots of decompile going on:

        0x4369df00  pool-2-thread-2
22:56:25.633932336 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.633938720 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x47a0d22d
22:56:25.633945312 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x45f6692d (stack map)
22:56:25.633951824 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.633958208 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.633964032 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 1
22:56:25.633969904 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.633975824 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.633981856  0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.633987504 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.633994000 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dad8
22:56:25.634000768 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dad4
22:56:25.634018448 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634024784 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.634030624  0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.634036976 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634043280 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634049248 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.634055056 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634061200 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634067088 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634073056 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634078992 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.634085104 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.634093712 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634099600 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.634105696 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.634112320 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634118896 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634125200 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.634131008 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634137232 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634143296 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634149488 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634156848 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.634163248 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.634175552 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634181616 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.634187040  0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.634192768  0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634198480  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634203792  0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.634209056  0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634214464  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634219696  0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634225040  0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634230752 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.634236832 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.634245504 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634251488 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.634257392 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.634264080 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634271648 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634277552 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.634283584 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634289936  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634295648 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634301408 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634307456 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.634313392 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.634325136 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634331216 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.634337200 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.634343504 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634349984 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634356032 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.634361840 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634368480 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634374400 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634379840  0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634385856 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.634393072 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.634401584 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634407696 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.634413648 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.634419968 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634426272 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634432160 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.634437968 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634444048 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634450080 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634455776  0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634461792 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.634468080 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.634480336 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634486496 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.634492304 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.634498752 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634505248 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634511424 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.634517344 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634523472 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634529312 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634535232 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634541264 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.634547200 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.634555664 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634561744 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.634568240 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.634574640 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634581296 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634587296 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.634593216 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634599280 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634605232 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634611488 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634617696 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.634623696 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.634635216 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634641184 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.634647120 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.634653808 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634660128 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634666320 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.634672688 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634678704 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634685280 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634691856 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634697968 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.634704128 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.634712352 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634718528 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.634724416 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.634731072 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634737392 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634743408 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.634749488 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634755888 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634761744 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634768000 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634774880 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.634781744 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.634792768 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634798992 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.634805104 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.634811840 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634818272 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634824096  0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.634830272 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634837520  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634843552 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634849600 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634856304 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.634862528 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.634870944 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634877024 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.634883104 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.634889664 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634896832 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634902960 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.634908992 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.634915152 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634920864  0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.634926704 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.634932608 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.634939248 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.634951344 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.634964800 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.634970944 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.634977824 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.634984752 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.634990864 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.634997008 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635003424 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635009488 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635015936 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635021808 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.635028240 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.635050032 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635056192 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.635062176 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.635068640 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635075520 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635081680 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.635087568 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635093040  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635098704 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635104944 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635111280 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.635117232 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.635129280 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635135904 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.635141936 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.635148448 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635155152 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635160928 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.635166720 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635172416  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635178048 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635184192 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635190176 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.635196304 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.635204512 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635210672 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.635216608 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.635223152 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635229520 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635235616 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.635241920 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635247776  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635254544 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635260640 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635266528 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.635272688 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.635283792 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635289728 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.635295600 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.635301776 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635308112 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635314608 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.635320512 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635326224  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635332016 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635338064 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635344128 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.635350144 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.635358336 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635364496 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.635370800 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.635377536 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635384016 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635389856 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.635395648 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635401088  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635406752 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635413040 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635419024 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.635425200 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.635438144 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635444272 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.635450368 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.635456720 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635462960 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635468752 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.635474528 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635480128  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635485776 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635492496 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635499904 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc3c
22:56:25.635506160 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc34
22:56:25.635514768 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635521280 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x479f6f15
22:56:25.635527216 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cfe8 (stack map)
22:56:25.635533664 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635540048 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635546112 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 4
22:56:25.635552016 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635557440  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635563312 *0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
22:56:25.635569728 *0x4369df00 j9codertvm(j9jit).71   Entry      >performDecompile
22:56:25.635576160 *0x4369df00 j9codertvm(j9jit).75   Event       building J2I frame at 0x4801dc70
22:56:25.635582592 *0x4369df00 j9codertvm(j9jit).79   Exit       <performDecompile - new SP = 0x4801dc60
22:56:25.635594336 *0x4369df00 j9codertvm(j9jit).59   Event       pending count from stack mapper is 0
22:56:25.635600816 *0x4369df00 j9codertvm(j9jit).33   Entry      >jitInterpreterPCFromWalkState - Lookup interp PC for 0x4972283d
22:56:25.635606992 *0x4369df00 j9codertvm(j9jit).37   Exit       <jitInterpreterPCFromWalkState - interp pc = 0x4607cf96 (stack map)
22:56:25.635613664 *0x4369df00 j9codertvm(j9jit).51   Event       at current PC
22:56:25.635620000 *0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635626064 *0x4369df00 j9codertvm(j9jit).58   Event       outgoing arg count is 2
22:56:25.635631904 *0x4369df00 j9codertvm(j9jit).63   Exit       <decompileMethodFrameIterator
22:56:25.635639216  0x4369df00 j9codertvm(j9jit).57   Entry      >decompileMethodFrameIterator
22:56:25.635644832  0x4369df00 j9codertvm(j9jit).61   Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values

lumpfish commented 3 years ago

is it possible to first attempt using jcmd to get javacore files and system dump files? The cores acquired via procdump.exe aren't in a good state.

Not at the moment. I've raised this issue: https://github.com/AdoptOpenJDK/stf/issues/103. @pshipton - do you know which jcmd commands result in the creation of javacores and system dumps?

pshipton commented 3 years ago

@lumpfish jcmd <pid> Dump.java and jcmd <pid> Dump.system

pshipton commented 3 years ago

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_x86-64_windows_mixed_Personal_testList_0/3/ No artifacts retained, the job timed out.

pshipton commented 3 years ago

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_1/11

https://140-211-168-230-openstack.osuosl.org/artifactory/ci-eclipse-openj9/Test/Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_1/11/system_test_output.tar.gz

lumpfish commented 3 years ago

jcmd should now be used to generate dumps on Windows: see https://github.com/AdoptOpenJDK/stf/issues/103

pshipton commented 3 years ago

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_x86-64_windows_mixed_Personal_testList_0/4/ https://ci.eclipse.org/openj9/job/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/1 No diagnostics because the job timed out before or during uploading them.

LT  15:26:42.228 - Completed 100.0%. Number of tests started=2 (+0)
LT  15:27:02.259 - Completed 100.0%. Number of tests started=2 (+0)
LT  15:27:22.212 - Completed 100.0%. Number of tests started=2 (+0)
STF 15:27:26.370 - Heartbeat: Process LT  is still running
STF 15:27:28.433 - **FAILED** Process LT  has timed out
STF 15:27:28.433 - Collecting dumps for: LT 
STF 15:27:28.435 - Running command: F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdkbinary/j2sdk-image/bin/java -XshowSettings:properties -version
STF 15:27:28.435 - Redirecting stderr to C:\temp\QwYwNFgAvm\java_properties.stderr
STF 15:27:28.435 - Redirecting stdout to C:\temp\QwYwNFgAvm\java_properties.stdout
STF 15:27:28.438 - Monitoring processes: stf::stfUtility->getJavaProperties
STF 15:27:28.931 - Monitoring Report Summary:
STF 15:27:28.931 -   o Process stf::stfUtility->getJavaProperties ended sucessfully
STF 15:27:29.322 - Using procdump.exe to generate .DMP files
STF 15:27:29.323 - Running command: F:\Users\jenkins\workspace\Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0\jvmtest\system\systemtest_prereqs\windows_sysinternals\procdump.exe -accepteula -ma 7584
STF 15:27:29.323 - Redirecting stderr to F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdk-tests/TKG/output_16138353434571/ParallelStreamsLoadTest_special_J9_24/20210220-142721-ParallelStreamsLoadTest/results/1.LT.jvmdump.stderr
STF 15:27:29.323 - Redirecting stdout to F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdk-tests/TKG/output_16138353434571/ParallelStreamsLoadTest_special_J9_24/20210220-142721-ParallelStreamsLoadTest/results/1.LT.jvmdump.stdout
STF 15:27:29.330 - Pausing for 30 seconds
STF 15:27:59.322 - Running command: F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdkbinary/j2sdk-image/bin/java -XshowSettings:properties -version
STF 15:27:59.322 - Redirecting stderr to C:\temp\66_pfw8k38\java_properties.stderr
STF 15:27:59.322 - Redirecting stdout to C:\temp\66_pfw8k38\java_properties.stdout
STF 15:27:59.324 - Monitoring processes: stf::stfUtility->getJavaProperties
STF 15:27:59.821 - Monitoring Report Summary:
STF 15:27:59.821 -   o Process stf::stfUtility->getJavaProperties ended sucessfully
STF 15:27:59.884 - Using procdump.exe to generate .DMP files
STF 15:27:59.885 - Running command: F:\Users\jenkins\workspace\Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0\jvmtest\system\systemtest_prereqs\windows_sysinternals\procdump.exe -accepteula -ma 7584
STF 15:27:59.885 - Redirecting stderr to F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdk-tests/TKG/output_16138353434571/ParallelStreamsLoadTest_special_J9_24/20210220-142721-ParallelStreamsLoadTest/results/1.LT.jvmdump.stderr
STF 15:27:59.885 - Redirecting stdout to F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdk-tests/TKG/output_16138353434571/ParallelStreamsLoadTest_special_J9_24/20210220-142721-ParallelStreamsLoadTest/results/1.LT.jvmdump.stdout
PROC [15:27:29] Dump 1 initiated: F:\Users\jenkins\workspace\Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0\openjdk-tests\TKG\output_16138353434571\ParallelStreamsLoadTest_special_J9_24\20210220-142721-ParallelStreamsLoadTest\results\java.exe_210220_152729.dmp
PROC [15:27:29] Dump 1 writing: Estimated dump file size is 1176 MB.
PROC stderr 
PROC stderr ProcDump v10.0 - Sysinternals process dump utility
PROC stderr Copyright (C) 2009-2020 Mark Russinovich and Andrew Richards
PROC stderr Sysinternals - www.sysinternals.com
PROC stderr 
STF 15:27:59.888 - Pausing for 30 seconds
STF 15:28:29.884 - Running command: F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdkbinary/j2sdk-image/bin/java -XshowSettings:properties -version
STF 15:28:29.884 - Redirecting stderr to C:\temp\40k97uUPms\java_properties.stderr
STF 15:28:29.884 - Redirecting stdout to C:\temp\40k97uUPms\java_properties.stdout
STF 15:28:29.887 - Monitoring processes: stf::stfUtility->getJavaProperties
STF 15:28:30.383 - Monitoring Report Summary:
STF 15:28:30.383 -   o Process stf::stfUtility->getJavaProperties ended sucessfully
STF 15:28:30.447 - Using procdump.exe to generate .DMP files
STF 15:28:30.448 - Running command: F:\Users\jenkins\workspace\Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0\jvmtest\system\systemtest_prereqs\windows_sysinternals\procdump.exe -accepteula -ma 7584
STF 15:28:30.448 - Redirecting stderr to F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdk-tests/TKG/output_16138353434571/ParallelStreamsLoadTest_special_J9_24/20210220-142721-ParallelStreamsLoadTest/results/1.LT.jvmdump.stderr
STF 15:28:30.448 - Redirecting stdout to F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdk-tests/TKG/output_16138353434571/ParallelStreamsLoadTest_special_J9_24/20210220-142721-ParallelStreamsLoadTest/results/1.LT.jvmdump.stdout
STF 15:28:30.450 - Pausing for 30 seconds
LT  15:28:08.978 - Completed 100.0%. Number of tests started=2 (+0)
LT  15:28:09.087 - Completed 100.0%. Number of tests started=2 (+0)
LT  15:28:22.259 - Completed 100.0%. Number of tests started=2 (+0)
LT  15:28:42.228 - Completed 100.0%. Number of tests started=2 (+0)
STF 15:29:00.447 - Monitoring Report Summary:
STF 15:29:00.447 -   o Process LT  has timed out
STF 15:29:00.447 - Killing processes: LT 
STF 15:29:00.447 -   o Process LT  pid 7584 stop()
STF 15:29:00.448 -   o Process LT  pid 7584 killed
**FAILED** at step 1 (Run parallel streams load test). Expected return value=0 Actual=1 at F:/Users/jenkins/workspace/Test_openjdk16_j9_special.system_x86-64_windows_mixed_Personal_testList_0/openjdk-tests/\TKG\output_16138353434571\ParallelStreamsLoadTest_special_J9_24/20210220-142721-ParallelStreamsLoadTest/execute.pl line 98.
STF 15:29:00.715 - **FAILED** execute script failed. Expected return value=0 Actual=1

pshipton commented 3 years ago

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_1/12

https://140-211-168-230-openstack.osuosl.org/artifactory/ci-eclipse-openj9/Test/Test_openjdk8_j9_special.system_x86-32_windows_Personal_testList_1/12/system_test_output.tar.gz

pshipton commented 3 years ago

I note this test appears to complete within 15min on other platforms.

pshipton commented 3 years ago

I guess this test isn't converted to use time based testing. I see some modes passing quickly, and other modes taking a longer period of time, 30min+.

pshipton commented 3 years ago

@Mesbah-Alam @lumpfish is it in progress to convert this test to time based?

lumpfish commented 3 years ago

As explained in https://github.com/AdoptOpenJDK/openjdk-systemtest/issues/379 - the test is self limiting to two concurrent instances - so there is no point in running it one more than two threads. Any additional threads just terminate immediately upon seeing that there are already two threads running.

As you have observed, it (usually?) takes > 5mins to run. If it were changed to time based, then when one instance ends another would replace it until the time limit is reached.

In reality, also as explained in https://github.com/AdoptOpenJDK/openjdk-systemtest/issues/379, historically the tests have only been running one instance because they were being deemed to have timed out immediately because of a bug in stf (now fixed).

So at the moment, the tests are being run exactly once down each of two threads. If they became '5 minute' tests they would mostly still run the same way. On some fast machines the test might be invoked more than once on those two threads. They would also still take longer than five minutes where they currently take longer than five minutes because running the test once takes more than 5 minutes.

What is your concern - that they are not running long enough, that they do not take the same amount of time to run across platforms and modes, or something else?

Mesbah-Alam commented 3 years ago

What is your concern - that they are not running long enough, that they do not take the same amount of time to run across platforms and modes, or something else?

@lumpfish , I guess the answer to this is what Pete said in one of his previous comments -

I see some modes passing quickly, and other modes taking a longer period of time, 30min+.

lumpfish commented 3 years ago

But as I said, they take >30 mins to run once in those modes

pshipton commented 3 years ago

My primary concern is this failure, it appears the tests are often trying to run for longer than the timeout.

Secondary, although this mode and some other modes can take 30+, there are modes being used where the testing takes less than 5 minutes. As previously discussed re time based testing, the shorter run time may not be long enough to warm up the JIT and find all the bugs.

pshipton commented 3 years ago

Looking at the diagnostics we have for the most recent failure https://github.com/eclipse/openj9/issues/11904#issuecomment-783448905, I was hoping to have javacore files, but I only see core files created via procdump.

lumpfish commented 3 years ago

Looking at the diagnostics we have for the most recently failure #11904 (comment), I was hoping to have javacore files, but I only see core files created via procdump.

Yes, I noticed that. I downloaded the same jdk build and ran my jcmd test and jcmd was used as expected:

STF 18:00:20.319 - ====================   E X E C U T E -   ====================
STF 18:00:20.319 - Running execute: perl c:\Users\user\stf_results/20210222-180018-SampleOverrunProcess/execute.pl
STF 18:00:20.441 -
STF 18:00:20.441 - Java version
STF 18:00:20.441 - Running: C:/openj9java/win_x86-64/jdk-16/bin/java -version
openjdk version "16-internal" 2021-03-16
OpenJDK Runtime Environment (build 16-internal+0-adhoc.jenkins.buildjdk16x86-64windowsmixedpersonal)
Eclipse OpenJ9 VM (build master-5be3435f123, JRE 16 Windows 10 amd64-64-Bit Compressed References 20210220_2 (JIT enabled, AOT enabled)
OpenJ9   - 5be3435f123
OMR      - e69c81f
JCL      - c8b23b0ef6d based on jdk-16+36)
STF 18:00:20.873 -
STF 18:00:20.873 - +------ Step 1 - Run client
STF 18:00:20.873 - | Run foreground process
STF 18:00:20.873 - |   Program:     C:/openj9java/win_x86-64/jdk-16/bin/java
STF 18:00:20.873 - |   Mnemonic:    CL
STF 18:00:20.873 - |   Echo:        ECHO_ON
STF 18:00:20.873 - |   Expectation: NON_ZERO_EXIT [0] within 10s
STF 18:00:20.873 - |
STF 18:00:20.873 - Running command: C:/openj9java/win_x86-64/jdk-16/bin/java -classpath c:\Users\user\git\stf\stf.samples\bin net.adoptopenjdk.stf.processManagement.apps.MiniClient 0 180000
STF 18:00:20.873 - Redirecting stderr to c:/Users/user/stf_results/20210222-180018-SampleOverrunProcess/results/1.CL.stderr
STF 18:00:20.873 - Redirecting stdout to c:/Users/user/stf_results/20210222-180018-SampleOverrunProcess/results/1.CL.stdout
STF 18:00:20.900 - Monitoring processes: CL
CL  18:00:21.396 Client started
CL  18:00:21.397 Client sleeping for 180000 milliseconds
STF 18:00:31.002 - **FAILED** Process CL  has timed out
STF 18:00:31.002 - Collecting dumps for: CL
STF 18:00:31.004 - Running command: C:\openj9java\win_x86-64\jdk-16/bin/java -XshowSettings:properties -version
STF 18:00:31.004 - Redirecting stderr to C:\Users\user\AppData\Local\Temp\KYCGW5PUoS\java_properties.stderr
STF 18:00:31.004 - Redirecting stdout to C:\Users\user\AppData\Local\Temp\KYCGW5PUoS\java_properties.stdout
STF 18:00:31.010 - Monitoring processes: stf::stfUtility->getJavaProperties
STF 18:00:31.453 - Monitoring Report Summary:
STF 18:00:31.453 -   o Process stf::stfUtility->getJavaProperties ended sucessfully
STF 18:00:31.454 - Using jcmd.exe to generate .DMP files
STF 18:00:31.454 - Running command: C:\openj9java\win_x86-64\jdk-16\bin\jcmd.exe 15868 Dump.java
STF 18:00:31.454 - Redirecting stderr to c:/Users/user/stf_results/20210222-180018-SampleOverrunProcess/results/1.CL.jvmdump.stderr
STF 18:00:31.454 - Redirecting stdout to c:/Users/user/stf_results/20210222-180018-SampleOverrunProcess/results/1.CL.jvmdump.stdout
STF 18:00:31.461 - Running command: C:\openj9java\win_x86-64\jdk-16\bin\jcmd.exe 15868 Dump.system
STF 18:00:31.461 - Redirecting stderr to c:/Users/user/stf_results/20210222-180018-SampleOverrunProcess/results/1.CL.jvmdump.stderr
STF 18:00:31.461 - Redirecting stdout to c:/Users/user/stf_results/20210222-180018-SampleOverrunProcess/results/1.CL.jvmdump.stdout
STF 18:00:31.466 - Pausing for 30 seconds
Terminating on signal SIGINT(2)

The code checks that there is a jcmd.exe available in the jdk bin dir and that java.vm.name contains 'J9' - if so it uses jcmd. It's not obvious to me why that would not work in your environment - as far as I can tell, you are running with the updated stf code. Maybe we'll have to add some diagnostics.

lumpfish commented 3 years ago

My primary concern is this failure, it appears the tests are often trying to run for longer than the timeout.

What do you mean by 'the timeout'? The tests are coded such that if the workload process does not complete within 60 minutes then the dumps are taken and the test is declared failed.

This is the code which sets that timeout:

        test.doRunForegroundProcess("Run parallel streams load test", "LT", Echo.ECHO_ON,
                ExpectedOutcome.cleanRun().within("60m"),
                loadTestInvocation);
    }

lumpfish commented 3 years ago

Secondary, although this mode and some other modes can take 30+, there are modes being used where the testing takes less than 5 minutes. As previously discussed re time based testing, the shorter run time may not be long enough to warm up the JIT and find all the bugs.

We can create a 'timed' variation. My point is that if you run for only 5 minutes you'll mostly only be running the tests once anyway.

Mesbah-Alam commented 3 years ago

We can create a 'timed' variation. My point is that if you run for only 5 minutes you'll mostly only be running the tests once anyway.

Will it work if we make a timed version of it that runs for 15m?

pshipton commented 3 years ago

What do you mean by 'the timeout'? The tests are coded such that if the workload process does not complete within 60 minutes then the dumps are taken and the test is declared failed.

As per previous analysis https://github.com/eclipse/openj9/issues/11904#issuecomment-775336852, this test isn't hanging, it's often just trying to run for more than 60min, causing it to fail. The preferred behavior is for the test to pass obviously, and also to run for only around 5 min in slow modes, not more than 1 hour.

pshipton commented 3 years ago

Looking at https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_ppc64le_linux_mixed_Nightly/19, some modes run significantly less than 5min.

7 - - ParallelStreamsLoadTest_special_J9_2 | 1 min 45 sec | OK | No | No 8 - - ParallelStreamsLoadTest_special_J9_3 | 1 min 39 sec | OK | No | No 9 - - ParallelStreamsLoadTest_special_J9_18 | 1 min 42 sec | OK | No | No 10 - - ParallelStreamsLoadTest_special_J9_22 | 37 sec | OK | No | No 11 - - ParallelStreamsLoadTest_special_J9_26 | 2 min 52 sec | OK | No | No 12 - - ParallelStreamsLoadTest_special_J9_29 | 35 sec

6 - - ParallelStreamsLoadTest_special_J9_0 | 42 sec | OK | No | No 7 - - ParallelStreamsLoadTest_special_J9_6 | 1 min 4 sec | OK | No | No 8 - - ParallelStreamsLoadTest_special_J9_12 | 54 sec | OK | No | No 9 - - ParallelStreamsLoadTest_special_J9_14 | 59 sec | OK | No | No 10 - - ParallelStreamsLoadTest_special_J9_16 | 1 min 26 sec | OK | No | No 11 - - ParallelStreamsLoadTest_special_J9_19 | 1 min 37 sec | OK | No | No 12 - - ParallelStreamsLoadTest_special_J9_20 | 19 min | OK | No | No 13 - - ParallelStreamsLoadTest_special_J9_25 | 2 min 43 sec | OK | No | No 10 - - ParallelStreamsLoadTest_special_J9_5 | 19 min | OK | No | No 11 - - ParallelStreamsLoadTest_special_J9_7 | 1 min 34 sec | OK | No | No 12 - - ParallelStreamsLoadTest_special_J9_17 | 46 sec | OK | No | No 13 - - ParallelStreamsLoadTest_special_J9_21 | 38 sec | OK | No | No 14 - - ParallelStreamsLoadTest_special_J9_24 | 1 min 36 sec | OK | No | No

6 - - ParallelStreamsLoadTest_special_J9_1 | 1 min 13 sec | OK | No | No 7 - - ParallelStreamsLoadTest_special_J9_4 | 1 min 8 sec | OK | No | No 8 - - ParallelStreamsLoadTest_special_J9_8 | 58 sec | OK | No | No 9 - - ParallelStreamsLoadTest_special_J9_13 | 1 min 3 sec | OK | No | No 10 - - ParallelStreamsLoadTest_special_J9_23 | 1 min 7 sec | OK | No | No 11 - - ParallelStreamsLoadTest_special_J9_27 | 4 min 4 sec | OK | No | No 12 - - ParallelStreamsLoadTest_special_J9_28 | 1 min 0 sec | OK | No | No

58 - - ParallelStreamsLoadTest_special_J9_9 | 44 sec | OK | No | No 59 - - ParallelStreamsLoadTest_special_J9_10 | 13 ms | OK | Yes | No 60 - - ParallelStreamsLoadTest_special_J9_11 | 13 ms | OK | Yes | No 61 - - ParallelStreamsLoadTest_special_J9_15 | 4 min 5 sec | OK | No | No

lumpfish commented 3 years ago

Thanks for the data.

So if we create a 'timed' variant, then it will be possible to set it to run for a minimum time - you can then decide what you think is a 'good' time to run for. For a 'fast' run a 5 minute test would means the tests would run about 5 times rather than once.

Regarding

this test isn't hanging, it's often just trying to run for more than 60min

then we need a bigger timeout, or we need to stop running in modes which add so much to the execution time. The downside to long timeouts are 1. If the test does hang then we wait for the timeout before we kill it, 2. We run the danger of hitting a timeout elsewhere in the process such as the global Jenkins job timeout.

pshipton commented 3 years ago

On xlinux, the same test https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_x86-64_linux_mixed_Nightly/19

38 - - ParallelStreamsLoadTest_special_J9_24 | 4 min 46 sec

variation: Mode107-OSRG JVM_OPTIONS: -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation

@0xdaryl @tajila any idea why this test is running so slowly on Windows?

pshipton commented 3 years ago

https://ci.eclipse.org/openj9/job/Test_openjdk16_j9_special.system_x86-64_windows_Personal_testList_0/4

pshipton commented 3 years ago

I've gathered timing information and discovered that OSRG modes run slow only on Windows, but not on other platforms. I've created https://github.com/AdoptOpenJDK/openjdk-tests/pull/2316 to disable these modes on Windows.

Assigning to JIT to investigate why these modes are slow only on Windows. @0xdaryl

variation: (24) Mode107-OSRG JVM_OPTIONS: -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation Windows 11: 67min aix 8: 9min, 11: 4min osx 8: 3min, 11: 5min plinux 8: 2min, 11: 4min xlinux 8: 4min, 11: 10min zlinux 8: 4min, 11: 6min

variation: (25) Mode110-OSRG JVM_OPTIONS: -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation -Xgcpolicy:gencon Windows 11: 32min aix 8: 4min, 11: 5min osx 8: 3min, 11: 2min plinux 8: 4min, 11: 5min xlinux 8: 4min, 11: 6min zlinux 8: 1min, 11: 2min

variation: (26) Mode610-OSRG JVM_OPTIONS: -Xcompressedrefs -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation -Xgcpolicy:gencon Windows 11: 25min aix 8: 4min, 11: 5min osx 8: 3min, 11: 2min plinux 8: 3min, 11: 4min xlinux 8: 5min, 11: 6min zlinux 8: 2min, 11: 2min

variation: (27) Mode612-OSRG JVM_OPTIONS: -Xcompressedrefs -Xgcpolicy:gencon -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation Windows 11: 33min aix 8: 4min, 11: 5min osx 8: 2min, 11: 4min plinux 8: 3min, 11: 5min xlinux 8: 4min, 11: 6min zlinux 8: 1min, 11: 2min

0xdaryl commented 3 years ago

@nbhuiyan : could you have a look at this please?

0xdaryl commented 3 years ago

This won't be resolved for 0.26.

0xdaryl commented 3 years ago

No progress on this for 0.27. Moving to 0.28.

JasonFengJ9 commented 1 year ago

JDK11 ppc64le_linux milestone 2(rhel8le-svl-rt4-1)

[2023-06-29T03:21:09.798Z] variation: Mode107-OSRG
[2023-06-29T03:21:09.798Z] JVM_OPTIONS:  -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation 

[2023-06-29T04:21:15.818Z] STF 21:21:13.316 - Heartbeat: Process LT  is still running
[2023-06-29T04:21:15.818Z] STF 21:21:14.318 - **FAILED** Process LT  has timed out
[2023-06-29T04:21:15.818Z] STF 21:21:14.318 - Collecting dumps for: LT 
[2023-06-29T04:21:15.818Z] STF 21:21:14.318 - Sending SIG 3 to the java process to generate a javacore
[2023-06-29T04:21:15.818Z] STF 21:21:14.319 - Running command: kill -3 434106

[2023-06-29T04:23:14.673Z] STF 21:23:14.341 - Monitoring Report Summary:
[2023-06-29T04:23:14.673Z] STF 21:23:14.341 -   o Process LT  has timed out
[2023-06-29T04:23:14.673Z] STF 21:23:14.342 - Killing processes: LT 
[2023-06-29T04:23:14.673Z] STF 21:23:14.343 -   o Process LT  pid 434106 is not running
[2023-06-29T04:23:14.673Z] **FAILED** at step 1 (Run parallel streams load test). Expected return value=0 Actual=1 at /home/jenkins/workspace/Test_openjdk11_j9_special.system_ppc64le_linux_testList_4/aqa-tests/TKG/../TKG/output_16879964992966/ParallelStreamsLoadTest_special_J9_22/20230628-202109-ParallelStreamsLoadTest/execute.pl line 98.
[2023-06-29T04:23:14.673Z] STF 21:23:14.577 - **FAILED** execute script failed. Expected return value=0 Actual=1
[2023-06-29T04:23:14.673Z] STF 21:23:14.577 - 
[2023-06-29T04:23:14.673Z] STF 21:23:14.578 - ====================   T E A R D O W N   ====================
[2023-06-29T04:23:14.673Z] STF 21:23:14.578 - Running teardown: perl /home/jenkins/workspace/Test_openjdk11_j9_special.system_ppc64le_linux_testList_4/aqa-tests/TKG/../TKG/output_16879964992966/ParallelStreamsLoadTest_special_J9_22/20230628-202109-ParallelStreamsLoadTest/tearDown.pl
[2023-06-29T04:23:15.111Z] STF 21:23:14.734 - TEARDOWN stage completed
[2023-06-29T04:23:15.111Z] STF 21:23:14.736 - 
[2023-06-29T04:23:15.111Z] STF 21:23:14.736 - =====================   R E S U L T S   =====================
[2023-06-29T04:23:15.111Z] STF 21:23:14.737 - Stage results:
[2023-06-29T04:23:15.111Z] STF 21:23:14.737 -   setUp:     pass
[2023-06-29T04:23:15.112Z] STF 21:23:14.737 -   execute:  *fail*
[2023-06-29T04:23:15.112Z] STF 21:23:14.737 -   teardown:  pass
[2023-06-29T04:23:15.112Z] STF 21:23:14.737 - 
[2023-06-29T04:23:15.112Z] STF 21:23:14.737 - Overall result: **FAILED**
[2023-06-29T04:23:15.112Z] -----------------------------------
[2023-06-29T04:23:15.112Z] ParallelStreamsLoadTest_special_J9_22_FAILED

eclipse-openj9 / openj9

ParallelStreamsLoadTest_special_J9_24 hang/timeout at 100% #11904