JDK-8271008 : appcds/*/MethodHandlesAsCollectorTest.java tests time out because of excessive GC (CodeCache GC Threshold) in loom
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11,17,19,repo-loom
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2021-07-21
  • Updated: 2022-04-04
  • Resolved: 2022-02-22
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 17 JDK 18 JDK 19
17.0.4-oracleFixed 18.0.2Fixed 19 b11Fixed
Related Reports
Duplicate :  
JDK-8256327 - Revisit aggressive code cache sweeping behaviour
Relates :  
JDK-8015774 - Add support for multiple code heaps
Description
Tests 
runtime/cds/appcds/dynamicArchive/methodHandles/MethodHandlesAsCollectorTest.java
runtime/cds/appcds/methodHandles/MethodHandlesAsCollectorTest.java
Comments
Fix Request (17u): Should get backported for parity with 17.0.4-oracle. Applies cleanly except Copyright year update. (That was changed by the enhancement JDK-8268368 in 18.) Nightly tests have passed.
31-03-2022
A pull request was submitted for review. URL: https://git.openjdk.java.net/jdk18u/pull/81 Date: 2022-03-30 05:46:43 +0000
30-03-2022
Fix Request (JDK 18u) Fixes a performance issue with the code cache sweeper. The fix is low risk and applies cleanly. Already tested and about to be backported to Oracle JDK 17u. Tier 1-3 testing is running for JDK 18u.
30-03-2022
A pull request was submitted for review. URL: https://git.openjdk.java.net/jdk17u-dev/pull/319 Date: 2022-03-30 12:35:07 +0000
30-03-2022
Changeset: 022d8070 Author: Coleen Phillimore <coleenp@openjdk.org> Date: 2022-02-22 13:42:56 +0000 URL: https://git.openjdk.java.net/jdk/commit/022d80707c346f4b82ac1eb53e77c634769631e9
22-02-2022
A pull request was submitted for review. URL: https://git.openjdk.java.net/jdk/pull/7514 Date: 2022-02-17 13:34:39 +0000
18-02-2022
The trigger for the sweeper calculates the reverse_free_ratio for the NonNMethod code heap repeatedly for this test, which is never cleaned. The fall back for when heaps are filled are the other code heaps MethodProfiled, then MethodNonProfiled. The aggressive sweeper trigger should really check the whole code heap is below 10% and not only check the NonNMethod code heap in this case. Changing the code to check the overall code cache in CodeCache::reverse_free_ratio() fixes the loom slower performance (loom does a full GC for each sweeper activation).
18-02-2022
What is shrinking is the Java heap, not the code cache. We can't unload nmethods that are on-stack. With virtual threads, said stacks can be in the heap. So we use a Java heap GC to find out what nmethods are reachable through loom continuations. This symptom seems to indicate that we are about to run out of code cache, and excessively trigger GCs, hoping to find more nmethods that we can sweep.
21-07-2021
it is interesting that codecache is smaller and smaller ..... [338.068s][info ][gc ] GC(423) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 191.468ms [338.278s][info ][gc ] GC(424) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 204.919ms [338.476s][info ][gc ] GC(425) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 192.277ms [338.672s][info ][gc ] GC(426) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 191.003ms [338.871s][info ][gc ] GC(427) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 192.947ms [339.070s][info ][gc ] GC(428) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 193.339ms [339.269s][info ][gc ] GC(429) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 192.665ms [339.468s][info ][gc ] GC(430) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 193.621ms [339.668s][info ][gc ] GC(431) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 194.164ms [339.869s][info ][gc ] GC(432) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 195.432ms [340.069s][info ][gc ] GC(433) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 194.919ms [340.270s][info ][gc ] GC(434) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 195.752ms [340.473s][info ][gc ] GC(435) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 196.762ms [340.676s][info ][gc ] GC(436) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 197.005ms [340.879s][info ][gc ] GC(437) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 196.781ms [341.082s][info ][gc ] GC(438) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 197.541ms [341.291s][info ][gc ] GC(439) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 198.915ms [341.498s][info ][gc ] GC(440) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 199.824ms [341.702s][info ][gc ] GC(441) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 198.376ms [341.907s][info ][gc ] GC(442) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 199.254ms [342.112s][info ][gc ] GC(443) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 199.130ms [342.319s][info ][gc ] GC(444) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 201.495ms [342.687s][info ][gc ] GC(445) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 363.190ms [342.880s][info ][gc ] GC(446) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 187.108ms [343.073s][info ][gc ] GC(447) Pause Full (CodeCache GC Threshold) 11M->10M(317M) 187.247ms [343.279s][info ][gc ] GC(448) Pause Full (CodeCache GC Threshold) 12M->9M(317M) 200.114ms [343.472s][info ][gc ] GC(449) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 186.963ms [343.665s][info ][gc ] GC(450) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 187.084ms [343.861s][info ][gc ] GC(451) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 188.256ms [344.068s][info ][gc ] GC(452) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 201.168ms [344.264s][info ][gc ] GC(453) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 188.932ms [344.458s][info ][gc ] GC(454) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 188.312ms [344.652s][info ][gc ] GC(455) Pause Full (CodeCache GC Threshold) 11M->9M(317M) 188.131ms [344.906s][info ][gc ] GC(456) Pause Full (CodeCache GC Threshold) 14M->10M(317M) 232.155ms [345.138s][info ][gc ] GC(457) Pause Full (CodeCache GC Threshold) 16M->11M(317M) 199.609ms [345.389s][info ][gc ] GC(458) Pause Full (CodeCache GC Threshold) 13M->11M(317M) 197.282ms [345.415s][info ][cds ] Regenerate MethodHandle Holder classes...done [345.718s][info ][gc ] GC(459) Pause Full (CodeCache GC Threshold) 13M->11M(317M) 298.332ms
21-07-2021
Test works ten times longer. The gc log says: [0.005s][info][gc] Using Serial [0.118s][info][cds] trying to map /data1/lmesnik/ws/loom/open/build/linux-x86_64-server-fastdebug/images/jdk/lib/server/classes.jsa [0.118s][info][cds] Opened archive /data1/lmesnik/ws/loom/open/build/linux-x86_64-server-fastdebug/images/jdk/lib/server/classes.jsa. [0.118s][info][cds] Archive was created with UseCompressedOops = 1, UseCompressedClassPointers = 1 [0.118s][info][cds] Core region alignment: 4096 [0.118s][info][cds] Reserved archive_space_rs [0x0000000800000000 - 0x0000000801000000] (16777216) bytes [0.118s][info][cds] Reserved class_space_rs [0x0000000801000000 - 0x0000000841000000] (1073741824) bytes [0.118s][info][cds] Mapped static region #0 at base 0x0000000800000000 top 0x00000008004d2000 (ReadWrite) [0.118s][info][cds] Mapped static region #1 at base 0x00000008004d2000 top 0x0000000800c99000 (ReadOnly) [0.118s][info][cds] CDS heap data is being ignored. UseG1GC, UseCompressedOops and UseCompressedClassPointers are required. [0.118s][info][cds] optimized module handling: enabled [0.118s][info][cds] full module graph: disabled class test.java.lang.invoke.MethodHandlesAsCollectorTest annotation: @org.junit.Test(timeout=0L, expected=org.junit.Test$None.class) invoking method: testAsCollector [2.963s][info ][gc ] GC(0) Pause Full (CodeCache GC Threshold) 77M->6M(317M) 210.994ms [6.097s][info ][gc ] GC(1) Pause Young (Allocation Failure) 93M->12M(317M) 102.272ms [8.896s][info ][gc ] GC(2) Pause Full (Metadata GC Threshold) 60M->13M(317M) 1250.338ms [12.303s][info ][gc ] GC(3) Pause Young (Allocation Failure) 101M->21M(317M) 138.592ms [15.611s][info ][gc ] GC(4) Pause Young (Allocation Failure) 109M->29M(317M) 269.567ms [17.673s][info ][gc ] GC(5) Pause Full (Metadata GC Threshold) 43M->28M(317M) 1297.886ms [21.954s][info ][gc ] GC(6) Pause Young (Allocation Failure) 116M->37M(317M) 140.353ms [25.198s][info ][gc ] GC(7) Pause Young (Allocation Failure) 124M->45M(317M) 263.376ms [30.474s][info ][gc ] GC(8) Pause Full (CodeCache GC Threshold) 66M->37M(317M) 4397.933ms [31.292s][info ][gc ] GC(9) Pause Full (CodeCache GC Threshold) 39M->37M(317M) 806.148ms [32.103s][info ][gc ] GC(10) Pause Full (CodeCache GC Threshold) 39M->37M(317M) 802.904ms [32.923s][info ][gc ] GC(11) Pause Full (CodeCache GC Threshold) 39M->37M(317M) 806.492ms [33.790s][info ][gc ] GC(12) Pause Full (CodeCache GC Threshold) 39M->37M(317M) 856.007ms [34.568s][info ][gc ] GC(13) Pause Full (CodeCache GC Threshold) 39M->37M(317M) 772.412ms [35.383s][info ][gc ] GC(14) Pause Full (CodeCache GC Threshold) 39M->37M(317M) 804.582ms [36.178s][info ][gc ] GC(15) Pause Full (CodeCache GC Threshold) 39M->37M(317M) 788.689ms ....
21-07-2021