Test-extended.system-JDK8-win_x86-64_cmprssptrs ConcurrentLoadTest_0 ForkJoinPoolTest getActiveThreadCount() expected:<0> but was:<1> #4277

pshipton · 2019-01-12T13:14:35Z

https://ci.eclipse.org/openj9/job/Test-extended.system-JDK8-win_x86-64_cmprssptrs/133

===============================================
Running test ConcurrentLoadTest_0 ...
===============================================
ConcurrentLoadTest_0 Start Time: Sat Jan 12 02:03:00 2019 Epoch Time (ms): 1547280180628
variation: NoOptions
JVM_OPTIONS:  -Xcompressedrefs 
STF 02:03:01.346 - =========================   S T F   =========================
systemtest-prereqs has been processed, and set to: C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqsRetrieving amount of free space on drive containing C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/\TestConfig\test_output_15472799049455\ConcurrentLoadTest_0
There is 23517 Mb free
STF 02:03:01.368 - ==================   G E N E R A T I O N   ==================
STF 02:03:01.370 - Checking JVM: C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdkbinary/j2sdk-image/jre/bin\..\..\
STF 02:03:01.370 - Starting process to generate scripts: C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdkbinary/j2sdk-image/jre/bin\..\..\/bin/java  -Dlog4j.skipJansi=true -Djava.system.class.loader=net.adoptopenjdk.stf.runner.StfClassLoader -classpath C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests///..//jvmtest\systemtest\otherLoadTest/../\systemtest_prereqs/log4j-2.3/log4j-api-2.3.jar;C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests///..//jvmtest\systemtest\otherLoadTest/../\systemtest_prereqs/log4j-2.3/log4j-core-2.3.jar;C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/stf/stf.core/scripts/../bin net.adoptopenjdk.stf.runner.StfRunner -properties "C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/\TestConfig\test_output_15472799049455\ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/stf_parameters.properties, , C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/stf/stf.core/config/stf.properties" -testDir "C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/\TestConfig\test_output_15472799049455\ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest"
GEN 02:03:02.346 - Found test. Project: 'openjdk.test.load' class: 'ConcurrentLoadTest.class' Dir: 'C:\Users\jenkins\workspace\Test-extended.system-JDK8-win_x86-64_cmprssptrs\jvmtest\systemtest\openjdk-systemtest\openjdk.test.load\bin'
GEN 02:03:02.362 - Found test. Project: 'openjdk.test.load' class: 'net.adoptopenjdk.stf.ConcurrentLoadTest'
GEN Classpath directories used by project 'openjdk.test.load': 
GEN   C:\\Users\\jenkins\\workspace\\Test-extended.system-JDK8-win_x86-64_cmprssptrs\\jvmtest\\systemtest\\openjdk-systemtest\\openjdk.test.load\\bin
GEN   C:\\Users\\jenkins\\workspace\\Test-extended.system-JDK8-win_x86-64_cmprssptrs\\jvmtest\\systemtest\\stf\\stf.core\\bin
GEN   C:\\Users\\jenkins\\workspace\\Test-extended.system-JDK8-win_x86-64_cmprssptrs\\jvmtest\\systemtest\\stf\\stf.load\\bin
GEN   C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/log4j-2.3/log4j-api-2.3.jar
GEN   C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/log4j-2.3/log4j-core-2.3.jar
GEN   C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/junit-4.12/junit-4.12.jar
GEN   C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/junit-4.12/hamcrest-core-1.3.jar
GEN 02:03:02.706 - Using Mode NoOptions. Values = ''
GEN 02:03:02.784 - 
GEN 02:03:02.784 - Test command summary:
GEN 02:03:02.784 -   Step  Stage   Command           Description
GEN 02:03:02.784 -  -----+--------+-----------------+------------
GEN 02:03:02.784 -     1  execute  Run java          Run concurrency unit tests
STF 02:03:02.818 - 
STF 02:03:02.818 - Script generation completed
STF 02:03:02.818 - 
STF 02:03:02.819 - 
STF 02:03:02.819 - =======================   S E T U P   =======================
STF 02:03:02.819 - Running setup: perl C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/\TestConfig\test_output_15472799049455\ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/setUp.pl
STF 02:03:02.971 - SETUP stage completed
STF 02:03:03.003 - 
STF 02:03:03.004 - ====================   E X E C U T E -   ====================
STF 02:03:03.004 - Running execute: perl C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/\TestConfig\test_output_15472799049455\ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/execute.pl
STF 02:03:03.159 - 
STF 02:03:03.159 - Java version
STF 02:03:03.159 - Running: C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdkbinary/j2sdk-image/jre/bin/../../bin/java -version
openjdk version "1.8.0_202-internal"
OpenJDK Runtime Environment (build 1.8.0_202-internal-jenkins_2019_01_11_23_24-b00)
Eclipse OpenJ9 VM (build master-827f2551a, JRE 1.8.0 Windows Server 2012 R2 amd64-64-Bit Compressed References 20190111_814 (JIT enabled, AOT enabled)
OpenJ9   - 827f2551a
OMR      - 11cdf3e2
JCL      - ae9adba3223 based on jdk8u202-b01)
STF 02:03:03.398 - 
STF 02:03:03.398 - +------ Step 1 - Run concurrency unit tests
STF 02:03:03.398 - | Run foreground process
STF 02:03:03.398 - |   Program:     C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdkbinary/j2sdk-image/jre/bin/../../bin/java
STF 02:03:03.398 - |   Mnemonic:    LT
STF 02:03:03.398 - |   Echo:        ECHO_ON
STF 02:03:03.398 - |   Expectation: CLEAN_RUN within 1h
STF 02:03:03.398 - |
STF 02:03:03.398 - Running command: C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdkbinary/j2sdk-image/jre/bin/../../bin/java -Xcompressedrefs -classpath C:\Users\jenkins\workspace\Test-extended.system-JDK8-win_x86-64_cmprssptrs\jvmtest\systemtest\stf\stf.load\bin;C:\Users\jenkins\workspace\Test-extended.system-JDK8-win_x86-64_cmprssptrs\jvmtest\systemtest\stf\stf.core\bin;C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/log4j-2.3/log4j-api-2.3.jar;C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/log4j-2.3/log4j-core-2.3.jar;C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/junit-4.12/junit-4.12.jar;C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/jvmtest/systemtest/systemtest_prereqs/junit-4.12/hamcrest-core-1.3.jar;C:\Users\jenkins\workspace\Test-extended.system-JDK8-win_x86-64_cmprssptrs\jvmtest\systemtest\openjdk-systemtest\openjdk.test.concurrent\bin net.adoptopenjdk.loadTest.LoadTest -resultsDir C:\Users\jenkins\workspace\Test-extended.system-JDK8-win_x86-64_cmprssptrs\openjdk-tests\TestConfig\test_output_15472799049455\ConcurrentLoadTest_0\20190112-020301-ConcurrentLoadTest\results -resultsPrefix 1.LT. -abortIfOutOfMemory false -reportFailureLimit 1 -abortAtFailureLimit 10 -maxTotalLogFileSpace 200M -maxSingleLogSize 1/25 -suite.concurrent.threadCount 20 -suite.concurrent.inventoryFile C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/TestConfig/test_output_15472799049455/ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/results/1.LT.inventory/openjdk.test.load/config/inventories/concurrent/concurrent.xml -suite.concurrent.inventoryExcludeFile C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/TestConfig/test_output_15472799049455/ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/results/1.LT.inventory/openjdk.test.load/config/inventories/concurrent/concurrent_exclude.xml -suite.concurrent.totalNumberTests 540 -suite.concurrent.selection random -suite.concurrent.seed -1 -suite.concurrent.repeatCount 1 -suite.concurrent.thinkingTime 0ms..0ms
STF 02:03:03.398 - Redirecting stderr to C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/TestConfig/test_output_15472799049455/ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/results/1.LT.stderr
STF 02:03:03.398 - Redirecting stdout to C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/TestConfig/test_output_15472799049455/ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/results/1.LT.stdout
STF 02:03:03.428 - Monitoring processes: LT 
LT  02:03:04.346 - Load test parameters
LT  02:03:04.346 -   Time limited         = false
LT  02:03:04.346 -   abortIfOutOfMemory   = false
LT  02:03:04.346 -   reportFailureLimit   = 1
LT  02:03:04.346 -   abortAtFailureLimit  = 10
LT  02:03:04.346 -   maxTotalLogFileSpace = 209715200
LT  02:03:04.346 -   maxSingleLogSize     = 8388608
LT  02:03:04.346 - Parameters for suite 0
LT  02:03:04.346 -   Suite name     = concurrent
LT  02:03:04.346 -   Number threads = 20
LT  02:03:04.346 -   Supplied seed  = -1
LT  02:03:04.346 -   Inventory file = C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/TestConfig/test_output_15472799049455/ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/results/1.LT.inventory/openjdk.test.load/config/inventories/concurrent/concurrent.xml
LT  02:03:04.346 -   Exclude file   = C:/Users/jenkins/workspace/Test-extended.system-JDK8-win_x86-64_cmprssptrs/openjdk-tests/TestConfig/test_output_15472799049455/ConcurrentLoadTest_0/20190112-020301-ConcurrentLoadTest/results/1.LT.inventory/openjdk.test.load/config/inventories/concurrent/concurrent_exclude.xml
LT  02:03:04.346 -   Number tests   = 540
LT  02:03:04.346 -   Repeat count   = 1
LT  02:03:04.346 -   Thinking time  = 0ms..0ms
LT  02:03:04.346 -   Selection mode = random
LT  02:03:04.346 -   Actual seed    = 1548044171656
LT  02:03:04.362 - Parsing inventory file. Root=C:\\Users\\jenkins\\workspace\\Test-extended.system-JDK8-win_x86-64_cmprssptrs\\openjdk-tests\\TestConfig\\test_output_15472799049455\\ConcurrentLoadTest_0\\20190112-020301-ConcurrentLoadTest\\results\\1.LT.inventory File=openjdk.test.load/config/inventories/concurrent/concurrent.xml
LT  02:03:04.378 - Reading exclusion file. File=openjdk.test.load/config/inventories/concurrent/concurrent_exclude.xml
LT  02:03:04.378 - Parsing inventory file. Root=C:\\Users\\jenkins\\workspace\\Test-extended.system-JDK8-win_x86-64_cmprssptrs\\openjdk-tests\\TestConfig\\test_output_15472799049455\\ConcurrentLoadTest_0\\20190112-020301-ConcurrentLoadTest\\results\\1.LT.inventory File=openjdk.test.load/config/inventories/concurrent/concurrent_exclude.xml
LT  02:03:04.378 - Final test list:
LT  02:03:04.378 -   0 JUnit[net.adoptopenjdk.test.concurrent.ArrayBlockingQueueTest]  Weighting=1 
LT  02:03:04.378 -   1 JUnit[net.adoptopenjdk.test.concurrent.ConcurrentHashMapTest]  Weighting=1 
LT  02:03:04.378 -   2 JUnit[net.adoptopenjdk.test.concurrent.ConcurrentLinkedQueueTest]  Weighting=1 
LT  02:03:04.378 -   3 JUnit[net.adoptopenjdk.test.concurrent.ConcurrentSkipListMapTest]  Weighting=1 
LT  02:03:04.378 -   5 JUnit[net.adoptopenjdk.test.concurrent.CopyOnWriteArrayListTest]  Weighting=1 
LT  02:03:04.378 -   6 JUnit[net.adoptopenjdk.test.concurrent.CopyOnWriteArraySetTest]  Weighting=1 
LT  02:03:04.378 -   7 JUnit[net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest]  Weighting=1 
LT  02:03:04.378 -   8 JUnit[net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTestAPI]  Weighting=1 
LT  02:03:04.378 -   9 JUnit[net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTestStress]  Weighting=1 
LT  02:03:04.378 -   10 JUnit[net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinTaskTest]  Weighting=1 
LT  02:03:04.378 -   11 JUnit[net.adoptopenjdk.test.concurrent.jsr166y.LinkedTransferQueueTest]  Weighting=1 
LT  02:03:04.378 -   12 JUnit[net.adoptopenjdk.test.concurrent.jsr166y.PhaserTest]  Weighting=1 
LT  02:03:04.378 -   13 JUnit[net.adoptopenjdk.test.concurrent.jsr166y.ThreadLocalRandomTest]  Weighting=1 
LT  02:03:04.378 -   14 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicBooleanTest]  Weighting=1 
LT  02:03:04.378 -   15 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicIntegerArrayTest]  Weighting=1 
LT  02:03:04.378 -   16 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicIntegerFieldUpdaterTest]  Weighting=1 
LT  02:03:04.378 -   17 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicIntegerTest]  Weighting=1 
LT  02:03:04.378 -   18 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicLongArrayTest]  Weighting=1 
LT  02:03:04.378 -   19 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicLongFieldUpdaterTest]  Weighting=1 
LT  02:03:04.378 -   20 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicLongTest]  Weighting=1 
LT  02:03:04.378 -   21 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicMarkableReferenceTest]  Weighting=1 
LT  02:03:04.378 -   22 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicReferenceArrayTest]  Weighting=1 
LT  02:03:04.378 -   23 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicReferenceFieldUpdaterTest]  Weighting=1 
LT  02:03:04.378 -   24 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicReferenceTest]  Weighting=1 
LT  02:03:04.378 -   25 JUnit[net.adoptopenjdk.test.concurrent.atomic.AtomicStampedReferenceTest]  Weighting=1 
LT  02:03:04.378 -   26 JUnit[net.adoptopenjdk.test.concurrent.locks.ReentrantLockTest]  Weighting=1 
LT  02:03:04.378 -   27 JUnit[net.adoptopenjdk.test.concurrent.locks.ReentrantReadWriteLockTest]  Weighting=1 
LT  02:03:04.409 - Starting thread. Suite=0 thread=0
LT  02:03:04.409 - Starting thread. Suite=0 thread=1
LT  02:03:04.409 - Starting thread. Suite=0 thread=2
LT  02:03:04.409 - Starting thread. Suite=0 thread=3
LT  02:03:04.409 - Starting thread. Suite=0 thread=4
LT  02:03:04.425 - Starting thread. Suite=0 thread=5
LT  02:03:04.425 - Starting thread. Suite=0 thread=6
LT  02:03:04.425 - Starting thread. Suite=0 thread=7
LT  02:03:04.425 - Starting thread. Suite=0 thread=8
LT  02:03:04.425 - Starting thread. Suite=0 thread=9
LT  02:03:04.425 - Starting thread. Suite=0 thread=10
LT  02:03:04.425 - Starting thread. Suite=0 thread=11
LT  02:03:04.425 - Starting thread. Suite=0 thread=12
LT  02:03:04.425 - Starting thread. Suite=0 thread=13
LT  02:03:04.425 - Starting thread. Suite=0 thread=14
LT  02:03:04.425 - Starting thread. Suite=0 thread=15
LT  02:03:04.425 - Starting thread. Suite=0 thread=16
LT  02:03:04.425 - Starting thread. Suite=0 thread=17
LT  02:03:04.425 - Starting thread. Suite=0 thread=18
LT  02:03:04.425 - Starting thread. Suite=0 thread=19
LT  02:03:24.440 - Completed 30.2%. Number of tests started=163
LT  02:03:44.690 - Completed 42.0%. Number of tests started=226 (+63)
LT  02:04:00.253 - First failure detected by thread: load-10. Not creating dumps as no dump generation is requested for this load test
LT  02:04:00.315 - suite.getInventory().getInventoryFileRef(): openjdk.test.load/config/inventories/concurrent/concurrent.xml
LT  02:04:00.315 - suite.isCreateDump() : false
LT  02:04:00.315 - Test failed
LT    Failure num.  = 1
LT    Test number   = 7
LT    Test details  = 'JUnit[net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest]'
LT    Suite number  = 0
LT    Thread number = 10
LT  >>> Captured test output >>>
LT  testStarted : testAPI(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  testFailure: testAPI(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest): 5 : getActiveThreadCount() expected:<0> but was:<1>
LT  junit.framework.AssertionFailedError: 5 : getActiveThreadCount() expected:<0> but was:<1>
LT  	at junit.framework.Assert.fail(Assert.java:57)
LT  	at junit.framework.Assert.failNotEquals(Assert.java:329)
LT  	at junit.framework.Assert.assertEquals(Assert.java:78)
LT  	at junit.framework.Assert.assertEquals(Assert.java:234)
LT  	at junit.framework.TestCase.assertEquals(TestCase.java:401)
LT  	at net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest.testAPI(ForkJoinPoolTest.java:122)
LT  	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
LT  	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
LT  	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
LT  	at java.lang.reflect.Method.invoke(Method.java:498)
LT  	at junit.framework.TestCase.runTest(TestCase.java:176)
LT  	at junit.framework.TestCase.runBare(TestCase.java:141)
LT  	at junit.framework.TestResult$1.protect(TestResult.java:122)
LT  	at junit.framework.TestResult.runProtected(TestResult.java:142)
LT  	at junit.framework.TestResult.run(TestResult.java:125)
LT  	at junit.framework.TestCase.run(TestCase.java:129)
LT  	at junit.framework.TestSuite.runTest(TestSuite.java:252)
LT  	at junit.framework.TestSuite.run(TestSuite.java:247)
LT  	at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:86)
LT  	at org.junit.runners.Suite.runChild(Suite.java:128)
LT  	at org.junit.runners.Suite.runChild(Suite.java:27)
LT  	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
LT  	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
LT  	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
LT  	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
LT  	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
LT  	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
LT  	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
LT  	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
LT  	at net.adoptopenjdk.loadTest.adaptors.JUnitAdaptor.executeTest(JUnitAdaptor.java:130)
LT  	at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
LT  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
LT  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
LT  	at java.lang.Thread.run(Thread.java:813)
LT  testFinished: testAPI(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  testStarted : testStress(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  testFinished: testStress(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  
LT  JUnit Test Results for: net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest
LT    Ran    : 2
LT    Passed : 1
LT    Failed : 1
LT    Ignored: 0
LT    Result : FAILED

The text was updated successfully, but these errors were encountered:

pshipton · 2019-01-16T12:42:11Z

https://ci.eclipse.org/openj9/job/Test-extended.system-JDK8-win_x86-64_cmprssptrs/137

JasonFengJ9 · 2019-01-16T15:02:33Z

Will look at this.

cathyzhyi · 2019-01-16T19:12:43Z

Will look at this.

@0dvictor is aware of the issue and is willing to help if this is JIT related.

JasonFengJ9 · 2019-01-16T22:52:00Z

A few observations:

This is an intermittent failure, ~2/10 (in two different machines) from the test history;
The failure occurred at net/adoptopenjdk/test/concurrent/jsr166y/ForkJoinPoolTest.java

assertEquals("5 : getActiveThreadCount()", 0, apiPool.getActiveThreadCount());

It is interesting to note that the spec states following:

Returns an estimate of the number of threads that are currently stealing or executing tasks. This method may overestimate the number of active threads.

Attempting to reproduce the failure and determine the failure rate.

JasonFengJ9 · 2019-01-17T13:43:24Z

Update:
Not able to reproduce the failure in a 50x grinder at internal jenkins machines.

Next step is to try the Eclipse machines where this PR was reported, hence requesting machine access to win2012r2-x86-2 or win2012r2-x86-3.

Reviewer: @DanHeidinga @pshipton
FYI: @jdekonin

pshipton · 2019-01-17T14:09:08Z

+1

DanHeidinga · 2019-01-17T14:09:33Z

+1

jdekonin · 2019-01-17T16:09:31Z

Discussed with @JasonFengJ9 and we decided launching a grinder on win2012r2-x86-2 would be a good first step. I have launched a 50x with his instruction since he doesn't have that access.

https://ci.eclipse.org/openj9/job/Test-Grinder/199/console

Please advise when the grinder is complete, or further grinder testing is required. win2012r2-x86-2 labels have been removed so no other jobs will land on this machine.

JasonFengJ9 · 2019-01-17T21:06:40Z

Thanks @jdekonin help launching grinders.
2/50 (same command line options) failed at https://ci.eclipse.org/openj9/job/Test-Grinder/199/console.
Another 50x grinder with -Xjit:exclude={java/util/concurrent/ForkJoinPool.*} all passed at https://ci.eclipse.org/openj9/job/Test-Grinder/200/consoleFull.

Could JIT team continue the investigation?
fyi: @0dvictor

jdekonin · 2019-01-17T21:20:29Z

https://ci.eclipse.org/openj9/job/Test-Grinder/202/console
with -Xjit:limit={java/util/concurrent/ForkJoinPool.*} as request for you @0dvictor

0dvictor · 2019-01-18T21:36:34Z

As mentioned earlier, #4277 (comment):

Returns an estimate of the number of threads that are currently stealing or executing tasks. This method may overestimate the number of active threads.

How does the test guarantee that the number of active threads is not overestimated in the assertion?

JasonFengJ9 · 2019-01-21T15:25:53Z

How does the test guarantee that the number of active threads is not overestimated in the assertion?

The spec is kind of confusing. On the other hand, do we understand why excluding the method java/util/concurrent/ForkJoinPool.* from JIT makes the ForkJoinPool.getActiveThreadCount() result consistent and passes the test?

DanHeidinga · 2019-01-23T16:38:14Z

@0dvictor What's the current status of this item? Its one of the few remaining 0.12.0 items

0dvictor · 2019-01-23T16:52:37Z

I believe @hzongaro is working on this issue. It is still under investigation.

hzongaro · 2019-01-24T14:16:17Z

I am able to reproduce this failure reliably on a Windows VM running with this option:

-Xjit:limit={java/util/concurrent/ForkJoinPool.awaitJoin*\|java/util/concurrent/ForkJoinPool.getActiveThreadCount*\|java/util/concurrent/ForkJoinPool.scan*\|java/util/concurrent/ForkJoinPool.signalWork*},count=0,optLevel=cold,lastOptIndex=3,disableInlining

If I remove awaitJoin from the list of methods, it runs successfully. The optimization referenced by lastOptIndex=3 is recognizedCallTransformer in this case.

Interestingly enough, awaitJoin does not appear to be compiled successfully. From a verbose log, we see this:

 java/util/concurrent/ForkJoinPool.awaitJoin(Ljava/util/concurrent/ForkJoinPool$WorkQueue;Ljava/util/concurrent/ForkJoinTask;J)I time=8516873us compilationHeapLimitExceeded memLimit=262144 KB freePhysicalMemory=14099 MB

From the traceFull log for recognizedCallTransformer, we see this, in part:

[    36]   3.1    O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF613CC28F0]
[    37]   3.2    O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF613CC3E30]
[    38]   3.3    O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF613CC5000]
[    39]   3.4    O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF613CC61D0]
[    40]   3.5    O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF613CC73A0]
...
[  6867]   3.6832 O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF605B29740]
[  6868]   3.6833 O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF605B2A910]
[  6869]   3.6834 O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF605B2BAE0]
[  6870]   3.6835 O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF605B2CCB0]
[  6871]   3.6836 O^O RECOGNIZED CALL TRANSFORMER: Transforming recognized call node [0x00007FF605B2DE80]

