Created on behalf of lishun.1@bytedance.com
------
After upgrading our project from JDK 17 to JDK 21, we observed a significant increase in GC times. Upon investigation, we found that the performance degradation is linked to the changes introduced inJDK-8290025. By analyzing the GC logs and performing some calculations, it appears that excessive young GCs are being triggered due to the CodeCache GC threshold.
Here's a simple case to reproduce the issue:
class HelloWorld
{
public static void main(String []args)
{
System.out.println("Hello, world!");
}
};
Run (jdk24) :
java -Xmx4g -Xms4g -Xlog:gc,codecache=info -XX:InitialCodeCacheSize=3m -XX:ReservedCodeCacheSize=3m -XX:+PrintCodeCache HelloWorld.java
The whole log of gc and codecache is attached and we can just pick a segment of it to see the abnormal trigger of CodeCache GC.
CodeCache: size=3072Kb used=2407Kb max_used=2451Kb free=664Kb
bounds [0x00007f1a248d0000, 0x00007f1a24bd0000, 0x00007f1a24bd0000]
total_blobs=1113, nmethods=681, adapters=339, full_count=0
Compilation: enabled, stopped_count=0, restarted_count=0
We see the max usage is 2467kb and total capacity is 3072kb. Yet the total number of "Pause Young (Concurrent Start) (CodeCache GC Threshold)" is more than 10 and it totally took around 17ms to do these 10+ collections.
[0.044s][info][gc ] GC(0) Pause Young (Concurrent Start) (CodeCache GC Threshold) 3M->1M(4096M) 1.415ms
[0.081s][info][gc ] GC(2) Pause Young (Concurrent Start) (CodeCache GC Threshold) 3M->1M(4096M) 1.105ms
[0.127s][info][gc ] GC(4) Pause Young (Concurrent Start) (CodeCache GC Threshold) 3M->1M(4096M) 1.329ms
[0.185s][info][gc ] GC(6) Pause Young (Concurrent Start) (CodeCache GC Threshold) 4M->1M(4096M) 1.408ms
[0.270s][info][gc ] GC(8) Pause Young (Concurrent Start) (CodeCache GC Threshold) 4M->2M(4096M) 1.452ms
[0.312s][info][gc ] GC(10) Pause Young (Concurrent Start) (CodeCache GC Threshold) 5M->2M(4096M) 1.546ms
[0.400s][info][gc ] GC(12) Pause Young (Concurrent Start) (CodeCache GC Threshold) 6M->2M(4096M) 1.773ms
[0.455s][info][gc ] GC(14) Pause Young (Concurrent Start) (CodeCache GC Threshold) 8M->3M(4096M) 2.320ms
[0.504s][info][gc ] GC(16) Pause Young (Concurrent Start) (CodeCache GC Threshold) 7M->4M(4096M) 1.983ms
[0.561s][info][gc ] GC(18) Pause Young (Concurrent Start) (CodeCache GC Threshold) 9M->4M(4096M) 2.366ms
[0.619s][info][gc ] GC(20) Pause Young (Concurrent Start) (CodeCache GC Threshold) 8M->5M(4096M) 2.974ms
This is weird since there's no Pause Young and Pause Remark if we use jdk17.
What's more, the triggering threshold of this kind of collection will gradually shrink to a low value and cause an unreasonable amount of collection, which, is exactly the same phenomenon as we encountered in our online project.
[0.042s][info][codecache] Triggering threshold (12.601%) GC due to allocating 15.995% since last unloading (0.000% used -> 15.995% used)
[0.080s][info][codecache] Triggering threshold (7.914%) GC due to allocating 8.203% since last unloading (39.038% used -> 47.241% used)
[0.126s][info][codecache] Triggering threshold (6.871%) GC due to allocating 6.925% since last unloading (47.266% used -> 54.191% used)
[0.183s][info][codecache] Triggering threshold (6.041%) GC due to allocating 6.136% since last unloading (53.593% used -> 59.729% used)
[0.268s][info][codecache] Triggering threshold (5.366%) GC due to allocating 5.396% since last unloading (58.830% used -> 64.225% used)
[0.310s][info][codecache] Triggering threshold (4.799%) GC due to allocating 4.862% since last unloading (63.143% used -> 68.005% used)
[0.398s][info][codecache] Triggering threshold (4.333%) GC due to allocating 4.431% since last unloading (66.679% used -> 71.110% used)
[0.453s][info][codecache] Triggering threshold (3.893%) GC due to allocating 3.902% since last unloading (70.146% used -> 74.048% used)
[0.502s][info][codecache] Triggering threshold (3.464%) GC due to allocating 3.809% since last unloading (73.100% used -> 76.908% used)
[0.558s][info][codecache] Triggering threshold (3.070%) GC due to allocating 3.556% since last unloading (75.977% used -> 79.533% used)
[0.616s][info][codecache] Triggering threshold (3.032%) GC due to allocating 3.052% since last unloading (76.737% used -> 79.789% used)
------
After upgrading our project from JDK 17 to JDK 21, we observed a significant increase in GC times. Upon investigation, we found that the performance degradation is linked to the changes introduced in
Here's a simple case to reproduce the issue:
class HelloWorld
{
public static void main(String []args)
{
System.out.println("Hello, world!");
}
};
Run (jdk24) :
java -Xmx4g -Xms4g -Xlog:gc,codecache=info -XX:InitialCodeCacheSize=3m -XX:ReservedCodeCacheSize=3m -XX:+PrintCodeCache HelloWorld.java
The whole log of gc and codecache is attached and we can just pick a segment of it to see the abnormal trigger of CodeCache GC.
CodeCache: size=3072Kb used=2407Kb max_used=2451Kb free=664Kb
bounds [0x00007f1a248d0000, 0x00007f1a24bd0000, 0x00007f1a24bd0000]
total_blobs=1113, nmethods=681, adapters=339, full_count=0
Compilation: enabled, stopped_count=0, restarted_count=0
We see the max usage is 2467kb and total capacity is 3072kb. Yet the total number of "Pause Young (Concurrent Start) (CodeCache GC Threshold)" is more than 10 and it totally took around 17ms to do these 10+ collections.
[0.044s][info][gc ] GC(0) Pause Young (Concurrent Start) (CodeCache GC Threshold) 3M->1M(4096M) 1.415ms
[0.081s][info][gc ] GC(2) Pause Young (Concurrent Start) (CodeCache GC Threshold) 3M->1M(4096M) 1.105ms
[0.127s][info][gc ] GC(4) Pause Young (Concurrent Start) (CodeCache GC Threshold) 3M->1M(4096M) 1.329ms
[0.185s][info][gc ] GC(6) Pause Young (Concurrent Start) (CodeCache GC Threshold) 4M->1M(4096M) 1.408ms
[0.270s][info][gc ] GC(8) Pause Young (Concurrent Start) (CodeCache GC Threshold) 4M->2M(4096M) 1.452ms
[0.312s][info][gc ] GC(10) Pause Young (Concurrent Start) (CodeCache GC Threshold) 5M->2M(4096M) 1.546ms
[0.400s][info][gc ] GC(12) Pause Young (Concurrent Start) (CodeCache GC Threshold) 6M->2M(4096M) 1.773ms
[0.455s][info][gc ] GC(14) Pause Young (Concurrent Start) (CodeCache GC Threshold) 8M->3M(4096M) 2.320ms
[0.504s][info][gc ] GC(16) Pause Young (Concurrent Start) (CodeCache GC Threshold) 7M->4M(4096M) 1.983ms
[0.561s][info][gc ] GC(18) Pause Young (Concurrent Start) (CodeCache GC Threshold) 9M->4M(4096M) 2.366ms
[0.619s][info][gc ] GC(20) Pause Young (Concurrent Start) (CodeCache GC Threshold) 8M->5M(4096M) 2.974ms
This is weird since there's no Pause Young and Pause Remark if we use jdk17.
What's more, the triggering threshold of this kind of collection will gradually shrink to a low value and cause an unreasonable amount of collection, which, is exactly the same phenomenon as we encountered in our online project.
[0.042s][info][codecache] Triggering threshold (12.601%) GC due to allocating 15.995% since last unloading (0.000% used -> 15.995% used)
[0.080s][info][codecache] Triggering threshold (7.914%) GC due to allocating 8.203% since last unloading (39.038% used -> 47.241% used)
[0.126s][info][codecache] Triggering threshold (6.871%) GC due to allocating 6.925% since last unloading (47.266% used -> 54.191% used)
[0.183s][info][codecache] Triggering threshold (6.041%) GC due to allocating 6.136% since last unloading (53.593% used -> 59.729% used)
[0.268s][info][codecache] Triggering threshold (5.366%) GC due to allocating 5.396% since last unloading (58.830% used -> 64.225% used)
[0.310s][info][codecache] Triggering threshold (4.799%) GC due to allocating 4.862% since last unloading (63.143% used -> 68.005% used)
[0.398s][info][codecache] Triggering threshold (4.333%) GC due to allocating 4.431% since last unloading (66.679% used -> 71.110% used)
[0.453s][info][codecache] Triggering threshold (3.893%) GC due to allocating 3.902% since last unloading (70.146% used -> 74.048% used)
[0.502s][info][codecache] Triggering threshold (3.464%) GC due to allocating 3.809% since last unloading (73.100% used -> 76.908% used)
[0.558s][info][codecache] Triggering threshold (3.070%) GC due to allocating 3.556% since last unloading (75.977% used -> 79.533% used)
[0.616s][info][codecache] Triggering threshold (3.032%) GC due to allocating 3.052% since last unloading (76.737% used -> 79.789% used)
- links to
-
Review(master) openjdk/jdk/21084