RFR: (S) 8050464: G1 string deduplication tests hang/timeout and leave running processes consuming all resources
Dmitry Fazunenko
dmitry.fazunenko at oracle.com
Thu Aug 7 10:01:11 UTC 2014
Jon,
Thanks for looking!
I love printing as much debug info as possible. But in this case I have
nothing to add.
BTW, the deduplication tests are full of various System.out.prinltn(),
so I think the it will be enough information in case of failure.
I modified a little the code to make test fail. The jtr is attached.
Please let me know if you believe that more data need to be printed.
Thanks,
Dima
On 06.08.2014 23:56, Jon Masamitsu wrote:
> Dima,
>
> If the test fails, can you print the strings with System.out.println() or
> System.err.println()? Any information about the strings might be
> useful to understand why deduplication didn't work or why the
> test thinks the deduplication didn't work (in case something
> happens that the test doesn't expect)?
>
> Jon
>
> On 8/6/2014 8:53 AM, Dmitry Fazunenko wrote:
>> Hi,
>>
>> Would you please look at the simple fix of String Deduplication tests.
>>
>> Description:
>>
>> When string deduplication has happened /s1.equals(s2)/ will be
>> equivalent to /s1 == s2/
>> Deduplication is performed in a separate thread so it could be
>> delayed a bit.
>> Tests are away about possible delay and give another chance if
>> deduplication hasn't
>> happened by the moment of check.
>> But tests wait for deduplication in infinitive loop, so if
>> deduplication doesn't work the tests
>> will timeout, leaving hanging VM after. Which is not very elegant.
>>
>> The fix is simple: replace infinitive loops with limited ones and
>> report failure.
>> The logic of the tests hasn't changed.
>>
>> http://cr.openjdk.java.net/~dfazunen/8050464/webrev.01/
>> https://bugs.openjdk.java.net/browse/JDK-8050464
>>
>> Any comments are welcome.
>>
>> Thanks,
>> Dima
>>
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20140807/a3b5a083/attachment.htm>
-------------- next part --------------
#Test Results (version 2)
#Thu Aug 07 13:51:17 MSK 2014
#-----testdescription-----
$file=/home/dfazunen/ws/hs-gc/test/gc/g1/TestStringDeduplicationFullGC.java
$root=/home/dfazunen/ws/hs-gc/test
keywords=bug8029075 gc
library=/testlibrary
run=ASSUMED_ACTION main TestStringDeduplicationFullGC\n
source=TestStringDeduplicationFullGC.java
title=Test string deduplication during full GC
#-----environment-----
#-----testresult-----
description=file\:/home/dfazunen/ws/hs-gc/test/gc/g1/TestStringDeduplicationFullGC.java
elapsed=17794 0\:00\:17.794
end=Thu Aug 07 13\:51\:17 MSK 2014
environment=regtest
execStatus=Failed. Execution failed\: `main' threw exception\: java.lang.RuntimeException\: Expected to get exit value of [0]
harnessLoaderMode=Classpath Loader
harnessVariety=Full Bundle
hostname=localhost
javatestOS=SunOS 5.11 (amd64)
javatestVersion=4.5
jtregVersion=jtreg 4.0 dev b00
script=com.sun.javatest.regtest.RegressionScript
sections=script_messages build compile main
start=Thu Aug 07 13\:50\:59 MSK 2014
test=gc/g1/TestStringDeduplicationFullGC.java
totalTime=17801
user.name=dfazunen
work=/home/dfazunen/ws/hs-gc/test/JTwork/gc/g1
#section:script_messages
----------messages:(5/219)----------
JDK under test: (/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64)
java version "1.9.0-ea"
Java(TM) SE Runtime Environment (build 1.9.0-ea-b24)
Java HotSpot(TM) 64-Bit Server VM (build 1.9.0-ea-b24, mixed mode)
#section:build
----------messages:(3/114)----------
command: build TestStringDeduplicationFullGC
reason: Named class compiled on demand
elapsed time (seconds): 3.402
result: Passed. Build successful
#section:compile
----------messages:(3/194)----------
command: compile -XDignore.symbol.file=true /home/dfazunen/ws/hs-gc/test/gc/g1/TestStringDeduplicationFullGC.java
reason: .class file out of date or does not exist
elapsed time (seconds): 3.383
----------rerun:(20/1458)*----------
DISPLAY=fa:0.0 \\
GNOME_DESKTOP_SESSION_ID=this-is-deprecated \\
HOME=/home/dfazunen \\
LANG=ru_RU.UTF-8 \\
LC_ALL=C \\
PATH=/bin:/usr/bin \\
PRINTER=spb04p14 \\
/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64/bin/javac \\
-J-Dtest.vm.opts= \\
-J-Dtest.jdk=/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64 \\
-J-Dtest.timeout.factor=1.0 \\
-J-Dtest.src.path=/home/dfazunen/ws/hs-gc/test/gc/g1:/home/dfazunen/ws/hs-gc/test/testlibrary \\
-J-Dtest.compiler.opts= \\
-J-Dcompile.jdk=/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64 \\
-J-Dtest.classes=/home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1 \\
-J-Dtest.class.path=/home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1:/home/dfazunen/ws/hs-gc/test/JTwork/classes/testlibrary \\
-J-Dtest.java.opts= \\
-J-Dtest.src=/home/dfazunen/ws/hs-gc/test/gc/g1 \\
-J-Dtest.tool.vm.opts= \\
-d /home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1 -classpath /home/dfazunen/ws/jtreg/dist/jtreg/lib/javatest.jar:/home/dfazunen/ws/jtreg/dist/jtreg/lib/jtreg.jar:/home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1:/home/dfazunen/ws/hs-gc/test/gc/g1:/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64/lib/tools.jar -sourcepath /home/dfazunen/ws/hs-gc/test/gc/g1:/home/dfazunen/ws/hs-gc/test/testlibrary -XDignore.symbol.file=true /home/dfazunen/ws/hs-gc/test/gc/g1/TestStringDeduplicationFullGC.java
----------System.out:(0/0)----------
----------System.err:(0/0)----------
result: Passed. Compilation successful
#section:main
----------messages:(3/158)----------
command: main TestStringDeduplicationFullGC
reason: Assumed action based on file name: run main TestStringDeduplicationFullGC
elapsed time (seconds): 11.505
----------System.out:(64/3695)----------
Command line: [/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64/bin/java -d64 -Xmn50m -Xms100m -Xmx100m -XX:+UseG1GC -XX:+UnlockDiagnosticVMOptions -XX:+VerifyAfterGC -XX:+PrintGC -XX:+PrintStringDeduplicationStatistics -XX:+UseStringDeduplication -XX:StringDeduplicationAgeThreshold=3 TestStringDeduplicationTools$DeduplicationTest 10000 5000 3 FullGC ]
Begin: DeduplicationTest
Creating strings: total=10000, unique=5000
Begin: Full GC 1/3
#0: [Full GC (System.gc()) VerifyAfterGC:[Verifying threads heap Roots HeapRegionSets HeapRegions RemSet StrDedup syms strs zone dict metaspace chunks hand C-heap code cache ]
4609K->1916K(100M), 0.0202693 secs]
[GC concurrent-string-deduplication, 1230.9K->633.2K(597.7K), avg 48.6%, 0.0040028 secs]
[Last Exec: 0.0040028 secs, Idle: 0.0000005 secs, Blocked: 0/0.0000000 secs]
[Inspected: 11835]
[Skipped: 0( 0.0%)]
[Hashed: 10607( 89.6%)]
[Known: 946( 8.0%)]
[New: 10889( 92.0%) 1230.9K]
[Deduplicated: 5126( 47.1%) 597.7K( 48.6%)]
[Young: 0( 0.0%) 0.0B( 0.0%)]
[Old: 5126(100.0%) 597.7K(100.0%)]
[Total Exec: 1/0.0040028 secs, Idle: 1/0.0000005 secs, Blocked: 0/0.0000000 secs]
[Inspected: 11835]
[Skipped: 0( 0.0%)]
[Hashed: 10607( 89.6%)]
[Known: 946( 8.0%)]
[New: 10889( 92.0%) 1230.9K]
[Deduplicated: 5126( 47.1%) 597.7K( 48.6%)]
[Young: 0( 0.0%) 0.0B( 0.0%)]
[Old: 5126(100.0%) 597.7K(100.0%)]
[Table]
[Memory Usage: 165.2K]
[Size: 1024, Min: 1024, Max: 16777216]
[Entries: 6709, Load: 655.2%, Cached: 0, Added: 6726, Removed: 17]
[Resize Count: 0, Shrink Threshold: 682(66.7%), Grow Threshold: 2048(200.0%)]
[Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0x0]
[Age Threshold: 3]
[Queue]
[Dropped: 0]
End: Full GC 1/3
Begin: Full GC 2/3
#1: [Full GC (System.gc()) VerifyAfterGC:[Verifying threads heap Roots HeapRegionSets HeapRegions RemSet StrDedup syms strs zone dict metaspace chunks hand C-heap code cache ]
2428K->1309K(100M), 0.0150873 secs]
End: Full GC 2/3
Begin: Full GC 3/3
#2: [Full GC (System.gc()) VerifyAfterGC:[Verifying threads heap Roots HeapRegionSets HeapRegions RemSet StrDedup syms strs zone dict metaspace chunks hand C-heap code cache ]
1821K->1309K(100M), 0.0136155 secs]
End: Full GC 3/3
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
----------System.err:(92/5030)----------
Exception in thread "main" java.lang.RuntimeException: String verification failed
at TestStringDeduplicationTools.verifyStrings(TestStringDeduplicationTools.java:181)
at TestStringDeduplicationTools.access$200(TestStringDeduplicationTools.java:35)
at TestStringDeduplicationTools$DeduplicationTest.main(TestStringDeduplicationTools.java:217)
stdout: [Begin: DeduplicationTest
Creating strings: total=10000, unique=5000
Begin: Full GC 1/3
#0: [Full GC (System.gc()) VerifyAfterGC:[Verifying threads heap Roots HeapRegionSets HeapRegions RemSet StrDedup syms strs zone dict metaspace chunks hand C-heap code cache ]
4609K->1916K(100M), 0.0202693 secs]
[GC concurrent-string-deduplication, 1230.9K->633.2K(597.7K), avg 48.6%, 0.0040028 secs]
[Last Exec: 0.0040028 secs, Idle: 0.0000005 secs, Blocked: 0/0.0000000 secs]
[Inspected: 11835]
[Skipped: 0( 0.0%)]
[Hashed: 10607( 89.6%)]
[Known: 946( 8.0%)]
[New: 10889( 92.0%) 1230.9K]
[Deduplicated: 5126( 47.1%) 597.7K( 48.6%)]
[Young: 0( 0.0%) 0.0B( 0.0%)]
[Old: 5126(100.0%) 597.7K(100.0%)]
[Total Exec: 1/0.0040028 secs, Idle: 1/0.0000005 secs, Blocked: 0/0.0000000 secs]
[Inspected: 11835]
[Skipped: 0( 0.0%)]
[Hashed: 10607( 89.6%)]
[Known: 946( 8.0%)]
[New: 10889( 92.0%) 1230.9K]
[Deduplicated: 5126( 47.1%) 597.7K( 48.6%)]
[Young: 0( 0.0%) 0.0B( 0.0%)]
[Old: 5126(100.0%) 597.7K(100.0%)]
[Table]
[Memory Usage: 165.2K]
[Size: 1024, Min: 1024, Max: 16777216]
[Entries: 6709, Load: 655.2%, Cached: 0, Added: 6726, Removed: 17]
[Resize Count: 0, Shrink Threshold: 682(66.7%), Grow Threshold: 2048(200.0%)]
[Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0x0]
[Age Threshold: 3]
[Queue]
[Dropped: 0]
End: Full GC 1/3
Begin: Full GC 2/3
#1: [Full GC (System.gc()) VerifyAfterGC:[Verifying threads heap Roots HeapRegionSets HeapRegions RemSet StrDedup syms strs zone dict metaspace chunks hand C-heap code cache ]
2428K->1309K(100M), 0.0150873 secs]
End: Full GC 2/3
Begin: Full GC 3/3
#2: [Full GC (System.gc()) VerifyAfterGC:[Verifying threads heap Roots HeapRegionSets HeapRegions RemSet StrDedup syms strs zone dict metaspace chunks hand C-heap code cache ]
1821K->1309K(100M), 0.0136155 secs]
End: Full GC 3/3
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
Verifying strings: total=10000, uniqueFound=5000, uniqueExpected=5000
Deduplication not completed, waiting...
];
stderr: [Exception in thread "main" java.lang.RuntimeException: String verification failed
at TestStringDeduplicationTools.verifyStrings(TestStringDeduplicationTools.java:181)
at TestStringDeduplicationTools.access$200(TestStringDeduplicationTools.java:35)
at TestStringDeduplicationTools$DeduplicationTest.main(TestStringDeduplicationTools.java:217)
]
exitValue = 1
java.lang.RuntimeException: Expected to get exit value of [0]
at com.oracle.java.testlibrary.OutputAnalyzer.shouldHaveExitValue(OutputAnalyzer.java:296)
at TestStringDeduplicationTools.testFullGC(TestStringDeduplicationTools.java:356)
at TestStringDeduplicationFullGC.main(TestStringDeduplicationFullGC.java:34)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:484)
at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94)
at java.lang.Thread.run(Thread.java:745)
JavaTest Message: Test threw exception: java.lang.RuntimeException: Expected to get exit value of [0]
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Expected to get exit value of [0]
----------rerun:(21/1320)*----------
DISPLAY=fa:0.0 \\
GNOME_DESKTOP_SESSION_ID=this-is-deprecated \\
HOME=/home/dfazunen \\
LANG=ru_RU.UTF-8 \\
LC_ALL=C \\
PATH=/bin:/usr/bin \\
PRINTER=spb04p14 \\
CLASSPATH=/home/dfazunen/ws/jtreg/dist/jtreg/lib/javatest.jar:/home/dfazunen/ws/jtreg/dist/jtreg/lib/jtreg.jar:/home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1:/home/dfazunen/ws/hs-gc/test/gc/g1:/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64/lib/tools.jar \\
/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64/bin/java \\
-Dtest.vm.opts= \\
-Dtest.jdk=/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64 \\
-Dtest.timeout.factor=1.0 \\
-Dtest.src.path=/home/dfazunen/ws/hs-gc/test/gc/g1:/home/dfazunen/ws/hs-gc/test/testlibrary \\
-Dtest.compiler.opts= \\
-Dcompile.jdk=/set/java/re/jdk/9/promoted/ea/b24/binaries/solaris-x64 \\
-Dtest.classes=/home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1 \\
-Dtest.class.path=/home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1:/home/dfazunen/ws/hs-gc/test/JTwork/classes/testlibrary \\
-Dtest.java.opts= \\
-Dtest.src=/home/dfazunen/ws/hs-gc/test/gc/g1 \\
-Dtest.tool.vm.opts= \\
com.sun.javatest.regtest.MainWrapper /home/dfazunen/ws/hs-gc/test/JTwork/classes/gc/g1/TestStringDeduplicationFullGC.jta
result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Expected to get exit value of [0]
test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Expected to get exit value of [0]
More information about the hotspot-gc-dev
mailing list