Looking at the first few call nodes referenced, only the first seems to be an actual call node. Perhaps the others are new nodes created by this optimization that are being endlessly retransformed - that's just a guess. I'm wondering whether there might be memory corruption happening here or elsewhere.

Continuing to investigate.

pshipton · 2019-01-29T20:33:41Z

There is no fix yet, but this is not a blocker for the 0.12 release. Moving to the next milestone.

hzongaro · 2019-02-05T02:10:38Z

Here's where I am in investigating this problem.

When I run locally with the option -Xjit:limit={java/util/concurrent/ForkJoinPool.awaitJoin*\|java/util/concurrent/ForkJoinPool.getActiveThreadCount*\|java/util/concurrent/ForkJoinPool.scan*\|java/util/concurrent/ForkJoinPool.signalWork*},count=0,optLevel=cold,lastOptIndex=3,disableInlining, I find that between test runs java.util.concurrent.awaitWork ends up parking a thread that's part of the ForkJoinPool for about two seconds, as it has no work to do.

The compilation of java.util.concurrent.awaitJoin occurs while that thread is parked, and the compilation goes into an infinite loop, repeatedly transforming a call node (as guessed above) until it runs out of memory. Because I specified the JIT options count=0, asynchronous compilation is disabled, and by the time the compilation fails, more than two seconds has elapsed for the thread that is parked.

