java 11 G1垃圾收集器回收所用的时间越来越长
java 11 G1垃圾收集器回收所用的时间越来越长
提问于 2022-08-23 05:36:51
我在linux平台上运行了spring java-service (JDK 11)，在这个平台中，垃圾收集( G1)所用的时间越来越长。
当服务刚刚重新启动时，每个集合使用的平均时间是微不足道的，例如0.05s，但是在加载了几天之后，平均收集时间可以增加到远远超过1秒。我看到它最终增长得如此之高，以至于几乎每小时有50%的时间被用于垃圾收集。
该服务还保留了增加的垃圾收集时间，因此即使该服务中断数小时，它也不会恢复，并且在中断后继续延长垃圾收集时间。完全GC没有帮助，只有重新启动服务才有帮助。
该服务的一般描述是:它处理soap请求，有未来，有线程，有线程池，并对多个数据库进行读写。
查看各个阶段的垃圾收集日志，一直使用的阶段是“CLDG(Ms)”，在“Ext根扫描”(Ext根扫描)中，该阶段位于“疏散收集集”：之下。
[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(查看较长的日志以获得更详细的说明。)
这里是一个完整的垃圾收集日志，需要0.43秒：
[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：
-Xlog:gc*=debug，gc+阶段=跟踪:/tmp/gc.log:time，level，tags:filecount=10，filesize=50m
我尝试过各种方法，例如添加内存、处理设置和试图查找内存泄漏。但我找不到那把冒烟的枪。:(
有人有什么建议/解决办法吗？
回答 1
Stack Overflow用户
发布于 2022-09-02 06:29:12
更新，原因，解决方案：
当这个特定的服务处于慢速状态时，我终于准备了一个java飞行记录器(.jfr)。当使用JDK任务控制分析记录时，我发现在1分钟的记录中就有数万个java.lang.LinkageError，并且在每个soap请求上生成了更多。这些在我们的日志中根本看不见，但是我们可以很容易地用xlog挖掘出它们。
来自xlog的示例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')显然原因是第三方jar，我们必须使用它，它具有jaxb-impl，并且尝试运行时重新生成soap的某些部分.但由于“尝试重复的类定义”，它无法成功地完成.所有这些都会生成这些错误，并消耗压缩的类空间和元空间。
当服务启动时，我们已经在日志中对此发出了警告，但不幸的是，所有的负面影响仅在重负载时才可见。
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无论如何，目前的解决方案似乎是使用系统属性启动服务。
-Dcom.sun.xml.bind.v2.bytecode.ClassTailor.noOptimize
都是这些人！
页面原文内容由Stack Overflow提供。腾讯云小微IT领域专用引擎提供翻译支持
原文链接：
https://stackoverflow.com/questions/73453615
复制相关文章
相似问题
腾讯云开发者
Copyright © 2013 - 2026 Tencent Cloud. All Rights Reserved. 腾讯云 版权所有
深圳市腾讯计算机系统有限公司 ICP备案/许可证号：粤B2-20090059 
粤公网安备44030502008569号
腾讯云计算（北京）有限责任公司 京ICP证150476号 | 京ICP备11018762号