2

I have spring boot java-service (JDK 11) running on a linux-platform in which under heavy load the time used for garbage collection (collector G1) keeps getting longer and longer.

When the service is just restarted the average time used per collection is insignificant e.g. 0.05s but after being put under load for several days the the average collection time can increase to well over 1 second. I've seen it increase eventually so high that almost 50% of every hour is used for garbage collection.

The service also retains the increased garbage collection time so even if the service is put on a break for hours, it doesn't recover and continues witch increased garbage collection time after the break. Full GC does not help, only restarting the service will help.

General description of the service would be that it handles soap-xml requests, has futures, has threads, has threadpools and reads&writes to several databases.

Looking at garbage collection log of the phases, the phase that uses all the time is the one called 'CLDG Roots (ms)' in the one called 'Ext Root Scanning' which is under 'Evacuate Collection Set':

[2022-08-22T08:07:05.639+0300][info ][gc,phases         ] GC(46489)   Evacuate Collection Set: 432.7ms
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       GC Worker Start (ms):     Min: 234380952.1, Avg: 234380952.4, Max: 234380953.2, Diff:  1.1, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Ext Root Scanning (ms):   Min:  1.8, Avg: 112.1, Max: 431.2, Diff: 429.4, Sum: 448.6, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Thread Roots (ms):        Min:  0.0, Avg:  4.2, Max: 12.9, Diff: 12.9, Sum: 16.8, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       StringTable Roots (ms):   Min:  0.0, Avg:  0.2, Max:  0.9, Diff:  0.9, Sum:  0.9, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Universe Roots (ms):      Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       JNI Handles Roots (ms):   Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       ObjectSynchronizer Roots (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Management Roots (ms):    Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       SystemDictionary Roots (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       CLDG Roots (ms):          Min:  0.0, Avg: 108.1, Max: 432.3, Diff: 432.3, Sum: 432.3, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       JVMTI Roots (ms):         Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       CM RefProcessor Roots (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Wait For Strong CLD (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Weak CLD Roots (ms):      Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       SATB Filtering (ms):      Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4

(Check the longer log for more detailed description.)

Here is log of one garbage collection in full which takes 0.43 seconds:

[2022-08-22T08:07:05.204+0300][debug][gc,heap           ] GC(46489) Heap before GC invocations=46489 (full 0): garbage-first heap   total 3145728K, used 2362368K [0x0000000740000000, 0x0000000800000000)
[2022-08-22T08:07:05.204+0300][debug][gc,heap           ] GC(46489)   region size 1024K, 1843 young (1887232K), 49 survivors (50176K)
[2022-08-22T08:07:05.204+0300][debug][gc,heap           ] GC(46489)  Metaspace       used 1282569K, capacity 1288576K, committed 1302288K, reserved 1900544K
[2022-08-22T08:07:05.204+0300][debug][gc,heap           ] GC(46489)   class space    used 448455K, capacity 451431K, committed 452032K, reserved 1048576K
[2022-08-22T08:07:05.204+0300][info ][gc,start          ] GC(46489) Pause Young (Normal) (G1 Evacuation Pause)
[2022-08-22T08:07:05.204+0300][info ][gc,task           ] GC(46489) Using 4 workers of 4 for evacuation
[2022-08-22T08:07:05.204+0300][debug][gc,tlab           ] GC(46489) TLAB totals: thrds: 79  refills: 6293 max: 241 slow allocs: 3022 max 296 waste:  1.0% gc: 8690776B max: 484520B slow: 8537992B max: 606032B fast: 0B max: 0B
[2022-08-22T08:07:05.204+0300][debug][gc,alloc,region   ] GC(46489) Mutator Allocation stats, regions: 1794, wasted size: 4744B ( 0.0%)
[2022-08-22T08:07:05.204+0300][debug][gc,age            ] GC(46489) Desired survivor size 121110528 bytes, new threshold 15 (max threshold 15)
[2022-08-22T08:07:05.204+0300][debug][gc,ergo,cset      ] GC(46489) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 145.64
[2022-08-22T08:07:05.204+0300][debug][gc,task,stats     ] GC(46489) GC Termination Stats
[2022-08-22T08:07:05.204+0300][debug][gc,task,stats     ] GC(46489)      elapsed  --strong roots-- -------termination------- ------waste (KiB)------
[2022-08-22T08:07:05.204+0300][debug][gc,task,stats     ] GC(46489) thr     ms        ms      %        ms      %    attempts  total   alloc    undo
[2022-08-22T08:07:05.204+0300][debug][gc,task,stats     ] GC(46489) --- --------- --------- ------ --------- ------ -------- ------- ------- -------
[2022-08-22T08:07:05.637+0300][debug][gc,task,stats     ] GC(46489)   0    432.44    432.42 100.00      0.00   0.00        1       1       1       0
[2022-08-22T08:07:05.637+0300][debug][gc,task,stats     ] GC(46489)   3    431.38     42.66   9.89    383.03  88.79        1       0       0       0
[2022-08-22T08:07:05.637+0300][debug][gc,task,stats     ] GC(46489)   1    432.56     45.81  10.59    383.84  88.74        1       0       0       0
[2022-08-22T08:07:05.637+0300][debug][gc,task,stats     ] GC(46489)   2    432.40     38.89   8.99    383.82  88.77        1       2       2       0
[2022-08-22T08:07:05.637+0300][debug][gc,ergo           ] GC(46489) Running G1 Clear Card Table Task using 4 workers for 5 units of work for 2100 regions.
[2022-08-22T08:07:05.637+0300][debug][gc,ref            ] GC(46489) Skipped phase1 of Reference Processing due to unavailable references
[2022-08-22T08:07:05.638+0300][debug][gc,ref            ] GC(46489) Skipped phase3 of Reference Processing due to unavailable references
[2022-08-22T08:07:05.638+0300][debug][gc,ergo           ] GC(46489) Running G1 Free Collection Set using 4 workers for collection set length 1843
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Live humongous region 0 object size 738608 start 0x0000000740000000  with remset 1 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 81 object size 1037776 start 0x0000000745100000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Live humongous region 108 object size 1037648 start 0x0000000746c00000  with remset 0 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Live humongous region 109 object size 1037680 start 0x0000000746d00000  with remset 0 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 125 object size 1037744 start 0x0000000747d00000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 131 object size 1037744 start 0x0000000748300000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 135 object size 1037776 start 0x0000000748700000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 136 object size 1037776 start 0x0000000748800000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 137 object size 1037744 start 0x0000000748900000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 140 object size 1037744 start 0x0000000748c00000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 143 object size 1037744 start 0x0000000748f00000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Live humongous region 145 object size 1037648 start 0x0000000749100000  with remset 0 code roots 0 is marked 0 reclaim candidate 0 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 146 object size 1037744 start 0x0000000749200000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 149 object size 1037744 start 0x0000000749500000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 150 object size 1037744 start 0x0000000749600000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,humongous      ] GC(46489) Dead humongous region 157 object size 1037776 start 0x0000000749d00000 with remset 0 code roots 0 is marked 0 reclaim candidate 1 type array 1
[2022-08-22T08:07:05.639+0300][debug][gc,plab           ] GC(46489) Young PLAB allocation: allocated: 49807360B, wasted: 4056B, unused: 1052976B, used: 48750328B, undo waste: 0B, 
[2022-08-22T08:07:05.639+0300][debug][gc,plab           ] GC(46489) Young other allocation: region end waste: 0B, regions filled: 48, direct allocated: 0B, failure used: 0B, failure wasted: 0B
[2022-08-22T08:07:05.639+0300][debug][gc,plab           ] GC(46489) Young sizing: calculated: 9750064B, actual: 9716048B
[2022-08-22T08:07:05.639+0300][debug][gc,plab           ] GC(46489) Old PLAB allocation: allocated: 94944B, wasted: 1216B, unused: 6536B, used: 87192B, undo waste: 0B, 
[2022-08-22T08:07:05.639+0300][debug][gc,plab           ] GC(46489) Old other allocation: region end waste: 0B, regions filled: 1, direct allocated: 2576B, failure used: 0B, failure wasted: 0B
[2022-08-22T08:07:05.639+0300][debug][gc,plab           ] GC(46489) Old sizing: calculated: 17432B, actual: 13072B
[2022-08-22T08:07:05.639+0300][info ][gc,mmu            ] GC(46489) MMU target violated: 201.0ms (200.0ms/201.0ms)
[2022-08-22T08:07:05.639+0300][debug][gc,alloc,stats    ] Old generation allocation in the last mutator period, old gen allocated: 94944B, humongous allocated: 11534336B,old gen growth: 94944B.
[2022-08-22T08:07:05.639+0300][debug][gc,ihop           ] GC(46489) Basic information (value update), threshold: 803636683B (24.95), target occupancy: 3221225472B, current occupancy: 525434368B, recent allocation size: 11629280B, recent allocation duration: 2755.64ms, recent old gen allocation rate: 4220175.16B/s, recent marking phase length: 2284.96ms
[2022-08-22T08:07:05.639+0300][debug][gc,ihop           ] GC(46489) Adaptive IHOP information (value update), threshold: 803636683B (29.35), internal target occupancy: 2738041651B, occupancy: 525434368B, additional buffer size: 1932525568B, predicted old gen allocation rate: 675492.86B/s, predicted marking phase length: 2782.27ms, prediction active: true
[2022-08-22T08:07:05.639+0300][debug][gc,ergo,refine    ] GC(46489) Updated Refinement Zones: green: 149, yellow: 447, red: 745
[2022-08-22T08:07:05.639+0300][info ][gc,phases         ] GC(46489)   Pre Evacuate Collection Set: 0.1ms
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Prepare TLABs: 0.0ms
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Choose Collection Set: 0.0ms
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Humongous Register: 0.1ms
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Humongous Total: 16
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Humongous Candidate: 16
[2022-08-22T08:07:05.639+0300][info ][gc,phases         ] GC(46489)   Evacuate Collection Set: 432.7ms
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       GC Worker Start (ms):     Min: 234380952.1, Avg: 234380952.4, Max: 234380953.2, Diff:  1.1, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Ext Root Scanning (ms):   Min:  1.8, Avg: 112.1, Max: 431.2, Diff: 429.4, Sum: 448.6, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Thread Roots (ms):        Min:  0.0, Avg:  4.2, Max: 12.9, Diff: 12.9, Sum: 16.8, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       StringTable Roots (ms):   Min:  0.0, Avg:  0.2, Max:  0.9, Diff:  0.9, Sum:  0.9, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Universe Roots (ms):      Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       JNI Handles Roots (ms):   Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       ObjectSynchronizer Roots (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Management Roots (ms):    Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       SystemDictionary Roots (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       CLDG Roots (ms):          Min:  0.0, Avg: 108.1, Max: 432.3, Diff: 432.3, Sum: 432.3, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       JVMTI Roots (ms):         Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       CM RefProcessor Roots (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Wait For Strong CLD (ms): Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Weak CLD Roots (ms):      Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       SATB Filtering (ms):      Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Update RS (ms):           Min:  0.0, Avg:  1.7, Max:  5.0, Diff:  5.0, Sum:  6.6, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)       Processed Buffers:        Min: 0, Avg: 21.8, Max: 82, Diff: 82, Sum: 87, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)       Scanned Cards:            Min: 0, Avg: 835.5, Max: 2250, Diff: 2250, Sum: 3342, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)       Skipped Cards:            Min: 0, Avg:  1.8, Max: 4, Diff: 4, Sum: 7, Workers: 4
[2022-08-22T08:07:05.639+0300][trace][gc,phases         ] GC(46489)       Scan HCC (ms):            Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Scan RS (ms):             Min:  0.0, Avg:  0.2, Max:  0.9, Diff:  0.9, Sum:  0.9, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)       Scanned Cards:            Min: 0, Avg: 10.5, Max: 42, Diff: 42, Sum: 42, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)       Claimed Cards:            Min: 0, Avg: 11.8, Max: 47, Diff: 47, Sum: 47, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)       Skipped Cards:            Min: 0, Avg:  0.0, Max: 0, Diff: 0, Sum: 0, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Code Root Scanning (ms):  Min:  0.0, Avg:  0.0, Max:  0.1, Diff:  0.1, Sum:  0.1, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     AOT Root Scanning (ms):   skipped
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Object Copy (ms):         Min:  1.1, Avg: 30.2, Max: 45.1, Diff: 43.9, Sum: 120.8, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     Termination (ms):         Min:  0.0, Avg: 287.7, Max: 383.8, Diff: 383.8, Sum: 1150.7, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)       Termination Attempts:     Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: 4, Workers: 4
[2022-08-22T08:07:05.639+0300][debug][gc,phases         ] GC(46489)     GC Worker Other (ms):     Min:  0.2, Avg:  0.3, Max:  0.6, Diff:  0.4, Sum:  1.2, Workers: 4
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     GC Worker Total (ms):     Min: 431.4, Avg: 432.2, Max: 432.6, Diff:  1.2, Sum: 1728.9, Workers: 4
[2022-08-22T08:07:05.640+0300][trace][gc,phases         ] GC(46489)       GC Worker End (ms):       Min: 234381384.6, Avg: 234381384.7, Max: 234381384.7, Diff:  0.1, Workers: 4
[2022-08-22T08:07:05.640+0300][info ][gc,phases         ] GC(46489)   Post Evacuate Collection Set: 2.2ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Code Roots Fixup: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Clear Card Table: 0.3ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Reference Processing: 0.4ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       Reconsider SoftReferences: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         SoftRef (ms):             skipped
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       Notify Soft/WeakReferences: 0.3ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Balance queues: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         SoftRef (ms):             Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 3
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         WeakRef (ms):             Min:  0.1, Avg:  0.1, Max:  0.1, Diff:  0.0, Sum:  0.2, Workers: 3
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         FinalRef (ms):            Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 3
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Total (ms):               Min:  0.1, Avg:  0.1, Max:  0.1, Diff:  0.0, Sum:  0.3, Workers: 3
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       Notify and keep alive finalizable: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         FinalRef (ms):            skipped
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       Notify PhantomReferences: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         PhantomRef (ms):          Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 1
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       SoftReference:
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Discovered: 0
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Cleared: 0
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       WeakReference:
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Discovered: 2155
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Cleared: 1709
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       FinalReference:
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Discovered: 0
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Cleared: 0
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)       PhantomReference:
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Discovered: 31
[2022-08-22T08:07:05.640+0300][debug][gc,phases,ref     ] GC(46489)         Cleared: 0
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Weak Processing: 0.3ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Merge Per-Thread State: 0.1ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Code Roots Purge: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Redirty Cards: 0.1ms
[2022-08-22T08:07:05.640+0300][trace][gc,phases         ] GC(46489)       Parallel Redirty (ms):    Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 4
[2022-08-22T08:07:05.640+0300][trace][gc,phases         ] GC(46489)         Redirtied Cards:          Min: 0, Avg: 591.5, Max: 1369, Diff: 1369, Sum: 2366, Workers: 4
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     DerivedPointerTable Update: 0.1ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Free Collection Set: 0.9ms
[2022-08-22T08:07:05.640+0300][trace][gc,phases         ] GC(46489)       Free Collection Set Serial: 0.5ms
[2022-08-22T08:07:05.640+0300][trace][gc,phases         ] GC(46489)       Young Free Collection Set (ms): Min:  0.0, Avg:  0.4, Max:  0.6, Diff:  0.5, Sum:  1.1, Workers: 3
[2022-08-22T08:07:05.640+0300][trace][gc,phases         ] GC(46489)       Non-Young Free Collection Set (ms): skipped
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Humongous Reclaim: 0.2ms
[2022-08-22T08:07:05.640+0300][trace][gc,phases         ] GC(46489)       Humongous Reclaimed: 12
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Start New Collection Set: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Resize TLABs: 0.0ms
[2022-08-22T08:07:05.640+0300][debug][gc,phases         ] GC(46489)     Expand Heap After Collection: 0.0ms
[2022-08-22T08:07:05.640+0300][info ][gc,phases         ] GC(46489)   Other: 0.6ms
[2022-08-22T08:07:05.640+0300][info ][gc,heap           ] GC(46489) Eden regions: 1794->0(1795)
[2022-08-22T08:07:05.640+0300][info ][gc,heap           ] GC(46489) Survivor regions: 49->48(231)
[2022-08-22T08:07:05.640+0300][info ][gc,heap           ] GC(46489) Old regions: 450->450
[2022-08-22T08:07:05.640+0300][info ][gc,heap           ] GC(46489) Humongous regions: 16->4
[2022-08-22T08:07:05.640+0300][info ][gc,metaspace      ] GC(46489) Metaspace: 1282569K->1282569K(1900544K)
[2022-08-22T08:07:05.640+0300][debug][gc,heap           ] GC(46489) Heap after GC invocations=46490 (full 0): garbage-first heap   total 3145728K, used 513119K [0x0000000740000000, 0x0000000800000000)
[2022-08-22T08:07:05.640+0300][debug][gc,heap           ] GC(46489)   region size 1024K, 48 young (49152K), 48 survivors (49152K)
[2022-08-22T08:07:05.640+0300][debug][gc,heap           ] GC(46489)  Metaspace       used 1282569K, capacity 1288576K, committed 1302288K, reserved 1900544K
[2022-08-22T08:07:05.640+0300][debug][gc,heap           ] GC(46489)   class space    used 448455K, capacity 451431K, committed 452032K, reserved 1048576K
[2022-08-22T08:07:05.640+0300][info ][gc                ] GC(46489) Pause Young (Normal) (G1 Evacuation Pause) 2308M->501M(3072M) 436.105ms
[2022-08-22T08:07:05.640+0300][info ][gc,cpu            ] GC(46489) User=1.53s Sys=0.01s Real=0.43s