The java.util.concurrent.awaitJoin method then stops the thread and in the process temporarily adjusts the number of active threads. The next test begins running and sees the temporarily altered value that causes getActiveThreadCount() to return 1 rather than 0.

So this is a permissible result for getActiveThreadCount() that is triggered by unusual system state.

Now, the problem with compiling ForkJoinPool.awaitJoin was fixed in pull request #4389, but when I did a grinder run with a recent build, ConcurrentLoadTest_0 still failed with the same assertion failure running with Xjit:limit={java/util/concurrent/ForkJoinPool.awaitJoin*\|java/util/concurrent/ForkJoinPool.getActiveThreadCount*\|java/util/concurrent/ForkJoinPool.scan*\|java/util/concurrent/ForkJoinPool.signalWork*} - i.e., with no count or optLevel options.

I am investigating further to verify that the failure still occurs because a thread ends up being parked for too long.

hzongaro · 2019-02-06T21:34:00Z

I've rerun in Grinder in AdoptOpenJDK with a recent nightly build with some extra debugging output captured in methods in ForkJoinPool. I was able to confirm that we're hitting a situation where a thread is being parked, and that if no work comes into the ForkJoinPool by the time the parked thread wakes up again (2 seconds, or a multiple of 2s), the work thread might be killed. That can cause another test that's using that same ForkJoinPool to see a non-zero value returned by getActiveThreadCount().

