JDK-8307788 : vmTestbase/gc/gctests/LargeObjects/large003/TestDescription.java timed out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 21,22
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2023-05-09
  • Updated: 2024-06-03
  • Resolved: 2024-01-25
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 21 JDK 22 JDK 23
21.0.5-oracleFixed 22Fixed 23 b07Fixed
Related Reports
Relates :  
JDK-8324205 - Excessive C2 compilation time when parsing allocation of large object
Relates :  
JDK-8324755 - Enable parallelism in vmTestbase/gc/gctests/LargeObjects tests
Description
The following test timed out in the JDK21 CI:

vmTestbase/gc/gctests/LargeObjects/large003/TestDescription.java

Here's a snippet from the log file:

#section:main
----------messages:(8/549)----------
command: main -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields false -aggregationDepth 3 -t 1
reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields false -aggregationDepth 3 -t 1 
started: Tue May 09 16:43:25 UTC 2023
Mode: othervm [/othervm specified]
Timeout information:
--- Timeout information end.
finished: Tue May 09 16:55:27 UTC 2023
elapsed time (seconds): 721.933
----------configuration:(0/0)----------
----------System.out:(280/11592)*----------
Stress time: 30 seconds
Stress iterations factor: 1
Stress threads factor: 1
Stress runs factor: 1
Max memory: 1037959168
Sleep time: 500
Iterations: 0
Number of threads: 1
Run GC thread: false
Run mem diag thread: false
Run forever: false
Loading classes that have number of fields under limitation (less than 65535)
Starting Thread[#17,gc.gctests.LargeObjects.large001.large001$Worker@151dd4a1,5,MainThreadGroup]
0: Loading class: nsk.share.gc.newclass.private_int_schild
0: Class loaded: nsk.share.gc.newclass.private_int_schild
0: Instance of the class: nsk.share.gc.newclass.private_int_schild@25de2e93
Added field objC  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
0: Testing non-null after GC force for: nsk.share.gc.newclass.private_int_schild
0: Unloading class: nsk.share.gc.newclass.private_int_schild
0: Result of uloading class nsk.share.gc.newclass.private_int_schild: false
0: Loading class: nsk.share.gc.newclass.protected_short_schild
0: Class loaded: nsk.share.gc.newclass.protected_short_schild
0: Instance of the class: nsk.share.gc.newclass.protected_short_schild@73c9b352
Added field objC  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
0: Testing non-null after GC force for: nsk.share.gc.newclass.protected_short_schild
0: Unloading class: nsk.share.gc.newclass.protected_short_schild
0: Result of uloading class nsk.share.gc.newclass.protected_short_schild: false
0: Loading class: nsk.share.gc.newclass.public_long_schild
0: Class loaded: nsk.share.gc.newclass.public_long_schild
0: Instance of the class: nsk.share.gc.newclass.public_long_schild@2829028d

<snip>

0: Testing non-null after GC force for: nsk.share.gc.newclass.static_combination_schild
0: Unloading class: nsk.share.gc.newclass.static_combination_schild
0: Result of uloading class nsk.share.gc.newclass.static_combination_schild: false
0: Loading class: nsk.share.gc.newclass.transient_combination_schild
0: Class loaded: nsk.share.gc.newclass.transient_combination_schild
0: Instance of the class: nsk.share.gc.newclass.transient_combination_schild@216fd47b
Added field objC  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
0: Testing non-null after GC force for: nsk.share.gc.newclass.transient_combination_schild
0: Unloading class: nsk.share.gc.newclass.transient_combination_schild
0: Result of uloading class nsk.share.gc.newclass.transient_combination_schild: false
0: Loading class: nsk.share.gc.newclass.volatile_combination_schild
0: Class loaded: nsk.share.gc.newclass.volatile_combination_schild
0: Instance of the class: nsk.share.gc.newclass.volatile_combination_schild@7bf78a56
Added field objC  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 3
Added field objC  .... 2
Added field objC  .... 1
Added field objP  .... 1
Added field objP  .... 2
Added field objC  .... 1
Added field objP  .... 1
0: Testing non-null after GC force for: nsk.share.gc.newclass.volatile_combination_schild
0: Unloading class: nsk.share.gc.newclass.volatile_combination_schild
0: Result of uloading class nsk.share.gc.newclass.volatile_combination_schild: false
No unexpected exceptions/errors are thrown
----------System.err:(1/16)----------
STATUS:Passed.
----------rerun:(40/6796)*----------

<snip>

result: Error. Program `c:\ade\mesos\work_dir\jib-master\install\jdk-21+22-1837\windows-x64-debug.jdk\jdk-21\fastdebug\bin\java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 721917ms).


Please note that the test PASSed while the timeout handler was running.
Comments
Fix request [21u] I backport this for parity with 21.0.5-oracle. No risk, only tests change. Clean backport. Test pass. SAP nightly testing passed.
28-05-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk17u-dev/pull/2495 Date: 2024-05-27 07:58:22 +0000
27-05-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk21u-dev/pull/604 Date: 2024-05-27 07:57:58 +0000
27-05-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk11u-dev/pull/2726 Date: 2024-05-27 07:58:42 +0000
27-05-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk22/pull/103 Date: 2024-02-01 23:25:25 +0000
01-02-2024
Changeset: 929af9ed Author: David Holmes <dholmes@openjdk.org> Date: 2024-01-25 05:26:13 +0000 URL: https://git.openjdk.org/jdk/commit/929af9ed037bcc098043d7b7b8d303744a6d4360
25-01-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/17524 Date: 2024-01-22 21:56:31 +0000
22-01-2024
I discussed JDK-8292818 with [~fparain] and while we see slows downs in these extreme cases, regular benchmarking does not show any adverse effect. For fastdebug in particular there are a lot of assertions used to validate the initial changes, which are probably no longer needed now this change has "baked" for some time, but it is also not worth the effort of changing just for a couple of tests. To that end I propose just increasing the timeout values for these tests.
22-01-2024
I rebuilt to the point before the integration of JDK-8292818 and got: TEST: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java ... main: 32.112 seconds with fastdebug and TEST: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java ... main: 30.973 seconds with product. I then added JDK-8292818 and rebuilt and got: TEST: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java ... main: 232.562 seconds with debug and TEST: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java ... main: 113.844 seconds with product. So we can see that JDK-8292818 has caused a 3x slowdown in product accessing extreme numbers of fields, and a 7x slowdown in fastdebug - resulting in the test timeouts.
11-01-2024
Here is the result of running one test in JDK 20: TEST: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java build: 0.005 seconds driver: 11.147 seconds build: 0.0 seconds main: 32.537 seconds TEST RESULT: Passed. Execution successful and the same result in JDK 21: TEST: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java build: 0.005 seconds driver: 13.913 seconds build: 0.0 seconds main: 233.456 seconds TEST RESULT: Passed. Execution successful That is a 7x slowdown and we see similar in current mainline TEST: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java build: 0.005 seconds driver: 13.743 seconds build: 0.001 seconds main: 204.07 seconds TEST RESULT: Passed. Execution successful
08-01-2024
Test vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java failed again
11-12-2023
We have not seen this test fail in a while now, but the last reported failure was after JDK-8317692 was integrated.
15-11-2023
There has been a report elsewhere that JDK-8292818 results in an extreme slowdown in GC.heap-dump due to the way fields are accessed: "Further analysis showed that the functions in InstanceKlass to get the access flags of a field (identified by its index) now requires an iteration of the fields. As FieldStream from reflectionUtils.hpp accesses such data through the InstanceKlass with a given field index, this results in quadratic complexity for each object that gets dumped." Could that be relevant here?
03-10-2023
Here are log file snippets from the jdk-22+13-897-tier4 sightings: vmTestbase/gc/gctests/LargeObjects/large005/TestDescription.java #section:main ----------messages:(8/539)---------- command: main -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields true -aggregationDepth 3 -t 1 reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields true -aggregationDepth 3 -t 1 started: Sat Aug 26 03:18:31 GMT 2023 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. finished: Sat Aug 26 03:29:53 GMT 2023 elapsed time (seconds): 681.954 ----------configuration:(0/0)---------- ----------System.out:(275/10747)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 2147483648 Sleep time: 500 Iterations: 0 Number of threads: 1 Run GC thread: false Run mem diag thread: false Run forever: false Loading classes that have number of fields under limitation (less than 65535) Starting Thread[#20,gc.gctests.LargeObjects.large001.large001$Worker@381e912b,5,MainThreadGroup] 0: Loading class: nsk.share.gc.newclass.private_int_schild 0: Class loaded: nsk.share.gc.newclass.private_int_schild 0: Instance of the class: nsk.share.gc.newclass.private_int_schild@70ddedc4 Added field objC .... 3 Added field objC .... 2 Added field objC .... 1 <snip> Added field objP .... 2 Added field objC .... 1 Added field objP .... 1 0: Testing non-null after GC force for: nsk.share.gc.newclass.volatile_combination_schild 0: Unloading class: nsk.share.gc.newclass.volatile_combination_schild 0: Result of uloading class nsk.share.gc.newclass.volatile_combination_schild: false No unexpected exceptions/errors are thrown ----------System.err:(1/15)---------- STATUS:Passed. ----------rerun:(33/8185)*---------- <snip> result: Error. Program `/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-22+13-897/macosx-x64-debug.jdk/jdk-22/fastdebug/bin/java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 681771ms). vmTestbase/gc/gctests/LargeObjects/large004/TestDescription.java #section:main ----------messages:(8/539)---------- command: main -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields true -aggregationDepth 1 -t 1 reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields true -aggregationDepth 1 -t 1 started: Sat Aug 26 03:08:03 GMT 2023 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. finished: Sat Aug 26 03:18:31 GMT 2023 elapsed time (seconds): 628.439 ----------configuration:(0/0)---------- ----------System.out:(1208/81336)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 2147483648 Sleep time: 500 Iterations: 0 Number of threads: 1 Run GC thread: false Run mem diag thread: false Run forever: false Loading classes that have number of fields under limitation (less than 65535) Starting Thread[#20,gc.gctests.LargeObjects.large001.large001$Worker@381e912b,5,MainThreadGroup] 0: Loading class: nsk.share.gc.newclass.private_int_schild 0: Class loaded: nsk.share.gc.newclass.private_int_schild 0: Instance of the class: nsk.share.gc.newclass.private_int_schild@70ddedc4 Added field objC .... 1 Added field objP .... 1 <snip> Added field objC .... 1 Added field objP .... 1 0: Testing non-null after GC force for: nsk.share.gc.newclass.volatile_combination_schild 0: Unloading class: nsk.share.gc.newclass.volatile_combination_schild 0: Result of uloading class nsk.share.gc.newclass.volatile_combination_schild: false No unexpected exceptions/errors are thrown ----------System.err:(1/15)---------- STATUS:Passed. ----------rerun:(33/8185)*---------- <snip> result: Error. Program `/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-22+13-897/macosx-x64-debug.jdk/jdk-22/fastdebug/bin/java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 628347ms). vmTestbase/gc/gctests/LargeObjects/large003/TestDescription.java #section:main ----------messages:(8/541)---------- command: main -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields false -aggregationDepth 3 -t 1 reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit gc.gctests.LargeObjects.large001.large001 -largeClassesPath classes -isOverLimitFields false -aggregationDepth 3 -t 1 started: Sat Aug 26 02:53:49 GMT 2023 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. finished: Sat Aug 26 03:04:41 GMT 2023 elapsed time (seconds): 651.218 ----------configuration:(0/0)---------- ----------System.out:(275/10747)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 2147483648 Sleep time: 500 Iterations: 0 Number of threads: 1 Run GC thread: false Run mem diag thread: false Run forever: false Loading classes that have number of fields under limitation (less than 65535) Starting Thread[#20,gc.gctests.LargeObjects.large001.large001$Worker@381e912b,5,MainThreadGroup] 0: Loading class: nsk.share.gc.newclass.private_int_schild 0: Class loaded: nsk.share.gc.newclass.private_int_schild 0: Instance of the class: nsk.share.gc.newclass.private_int_schild@70ddedc4 Added field objC .... 3 Added field objC .... 2 Added field objC .... 1 <snip> Added field objP .... 2 Added field objC .... 1 Added field objP .... 1 0: Testing non-null after GC force for: nsk.share.gc.newclass.volatile_combination_schild 0: Unloading class: nsk.share.gc.newclass.volatile_combination_schild 0: Result of uloading class nsk.share.gc.newclass.volatile_combination_schild: false No unexpected exceptions/errors are thrown ----------System.err:(1/15)---------- STATUS:Passed. ----------rerun:(33/8186)*---------- <snip> result: Error. Program `/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-22+13-897/macosx-x64-debug.jdk/jdk-22/fastdebug/bin/java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 650804ms). Default timeout value of 120 seconds/2 minutes with a default timeoutFactor of 4 means a total timeout of 480 seconds/8 minutes. The run executed for 681.954 (large005), 628.439 (large004) and 651.218 (large003) seconds. The tests did manage to pass while the timeout handler was running.
26-08-2023
Moving to runtime to investigate further. This does not look like gc is responsible for the very slow execution/timeouts, but a runtime call that is very slow. Options include raising the timeout (locally run, the test always seems to timeout - I think within CI we already increase the timeout), changing the test to do less work, or speeding up the runtime call somehow. The issue is also independent of GC and operating environment.
16-05-2023
Getting fields of the (large) objects in question takes a long time; I measured 25-30s(!) to retrieve 65k fields of an object. Annotating that method as follows: oop Reflection::new_field(fieldDescriptor* fd, TRAPS) { Ticks values[7]; values[0] = Ticks::now(); Symbol* field_name = fd->name(); oop name_oop = StringTable::intern(field_name, CHECK_NULL); values[1] = Ticks::now(); Handle name = Handle(THREAD, name_oop); Symbol* signature = fd->signature(); InstanceKlass* holder = fd->field_holder(); Handle type = new_type(signature, holder, CHECK_NULL); values[2] = Ticks::now(); Handle rh = java_lang_reflect_Field::create(CHECK_NULL); values[3] = Ticks::now(); java_lang_reflect_Field::set_clazz(rh(), fd->field_holder()->java_mirror()); java_lang_reflect_Field::set_slot(rh(), fd->index()); java_lang_reflect_Field::set_name(rh(), name()); java_lang_reflect_Field::set_type(rh(), type()); if (fd->is_trusted_final()) { java_lang_reflect_Field::set_trusted_final(rh()); } // Note the ACC_ANNOTATION bit, which is a per-class access flag, is never set here. java_lang_reflect_Field::set_modifiers(rh(), fd->access_flags().as_int() & JVM_RECOGNIZED_FIELD_MODIFIERS); java_lang_reflect_Field::set_override(rh(), false); values[4] = Ticks::now(); if (fd->has_generic_signature()) { Symbol* gs = fd->generic_signature(); Handle sig = java_lang_String::create_from_symbol(gs, CHECK_NULL); java_lang_reflect_Field::set_signature(rh(), sig()); } values[5] = Ticks::now(); typeArrayOop an_oop = Annotations::make_java_array(fd->annotations(), CHECK_NULL); java_lang_reflect_Field::set_annotations(rh(), an_oop); values[6] = Ticks::now(); LogTarget(Info, gc) lt; LogStream ls(&lt); for (uint i = 1; i < 7; i++) { ls.print("%zu ", (values[i] - values[i-1]).nanoseconds() ); } ls.cr(); return rh(); } gives following example output: [10.182s][info][gc ] 3286 151 501 250 20 60 [10.183s][info][gc ] 2244 150 571 261 20 60 [10.183s][info][gc ] 2164 140 521 251 20 70 [10.184s][info][gc ] 2364 141 511 260 20 60 [10.184s][info][gc ] 2174 150 501 270 20 81 [10.185s][info][gc ] 2525 140 511 251 20 60 (These are times in ns). String interning seems to take most of the time, followed by java_lang_reflect_Field::create().
16-05-2023