xlog used:

-Xlog:gc*=debug,gc+phases=trace:/tmp/gc.log:time,level,tags:filecount=10,filesize=50m

I've tried various things, e.g. adding memory, playing with settings and trying to find memory leaks. But i've not being able to find the smoking gun. :(

Anybody got any advice/solution anything?

dibledob
  • 31
  • 3
  • The complexity screams that some resource leak is around. I'd start first with a SonarLint/Qube cleanup, so clean code remains. If you succeed in _profiling_ that might help, as critical bottlenecks might be involved. Less threads might help. – Joop Eggen Aug 23 '22 at 06:37
  • maybe comparing heap dump in gc happening period would help to sweep the tons of log to see which threads do the job? – Harry_T Aug 23 '22 at 07:57

1 Answers1

1

UPDATE, REASON, SOLUTION:

I finally got around to make a java flight recorder (.jfr) recording when this particular service was in a slowed state. When analyzing the recording with JDK Mission Control I detected that there were tens of thousands of java.lang.LinkageError in just a 1 minute recording and more were generated on every soap-request. These were not visible on our logs at all, but we could easily dig them out with xlog.

Example from xlog with exceptions=trace:

'java/lang/LinkageError'{0x00000000cbaf5990}: loader org.springframework.boot.loader.LaunchedURLClassLoader @f6c48ac attempted duplicate class definition for OUR.SERVICE.CLASS.jaxb.Sort$JaxbAccessorF_elementName. (OUR.SERVICE.CLASS.jaxb.Sort$JaxbAccessorF_elementName is in unnamed module of loader org.springframework.boot.loader.LaunchedURLClassLoader @f6c48ac, parent loader 'app')

Apparently the reason was a third party jar, which we have to use, which has jaxb-impl and which tries on runtime to regenerate certain parts of the soap-api... which it doesn't succeed in doing because of that "attempted duplicate class definition"... All this generates those errors and consumes compressed class space and metaspace.

We have had a warning about this on our logs, when the service starts, but unfortunately the all negative effects have been visible only on heavy load.

WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.sun.xml.bind.v2.runtime.reflect.opt.Injector$1 (file:<OUR SERVICE DIRECTORY>/jaxb-impl.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int)
WARNING: Please consider reporting this to the maintainers of com.sun.xml.bind.v2.runtime.reflect.opt.Injector$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release

Anyways the solution for the time being seems to be starting the service with the system property

-Dcom.sun.xml.bind.v2.bytecode.ClassTailor.noOptimize

Thats all folks!

dibledob
  • 31
  • 3