JDK-8267348 : Rewrite gc/epsilon/TestClasses.java to use Metaspace with less classes
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 11,16,17
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: linux
  • CPU: x86
  • Submitted: 2021-05-18
  • Updated: 2022-10-13
  • Resolved: 2021-05-20
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 11 JDK 17
11.0.13Fixed 17 b24Fixed
Related Reports
Relates :  
JDK-8267396 - Avoid recording "pc" in unhandled oops detector for better performance
Relates :  
JDK-8266074 - Vtable-based CHA implementation
Sub Tasks
JDK-8267409 :  
ProblemList gc/epsilon/TestClasses.java on linux-x64 - Resolved
Description
Sometimes times out during the test, sometimes the timeout hits in the post test clean up. Seems to only be occurring for the CheckUnhandledOops config.

----------System.out:(37/3712)----------
[0.007s][info][gc] Using Epsilon
[0.007s][warning][gc,init] Consider enabling -XX:+AlwaysPreTouch to avoid memory commit hiccups
[0.007s][info   ][gc,metaspace] CDS archive(s) mapped at: [0x0000000800000000-0x0000000800c2d000-0x0000000800c2d000), size 12767232, SharedBaseAddress: 0x0000000800000000, ArchiveRelocationMode: 0.
[0.007s][info   ][gc,metaspace] Compressed class space mapped at: 0x0000000801000000-0x0000000804400000, reserved size: 54525952
[0.007s][info   ][gc,metaspace] Narrow klass base: 0x0000000800000000, Narrow klass shift: 0, Narrow klass range: 0x100000000
[1.009s][info   ][gc          ] GC request for "Metadata GC Threshold" is handled
[1.009s][info   ][gc,metaspace] Metaspace: 61440K reserved, 1024K (1.67%) committed, 902K (1.47%) used
[2.393s][info   ][gc          ] GC request for "Metadata GC Threshold" is handled
[2.393s][info   ][gc,metaspace] Metaspace: 61440K reserved, 1728K (2.81%) committed, 1550K (2.52%) used
[4.532s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 6598K (5.03%) used
[4.532s][info   ][gc,metaspace] Metaspace: 61440K reserved, 2368K (3.85%) committed, 2172K (3.54%) used
[7.159s][info   ][gc          ] GC request for "Metadata GC Threshold" is handled
[7.159s][info   ][gc,metaspace] Metaspace: 61440K reserved, 2880K (4.69%) committed, 2710K (4.41%) used
[22.144s][info   ][gc          ] GC request for "Metadata GC Threshold" is handled
[22.144s][info   ][gc,metaspace] Metaspace: 61440K reserved, 4800K (7.81%) committed, 4673K (7.61%) used
[22.606s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 13210K (10.08%) used
[22.606s][info   ][gc,metaspace] Metaspace: 61440K reserved, 4928K (8.02%) committed, 4718K (7.68%) used
[54.895s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 19822K (15.12%) used
[54.895s][info   ][gc,metaspace] Metaspace: 61440K reserved, 7424K (12.08%) committed, 7201K (11.72%) used
[63.913s][info   ][gc          ] GC request for "Metadata GC Threshold" is handled
[63.913s][info   ][gc,metaspace] Metaspace: 61440K reserved, 8000K (13.02%) committed, 7825K (12.74%) used
[99.121s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 26377K (20.12%) used
[99.121s][info   ][gc,metaspace] Metaspace: 61440K reserved, 9856K (16.04%) committed, 9648K (15.70%) used
[169.748s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 32938K (25.13%) used
[169.748s][info   ][gc,metaspace] Metaspace: 61440K reserved, 12224K (19.90%) committed, 12038K (19.59%) used
[213.437s][info   ][gc          ] GC request for "Metadata GC Threshold" is handled
[213.437s][info   ][gc,metaspace] Metaspace: 61440K reserved, 13376K (21.77%) committed, 13209K (21.50%) used
[257.122s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 39580K (30.20%) used
[257.122s][info   ][gc,metaspace] Metaspace: 61440K reserved, 14592K (23.75%) committed, 14446K (23.51%) used
[329.120s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 46158K (35.22%) used
[329.120s][info   ][gc,metaspace] Metaspace: 69632K reserved, 17024K (24.45%) committed, 16836K (24.18%) used
[462.044s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 52725K (40.23%) used
[462.044s][info   ][gc,metaspace] Metaspace: 69632K reserved, 19392K (27.85%) committed, 19201K (27.58%) used
Timeout refired 600 times
[607.818s][info   ][gc          ] Heap: 128M reserved, 128M (100.00%) committed, 59296K (45.24%) used
[607.818s][info   ][gc,metaspace] Metaspace: 69632K reserved, 21632K (31.07%) committed, 21518K (30.90%) used
[618.906s][info   ][gc          ] GC request for "Heap Inspection Initiated GC" is ignored
Comments
Fix Request (11u) This stabilizes the test. The patch does not apply cleanly due to different Java package. 11u RFR acked by clanger.
27-07-2021
Changeset: 7b98400c Author: Aleksey Shipilev <shade@openjdk.org> Date: 2021-05-20 16:45:38 +0000 URL: https://git.openjdk.java.net/jdk/commit/7b98400c81900a8c779394d549b5fb61f1dd8638
20-05-2021
It is strange that JDK-8266074 appears to be the cause as we did not see this start to fail until JDK-8254598 was integrated. Maybe a few effects have combined.
19-05-2021
The test fix is in review. I still believe we want to do JDK-8267396 generically, and maybe followup why JDK-8266074 made is slower.
19-05-2021
Running under perf with: $ CONF=linux-x86_64-server-fastdebug make run-test TEST=gc/epsilon/TestClasses.java TEST_VM_OPTS="-XX:+CheckUnhandledOops" ...shows this is the hotpath: - 49.68% 0.00% MainThread libjava.so [.] Java_java_lang_ClassLoader_defineClass1 - 49.68% Java_java_lang_ClassLoader_defineClass1 - 49.33% JVM_DefineClassWithSource - 49.33% jvm_define_class_common - 49.24% SystemDictionary::resolve_class_from_stream - 48.40% SystemDictionary::define_instance_class - 48.19% CodeCache::flush_dependents_on - 48.19% CodeCache::mark_for_deoptimization - 48.11% nmethod::check_all_dependencies - 47.73% Dependencies::DepStream::check_klass_dependency - 47.28% Dependencies::DepStream::check_new_klass_dependency - 45.55% Klass::next_sibling - 44.77% ClassLoaderData::is_alive - 42.31% AccessInternal::PostRuntimeDispatch<EpsilonBarrierSet::AccessBarrier<594020ul, EpsilonBarrierSet>, (AccessInternal::BarrierType)2, 594020ul>::oop_ - 27.59% oop::register_oop - 23.40% os::current_frame - 18.13% CodeCache::find_blob 14.34% CodeCache::get_code_heap_containing 3.07% GrowableArrayIterator<CodeHeap*>::GrowableArrayIterator 2.41% frame::adjust_unextended_sp 1.77% os::is_first_C_frame 4.34% UnhandledOops::register_unhandled_oop As such, I find it unlikely it is due to recent String dedup changes. I'll bisect more thoroughly.
19-05-2021
I'll take a look, thanks.
19-05-2021
It appears this may have started timing out when the change for JDK-8254598 was introduced.
19-05-2021
I think we can make -XX:+CheckUnhandledOops faster, see JDK-8267396.
19-05-2021
Bisection shows the regression started with JDK-8266074, which makes more sense given the profile. Running with -XX:-UseVtableBasedCHA makes the regression go away. [~vlivanov], you might be interested in this. Meanwhile, I can see if I can rewrite the test to be faster, for example by splitting the classloaders and such.
19-05-2021
Assigning to [~shade]
18-05-2021
The test is taking 10x longer to run with CheckUnhandledOops enabled: Normal run: main: 23.326 seconds CheckUnhandledOops: main: 265.767 seconds
18-05-2021