Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8340434

Excessive Young GCs Triggered by CodeCache GC Threshold

XMLWordPrintable

    • Icon: Enhancement Enhancement
    • Resolution: Unresolved
    • Icon: P4 P4
    • tbd
    • 20, 21, 22, 23, 24
    • hotspot
    • None
    • gc

      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 in JDK-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)

            Unassigned Unassigned
            haotang Hao Tang
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated: