[Patch] JTreg case FiniteGCLatency.java failed randomly when using Serial GC.

[yuanxiang (F)]

Hi,
	I sent these two mails last Friday, and haven't seen them until this week. I think there may be something wrong with my mail system, so I resent them... ( But I haven't received all of them from aarch32-port-dev at openjdk.java.net until now. )
	Sorry for the repetitive mails in the mail list.

	These two bugs are hard to reproduce...
	To the case FiniteGCLatency.java, we tested it on about 10 arm boards, and only 2 boards can reproduce it. On one of the 2 boards, one use accord can reproduce, while other one can't. May be this is because the proper uninitialized values are hard to get.

	And to the case TransformationWarningsTest, it needs many runs to reproduce. On a 2-core board, we ran it more than 10,000 times to reproduces. On ARM JUNO boards, it also needs more than 1,000 times to reproduce. May be this is because the error scenario is very hard to occur. It needs one thread to write to the constant pool cache, and another thread is reading the same entry at the same time.

	

	Best Wishes!

	Xiang Yuan
	09/01/2016

----------------------------------------------------------------------------
On 8/31/2016 21:54, Alex wrote:

Hi,

On 08/26/2016 10:42 AM, yuanxiang (F) wrote:
> HI, all:
>           We found than JTReg test case jdk/test/java/rmi/server/Unreferenced/finiteGCLatency/FiniteGCLatency.java may fail sometimes.
>
> It reported:
> /*******************************************/
>
> Regression test for bug 4164696
>
> exported remote object
> created registry
> bound remote object in registry
> unbound remote object from registry; waiting for unreferenced() callback...
> java.lang.RuntimeException: TEST FAILED: unrefereced() not invoked after 50.0 seconds
>   at FiniteGCLatency.main(FiniteGCLatency.java:97)
>   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:498)
>   at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:110)
>   at java.lang.Thread.run(Thread.java:745)
>
> JavaTest Message: Test threw exception: java.lang.RuntimeException: 
> TEST FAILED: unrefereced() not invoked after 50.0 seconds JavaTest 
> Message: shutting down test 
> /*******************************************/
>
> Test command:
> jtreg -va -nr ./jdk8u-aarch32/jdk/test/java/rmi/server/Unreferenced/finiteGCLatency/FiniteGCLatency.java
>           (Use Serial GC.)
>
> This bug is random, and we may need to test it on different account or machine to reproduce.

Just for the record, I cannot reproduce neither this nor the TransformationWarningsTest failures on 3 different arm boards. It probably requires a bigger machine to reproduce this.

>
>           We found the root cause is that the field _time_of_last_gc of class Generation is not initialized.
>
>
>           This case sets RMI GC interval to 6s, and waits for method Unreferenced to be invoked in 50s.
>           In the failed cases, method Unreferenced didn't been invoked.
>
> And this is because:
>           (1) test case sets 6000ms to sun.rmi.dgc.client.gcInterval
>           (2) DGCClient.lookup() creates a new GC$LatencyRequest object to set the new interval.
>           (3) And the following method calls are:
> constructor GC$LatencyRequest() --> GC$LatencyRequest.adjustLatencyIfNeeded() --> GC$Daemon.setLatencyTarget() -->
> create or notify thread GC$Daemon --> GC$Daemon.run() -->
>                 GC.maxObjectInspectionAge() --> GenCollectedHeap::millis_since_last_gc() -->
>                 GenCollectedHead::generation_iterate() --> GenTimeOfLastGCClosure.do_generation() -->
>                 Generation.time_of_last_gc()
>           (4) Generation.time_of_last_gc() returns the static field _time_of_last_gc, however it hasn't been initialized.
>           (5) If the value of _time_of_last_gc is very big, the test case fails.
>
> The analysis above takes Serial GC as example.
> According to the codes, CMS GC may have the same problem. Parallel GC initializes the field _time_of_last_gc and is OK.
>
>
> Following is the patch to fix this problem.
> /*******************************Patch Begin**********************************/
> Index: hotspot/src/share/vm/memory/generation.cpp
> ===================================================================
> --- hotspot/src/share/vm/memory/generation.cpp
> +++ hotspot/src/share/vm/memory/generation.cpp
> @@ -46,6 +46,7 @@
> PRAGMA_FORMAT_MUTE_WARNINGS_FOR_GCC
>
>   Generation::Generation(ReservedSpace rs, size_t initial_size, int level) :
> +  _time_of_last_gc(0L),
>     _level(level),
>     _ref_processor(NULL) {
>     if (!_virtual_space.initialize(rs, initial_size)) {
> Index: hotspot/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp
> ===================================================================
> --- hotspot/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp
> +++ hotspot/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp
> @@ -553,6 +553,7 @@
> CMSCollector::CMSCollector(ConcurrentMarkSweepGeneration* cmsGen,
>                              CardTableRS*                   ct,
>                              ConcurrentMarkSweepPolicy*     cp):
> +  _time_of_last_gc(0L),
>     _cmsGen(cmsGen),
>     _ct(ct),
>     _ref_processor(NULL),    // will be set later
> /*******************************Patch End**********************************/
>
>
>
> Best Regrards!
>
>
> Xiang Yuan
> 8/26/2016
>
>
>
>


-- 
-Alex