This happens even without the compilation problem in ForkJoinPool.awaitJoin - presumably if the test is run on machines that are busy enough. When I run the test locally, I never see threads being parked by ForkJoinPool.awaitWork.

So I believe this can be classified as a test case problem.

FYI: @smlambert @llxia

hzongaro · 2019-02-08T14:08:56Z

@pshipton Peter, may I ask you to remove the comp:jit label from this issue? See #4277 (comment) and #4277 (comment) above for more information

pshipton · 2019-02-08T14:29:46Z

Moved to comp:test.

pshipton · 2019-09-21T13:33:12Z

Closing as we haven't seen this occur again.

pshipton · 2019-10-01T13:07:55Z

Another one
https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_extended.system_x86-64_windows_Nightly/155

Not sure this will ever be resolved, I'll keep it closed unless the frequency of failure increases.

pshipton · 2019-10-08T15:50:57Z

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_extended.system_x86-32_windows_Nightly/161

pshipton · 2019-10-18T12:17:25Z

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_extended.system_x86-64_windows_Nightly/170

pshipton · 2020-04-02T13:01:04Z

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_extended.system_x86-32_windows_Nightly/329

JasonFengJ9 · 2020-04-02T23:16:34Z

Observed in an internal build Test_openjdk8_j9_extended.system_x86-64_windows_Nightly/299 as well:

