JDK-8148940 : java/lang/ref/FinalizeOverride.java can time out due to frequent safepointing
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 8u112,9
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: solaris
  • CPU: sparc
  • Submitted: 2016-02-03
  • Updated: 2016-11-23
  • Resolved: 2016-02-29
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9 b110Fixed
Related Reports
Relates :  
JDK-8150717 - Bootstrapping invokedynamic call sites can significantly increase time spent in the VM
Relates :  
JDK-8148483 - JEP 280 Integration
Description
The test "java/lang/ref/FinalizeOverride.java" times out after 2409.158 seconds. From the pstack output it looks as if the main thread (lwp# 25) is waiting for compilation to complete (BackgroundCompilation is turned off due to -Xcomp):

 fffffff12e10f000 __1cNCompileBrokerTwait_for_completion6FpnLCompileTask__v_ (1014a3750, 1, 0, fffffff12f4e0f28, fffffff12efcbdd8, fffffff12f55b558) + 1b0

The compiler thread (lwp# 31) is blocking:
 ffffffff7eae9aec lwp_cond_wait (1005ca450, 1005ca438, 0, 0)
 fffffff12ea55668 __1cCosNPlatformEventEpark6M_v_ (1005ca400, ffffffffffffffff, 1005d4901, 1005ca450, fffffff12f237af0, 0) + 158
 fffffff12e9d2b70 __1cHMonitorFILock6MpnGThread__v_ (1001be260, 1005c8800, fffffff12f56d520, 1005ca401, fffffff12f20ce14, 1001be268) + 180
 fffffff12e9d3c98 __1cHMonitorbClock_without_safepoint_check6MpnGThread__v_ (1001be260, 1005c8800, ffffffff7d401c00, 0, 2d4000, 1) + 78
 fffffff12eba6574 __1cUSafepointSynchronizeFblock6FpnKJavaThread__v_ (1005c8800, deab, deab, fffffff12f5975d0, 5, fffffff12f5a3d00) + 294
 fffffff12ed396ec __1cKJavaThreadbScheck_safepoint_and_suspend_for_native_trans6Fp0_v_ (1005c8800, 20000000, 0, fffffff12f2faa38, fffffff12f4e0f28, 1005c8800) + 19c
 fffffff12de191ec __1cVThreadStateTransitionWtransition_from_native6FpnKJavaThread_nPJavaThreadState__v_ (1005c8800, 6, ffffffff7c500000, 8c000, 8c3e1, fffffff12f4e0f28) + 12c
 fffffff12df81ab0 __1cFciEnvPregister_method6MpnIciMethod_ipnLCodeOffsets_ipnKCodeBuffer_ipnJOopMapSet_pnVExceptionHandlerTable_pnWImplicitExceptionTable_pnQAbstractCompiler_bbnIRTMState__v_ (ffffffff588ff2d8, 10f0fdb30, ffffffffffffffff, ffffffff588fed30, 1b0, ffffffff588fed58) + 90
 fffffff12dde51cc __1cLCompilationMinstall_code6Mi_v_ (ffffffff588fec68, ffffffff588ff2d8, 1005c9860, fffffff12eed9608, 10f0fdb30, 1b0) + 17c

Only seen on Solaris Sparc. Could be related to recent compiler upgrade.
Comments
Since Indify String Concatenation (JDK-8148483) was pushed, the execution time of the java/lang/ref/FinalizeOverride.java test increased by 2-89X. The increase can be measured both with -Xmixed and -Xcomp and it results from a combination of two main factors: (1) The test spends an increased amount of time in the VM (e.g., because an ISC-enabled build can trigger up to 2X more compilations than a non-ISC-enabled build); (2) The test triggers safepointing frequently. Here are some details on these factors. Factor (2) is caused by the main() method of the test triggers GC and finalization in a tight loop: while (finalizedCount.get() != (count+1)) { System.gc(); System.runFinalization(); } Each GC triggers a safepoint that is observed by all threads of the VM (including compiler threads when they, for example, access VM-internal data during compilation). Factor (1) is caused by the string concatenations performed in the finalize() method of the classes PrivateFinalize, SubSubClass, SubClass, PublicFinalize, and Base. Bootstrapping of the string-related invokedynamic calls in these classes causes more time to be spent in the VM and can trigger additional compilations (up to 2X more). Factor (1) and (2) interplay in the following manner: Finalization happens concurrently with the main thread of the test. As more time is spent in the VM, more safepoints are observed, which slows down the progress of the whole VM (including the test). At the same time, the main thread has the chance to trigger more safepoints. Here are some numbers (incl. execution time, number of safepoints and compilations) measured on two different platforms. linux-x86_64, -Xmixed configuration | execution time | #GC safepoints | #compiled methods ========================================== no-ISC | 0.2s | 8 | 21 ISC | 2.8s | 247 | 102 linux-x86_64, -Xcomp configuration | execution time | #GC safepoints | #compiled methods ========================================== no-ISC | 3s | 11 | 1081 ISC | 25s | 250 | 2208 solaris_sparcv9, -Xmixed configuration | execution time | #GC safepoints | #compiled methods ========================================== no-ISC | 9s | 6 | 30 ISC | 32s | 105 | 91 solaris_sparcv9, -Xcomp configuration | execution time | #GC safepoints | #compiled methods ========================================== no-ISC | 41s | 11 | 1025 ISC | 3657s | 3801 | 2146
25-02-2016
Solution #1: Reduce the freqency of triggering GCs http://cr.openjdk.java.net/~zmajo/8148940/webrev.00/ Solution #2: Remove string operations from finalizers. http://cr.openjdk.java.net/~zmajo/8148940/webrev.01/ linux-x86_64, -Xmixed | execution time ============================ webrev.00 | 1s webrev.01 | 0.8s linux-x86_64, -Xcomp | execution time | #GC safepoints | #compiled methods ================================================= webrev.00 | 44s | 6 | 2204 webrev.01 | 18s | 15 | 1048 solaris_sparcv9, -Xmixed | execution time ============================ webrev.00 | 11s webrev.01 | 04s solaris_sparcv9, -Xcomp | execution time | #GC safepoints | #compiled methods ================================================= webrev.00 | 60s | 25 | 2121 webrev.01 | 43s | 6 | 991
25-02-2016
The stack shows the compiler thread is blocking for a safepoint.
03-02-2016