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: <http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20140807/a3b5a083/attachment.html>
-------------- 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