01:56:31  openjdk version "1.8.0_252-internal"
01:56:31  OpenJDK Runtime Environment (build 1.8.0_252-internal-jenkins_2020_04_01_21_43-b00)
01:56:31  Eclipse OpenJ9 VM (build ibm_sdk-ff0268904c, JRE 1.8.0 Windows Server 2016 amd64-64-Bit Compressed References 20200401_369 (JIT enabled, AOT enabled)
01:56:31  OpenJ9   - ff0268904c
01:56:31  OMR      - f719b35c8
01:56:31  JCL      - 4f7bf238294 based on jdk8u252-b08)

LT  02:17:10.612 - Completed 86.1%. Number of tests started=465 (+83)
LT  02:17:17.883 - First failure detected by thread: load-18. Not creating dumps as no dump generation is requested for this load test
LT  02:17:17.983 - suite.getInventory().getInventoryFileRef(): openjdk.test.load/config/inventories/concurrent/concurrent.xml
LT  02:17:17.984 - suite.isCreateDump() : false
LT  02:17:17.986 - Test failed
LT    Failure num.  = 1
LT    Test number   = 7
LT    Test details  = 'JUnit[net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest]'
LT    Suite number  = 0
LT    Thread number = 18
LT  >>> Captured test output >>>
LT  testStarted : testAPI(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  testFailure: testAPI(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest): 5 : getActiveThreadCount() expected:<0> but was:<1>
LT  junit.framework.AssertionFailedError: 5 : getActiveThreadCount() expected:<0> but was:<1>
LT  	at junit.framework.Assert.fail(Assert.java:57)
LT  	at junit.framework.Assert.failNotEquals(Assert.java:329)
LT  	at junit.framework.Assert.assertEquals(Assert.java:78)
LT  	at junit.framework.Assert.assertEquals(Assert.java:234)
LT  	at junit.framework.TestCase.assertEquals(TestCase.java:401)
LT  	at net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest.testAPI(ForkJoinPoolTest.java:122)
LT  	at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
LT  	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
LT  	at java.lang.reflect.Method.invoke(Method.java:498)
LT  	at junit.framework.TestCase.runTest(TestCase.java:176)
LT  	at junit.framework.TestCase.runBare(TestCase.java:141)
LT  	at junit.framework.TestResult$1.protect(TestResult.java:122)
LT  	at junit.framework.TestResult.runProtected(TestResult.java:142)
LT  	at junit.framework.TestResult.run(TestResult.java:125)
LT  	at junit.framework.TestCase.run(TestCase.java:129)
LT  	at junit.framework.TestSuite.runTest(TestSuite.java:252)
LT  	at junit.framework.TestSuite.run(TestSuite.java:247)
LT  	at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:86)
LT  	at org.junit.runners.Suite.runChild(Suite.java:128)
LT  	at org.junit.runners.Suite.runChild(Suite.java:27)
LT  	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
LT  	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
LT  	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
LT  	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
LT  	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
LT  	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
LT  	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
LT  	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
LT  	at net.adoptopenjdk.loadTest.adaptors.JUnitAdaptor.executeTest(JUnitAdaptor.java:130)
LT  	at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
LT  	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
LT  	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
LT  	at java.lang.Thread.run(Thread.java:821)
LT  testFinished: testAPI(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  testStarted : testStress(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  testFinished: testStress(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest)
LT  
LT  JUnit Test Results for: net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest
LT    Ran    : 2
LT    Passed : 1
LT    Failed : 1
LT    Ignored: 0
LT    Result : FAILED
LT  <<<
LT  
LT  02:17:30.633 - Completed 98.7%. Number of tests started=533 (+68) (with 1 failure(s))
LT  02:17:31.758 - Thread completed. Suite=0 thread=14
LT  02:17:31.851 - Thread completed. Suite=0 thread=19
LT  02:17:32.039 - Thread completed. Suite=0 thread=15
LT  02:17:32.961 - Thread completed. Suite=0 thread=3
LT  02:17:37.117 - Thread completed. Suite=0 thread=8
LT  02:17:37.367 - Thread completed. Suite=0 thread=12
LT  02:17:37.992 - Thread completed. Suite=0 thread=0
LT  02:17:39.178 - Thread completed. Suite=0 thread=6
LT  02:17:40.428 - Thread completed. Suite=0 thread=16
LT  02:17:40.918 - Thread completed. Suite=0 thread=9
LT  02:17:41.070 - Thread completed. Suite=0 thread=7
LT  02:17:43.535 - Thread completed. Suite=0 thread=2
LT  02:17:44.387 - Thread completed. Suite=0 thread=5
LT  02:17:44.691 - Thread completed. Suite=0 thread=1
LT  02:17:50.689 - Completed 100.0%. Number of tests started=540 (+7) (with 1 failure(s))
LT  02:17:51.385 - Thread completed. Suite=0 thread=17
LT  02:17:57.980 - Thread completed. Suite=0 thread=10
LT  02:17:57.996 - Thread completed. Suite=0 thread=4
LT  02:18:05.437 - Thread completed. Suite=0 thread=11
LT  02:18:09.904 - Thread completed. Suite=0 thread=13
LT  02:18:10.654 - Completed 100.0%. Number of tests started=540 (+0) (with 1 failure(s))
LT  02:18:14.044 - Thread completed. Suite=0 thread=18
LT  02:18:14.154 - Load test completed
LT  02:18:14.154 -   Ran     : 540
LT  02:18:14.154 -   Passed  : 539
LT  02:18:14.154 -   Failed  : 1
LT  02:18:14.154 -   Result  : FAILED
STF 02:18:14.327 - **FAILED** Process LT  ended with exit code (1) and not the expected exit code/s (0)
STF 02:18:14.328 - Monitoring Report Summary:
STF 02:18:14.328 -   o Process LT  ended with exit code (1) and not the expected exit code/s (0)
STF 02:18:14.329 - Killing processes: LT 
STF 02:18:14.329 -   o Process LT  is not running
**FAILED** at step 1 (Run concurrency unit tests). Expected return value=0 Actual=1 at C:/Users/jenkins/workspace/Test_openjdk8_j9_extended.system_x86-64_windows_Nightly/openjdk-tests/\TKG\test_output_15858072989004\ConcurrentLoadTest_0/20200402-021525-ConcurrentLoadTest/execute.pl line 94.
STF 02:18:14.678 - **FAILED** execute script failed. Expected return value=0 Actual=1
STF 02:18:14.678 - 
STF 02:18:14.678 - ====================   T E A R D O W N   ====================
STF 02:18:14.678 - Running teardown: perl C:/Users/jenkins/workspace/Test_openjdk8_j9_extended.system_x86-64_windows_Nightly/openjdk-tests/\TKG\test_output_15858072989004\ConcurrentLoadTest_0/20200402-021525-ConcurrentLoadTest/tearDown.pl
STF 02:18:14.919 - TEARDOWN stage completed
STF 02:18:14.947 - 
STF 02:18:14.947 - =====================   R E S U L T S   =====================
STF 02:18:14.948 - Stage results:
STF 02:18:14.948 -   setUp:     pass
STF 02:18:14.948 -   execute:  *fail*
STF 02:18:14.948 -   teardown:  pass
STF 02:18:14.948 - 
STF 02:18:14.948 - Overall result: **FAILED**

ConcurrentLoadTest_0_FAILED

To rebuild the failed tests in =https://hyc-runtimes-jenkins.swg-devops.com/job/Grinder, use the following links: https://hyc-runtimes-jenkins.swg-devops.com/job/Grinder/parambuild/?JDK_VERSION=8&JDK_IMPL=openj9&BUILD_LIST=system&PLATFORM=x86-64_windows&TARGET=ConcurrentLoadTest_0

pshipton · 2020-06-17T13:33:45Z

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_extended.system_x86-64_windows_Nightly/401

karianna · 2020-07-13T11:32:33Z

adoptium/aqa-tests#1881

pshipton added the test failure label Jan 12, 2019

pshipton changed the title ~~Test-extended.system-JDK8-win_x86-64_cmprssptrs ConcurrentLoadTest_0 getActiveThreadCount() expected:<0> but was:<1>~~ Test-extended.system-JDK8-win_x86-64_cmprssptrs ConcurrentLoadTest_0 ForkJoinPoolTest getActiveThreadCount() expected:<0> but was:<1> Jan 12, 2019

pshipton added this to the Release 0.12.0 (Java 8, 11 Jan refresh) milestone Jan 16, 2019

pshipton added the comp:jit label Jan 24, 2019

pshipton modified the milestones: Release 0.12.0 (Java 8, 11 Jan refresh), Release 0.13.0 (Java 12) Jan 29, 2019

pshipton added comp:test and removed comp:jit labels Feb 8, 2019

pshipton removed this from the Release 0.13.0 (Java 12) milestone Feb 20, 2019

pshipton closed this as completed Sep 21, 2019

pshipton mentioned this issue Jun 4, 2020

ConcurrentLoadTest_0: testAPI(net.adoptopenjdk.test.concurrent.jsr166y.ForkJoinPoolTest): 5 : getActiveThreadCount() expected:<0> but was:<1> #9797

Closed

This was referenced Jul 13, 2020

ConcurrentLoadTest_0 FAILED in Test_openjdk8_hs_extended.system_x86-64_windows adoptium/aqa-tests#1881

Closed

Promote AdoptOpenJDK Version jdk8u262-b10 AdoptOpenJDK/TSC#163

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Test-extended.system-JDK8-win_x86-64_cmprssptrs ConcurrentLoadTest_0 ForkJoinPoolTest getActiveThreadCount() expected:<0> but was:<1> #4277

Test-extended.system-JDK8-win_x86-64_cmprssptrs ConcurrentLoadTest_0 ForkJoinPoolTest getActiveThreadCount() expected:<0> but was:<1> #4277

pshipton commented Jan 12, 2019

pshipton commented Jan 16, 2019

JasonFengJ9 commented Jan 16, 2019

cathyzhyi commented Jan 16, 2019

JasonFengJ9 commented Jan 16, 2019

JasonFengJ9 commented Jan 17, 2019

pshipton commented Jan 17, 2019

DanHeidinga commented Jan 17, 2019

jdekonin commented Jan 17, 2019

JasonFengJ9 commented Jan 17, 2019

jdekonin commented Jan 17, 2019

0dvictor commented Jan 18, 2019

JasonFengJ9 commented Jan 21, 2019

DanHeidinga commented Jan 23, 2019

0dvictor commented Jan 23, 2019

hzongaro commented Jan 24, 2019

pshipton commented Jan 29, 2019

hzongaro commented Feb 5, 2019

hzongaro commented Feb 6, 2019

hzongaro commented Feb 8, 2019

pshipton commented Feb 8, 2019

pshipton commented Sep 21, 2019

pshipton commented Oct 1, 2019

pshipton commented Oct 8, 2019

pshipton commented Oct 18, 2019

pshipton commented Apr 2, 2020

JasonFengJ9 commented Apr 2, 2020

pshipton commented Jun 17, 2020

karianna commented Jul 13, 2020

Test-extended.system-JDK8-win_x86-64_cmprssptrs ConcurrentLoadTest_0 ForkJoinPoolTest getActiveThreadCount() expected:<0> but was:<1> #4277

Test-extended.system-JDK8-win_x86-64_cmprssptrs ConcurrentLoadTest_0 ForkJoinPoolTest getActiveThreadCount() expected:<0> but was:<1> #4277

Comments

pshipton commented Jan 12, 2019

pshipton commented Jan 16, 2019

JasonFengJ9 commented Jan 16, 2019

cathyzhyi commented Jan 16, 2019

JasonFengJ9 commented Jan 16, 2019

JasonFengJ9 commented Jan 17, 2019

pshipton commented Jan 17, 2019

DanHeidinga commented Jan 17, 2019

jdekonin commented Jan 17, 2019

JasonFengJ9 commented Jan 17, 2019

jdekonin commented Jan 17, 2019

0dvictor commented Jan 18, 2019

JasonFengJ9 commented Jan 21, 2019

DanHeidinga commented Jan 23, 2019

0dvictor commented Jan 23, 2019

hzongaro commented Jan 24, 2019

pshipton commented Jan 29, 2019

hzongaro commented Feb 5, 2019

hzongaro commented Feb 6, 2019

hzongaro commented Feb 8, 2019

pshipton commented Feb 8, 2019

pshipton commented Sep 21, 2019

pshipton commented Oct 1, 2019

pshipton commented Oct 8, 2019

pshipton commented Oct 18, 2019

pshipton commented Apr 2, 2020

JasonFengJ9 commented Apr 2, 2020

pshipton commented Jun 17, 2020

karianna commented Jul 13, 2020