性能问答>JNI Weak Reference运行越久GC回收时间越来越长,如何排查导致的原因?>
1回复
5月前

JNI Weak Reference运行越久GC回收时间越来越长,如何排查导致的原因?



1.问题描述

gc打印明细日志:

:27.785+0800: 586146.098: Total time for which application threads were stopped: 0.0026953 seconds, Stopping threads took: 0.0001250 seconds
2021-12-17T11:04:29.265+0800: 586147.577: Total time for which application threads were stopped: 0.0027200 seconds, Stopping threads took: 0.0001658 seconds
2021-12-17T11:04:32.377+0800: 586150.690: Total time for which application threads were stopped: 0.0027273 seconds, Stopping threads took: 0.0001261 seconds
2021-12-17T11:04:34.267+0800: 586152.580: Total time for which application threads were stopped: 0.0028659 seconds, Stopping threads took: 0.0001474 seconds
2021-12-17T11:04:39.270+0800: 586157.583: Total time for which application threads were stopped: 0.0027517 seconds, Stopping threads took: 0.0001378 seconds
2021-12-17T11:04:43.980+0800: 586162.292: Total time for which application threads were stopped: 0.0027815 seconds, Stopping threads took: 0.0001407 seconds
2021-12-17T11:04:44.273+0800: 586162.585: Total time for which application threads were stopped: 0.0027941 seconds, Stopping threads took: 0.0001339 seconds
2021-12-17T11:04:46.517+0800: 586164.829: Total time for which application threads were stopped: 0.0027711 seconds, Stopping threads took: 0.0001433 seconds
2021-12-17T11:04:49.276+0800: 586167.588: Total time for which application threads were stopped: 0.0026813 seconds, Stopping threads took: 0.0001352 seconds
2021-12-17T11:04:52.282+0800: 586170.594: Total time for which application threads were stopped: 0.0026708 seconds, Stopping threads took: 0.0001274 seconds
2021-12-17T11:04:54.279+0800: 586172.591: Total time for which application threads were stopped: 0.0026073 seconds, Stopping threads took: 0.0001270 seconds
2021-12-17T11:04:57.289+0800: 586175.601: Total time for which application threads were stopped: 0.0027016 seconds, Stopping threads took: 0.0001568 seconds
2021-12-17T11:04:59.282+0800: 586177.594: Total time for which application threads were stopped: 0.0027302 seconds, Stopping threads took: 0.0001348 seconds
2021-12-17T11:05:01.885+0800: 586180.197: Total time for which application threads were stopped: 0.0027716 seconds, Stopping threads took: 0.0001430 seconds
2021-12-17T11:05:02.699+0800: 586181.011: Total time for which application threads were stopped: 0.0025587 seconds, Stopping threads took: 0.0000804 seconds
2021-12-17T11:05:04.285+0800: 586182.597: Total time for which application threads were stopped: 0.0028400 seconds, Stopping threads took: 0.0001370 seconds
2021-12-17T11:05:06.872+0800: 586185.185: Total time for which application threads were stopped: 0.0026991 seconds, Stopping threads took: 0.0001382 seconds
2021-12-17T11:05:07.519+0800: 586185.831: Total time for which application threads were stopped: 0.0048583 seconds, Stopping threads took: 0.0001522 seconds
2021-12-17T11:05:07.521+0800: 586185.834: Total time for which application threads were stopped: 0.0023496 seconds, Stopping threads took: 0.0000791 seconds
2021-12-17T11:05:07.524+0800: 586185.836: Total time for which application threads were stopped: 0.0022160 seconds, Stopping threads took: 0.0000499 seconds
2021-12-17T11:05:07.525+0800: 586185.838: Total time for which application threads were stopped: 0.0016928 seconds, Stopping threads took: 0.0000549 seconds
2021-12-17T11:05:07.527+0800: 586185.839: Total time for which application threads were stopped: 0.0014079 seconds, Stopping threads took: 0.0000956 seconds
2021-12-17T11:05:09.170+0800: 586187.483: Total time for which application threads were stopped: 0.0029185 seconds, Stopping threads took: 0.0001809 seconds
2021-12-17T11:05:09.288+0800: 586187.600: Total time for which application threads were stopped: 0.0028974 seconds, Stopping threads took: 0.0001574 seconds
2021-12-17T11:05:09.951+0800: 586188.263: Total time for which application threads were stopped: 0.0028724 seconds, Stopping threads took: 0.0001564 seconds
{Heap before GC invocations=7686 (full 5):
 PSYoungGen      total 4187136K, used 4184244K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 4179968K, 100% used [0x00000006c0000000,0x00000007bf200000,0x00000007bf200000)
  from space 7168K, 59% used [0x00000007bf900000,0x00000007bfd2d170,0x00000007c0000000)
  to   space 7168K, 0% used [0x00000007bf200000,0x00000007bf200000,0x00000007bf900000)
 ParOldGen       total 8388608K, used 1474393K [0x00000004c0000000, 0x00000006c0000000, 0x00000006c0000000)
  object space 8388608K, 17% used [0x00000004c0000000,0x0000000519fd6568,0x00000006c0000000)
 Metaspace       used 158300K, capacity 167588K, committed 167896K, reserved 1198080K
  class space    used 18478K, capacity 20165K, committed 20224K, reserved 1048576K
2021-12-17T11:05:12.130+0800: 586190.442: [GC (Allocation Failure) 2021-12-17T11:05:12.138+0800: 586190.450: [SoftReference, 0 refs, 0.0000296 secs]2021-12-17T11:05:12.138+0800: 586190.450: [WeakReference, 255 refs, 0.0000300 secs]2021-12-17T11:05:12.138+0800: 586190.450: [FinalReference, 462 refs, 0.0001339 secs]2021-12-17T11:05:12.138+0800: 586190.450: [PhantomReference, 24 refs, 2 refs, 0.0001254 secs]2021-12-17T11:05:12.138+0800: 586190.450: [JNI Weak Reference, 0.1113340 secs][PSYoungGen: 4184244K->5974K(4187136K)] 5658637K->1480472K(12575744K), 0.1210229 secs] [Times: user=0.11 sys=0.04, real=0.12 secs] 

Heap after GC invocations=7686 (full 5):
 PSYoungGen      total 4187136K, used 5974K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 4179968K, 0% used [0x00000006c0000000,0x00000006c0000000,0x00000007bf200000)
  from space 7168K, 83% used [0x00000007bf200000,0x00000007bf7d5b78,0x00000007bf900000)
  to   space 7168K, 0% used [0x00000007bf900000,0x00000007bf900000,0x00000007c0000000)
 ParOldGen       total 8388608K, used 1474497K [0x00000004c0000000, 0x00000006c0000000, 0x00000006c0000000)
  object space 8388608K, 17% used [0x00000004c0000000,0x0000000519ff0588,0x00000006c0000000)
 Metaspace       used 158300K, capacity 167588K, committed 167896K, reserved 1198080K
  class space    used 18478K, capacity 20165K, committed 20224K, reserved 1048576K
}
2021-12-17T11:05:12.252+0800: 586190.564: Total time for which application threads were stopped: 0.1241711 seconds, Stopping threads took: 0.0001497 seconds
2021-12-17T11:05:12.254+0800: 586190.566: Total time for which application threads were stopped: 0.0025334 seconds, Stopping threads took: 0.0001241 seconds
2021-12-17T11:05:14.290+0800: 586192.603: Total time for which application threads were stopped: 0.0027954 seconds, Stopping threads took: 0.0001364 seconds
2021-12-17T11:05:16.020+0800: 586194.332: Total time for which application threads were stopped: 0.0026716 seconds, Stopping threads took: 0.0001258 seconds
2021-12-17T11:05:19.293+0800: 586197.605: Total time for which application threads were stopped: 0.0027136 seconds, Stopping threads took: 0.0001309 seconds
2021-12-17T11:05:21.785+0800: 586200.098: Total time for which application threads were stopped: 0.0027856 seconds, Stopping threads took: 0.0001288 seconds
2021-12-17T11:05:24.296+0800: 586202.608: Total time for which application threads were stopped: 0.0027815 seconds, Stopping threads took: 0.0001261 seconds
2021-12-17T11:05:25.599+0800: 586203.911: Total time for which application threads were stopped: 0.0026281 seconds, Stopping threads took: 0.0000747 seconds
2021-12-17T11:05:26.792+0800: 586205.104: Total time for which application threads were stopped: 0.0028084 seconds, Stopping threads took: 0.0001393 seconds
2021-12-17T11:05:29.299+0800: 586207.611: Total time for which application threads were stopped: 0.0026946 seconds, Stopping threads took: 0.0001346 seconds
2021-12-17T11:05:31.400+0800: 586209.712: Total time for which application threads were stopped: 0.0026677 seconds, Stopping threads took: 0.0001289 seconds
2021-12-17T11:05:34.302+0800: 586212.614: Total time for which application threads were stopped: 0.0027142 seconds, Stopping threads took: 0.0001358 seconds
2021-12-17T11:05:36.544+0800: 586214.856: Total time for which application threads were stopped: 0.0027435 seconds, Stopping threads took: 0.0001396 seconds
2021-12-17T11:05:36.546+0800: 586214.858: Total time for which application threads were stopped: 0.0024409 seconds, Stopping threads took: 0.0000583 seconds
2021-12-17T11:05:36.548+0800: 586214.860: Total time for which application threads were stopped: 0.0017922 seconds, Stopping threads took: 0.0000891 seconds
2021-12-17T11:05:36.549+0800: 586214.862: Total time for which application threads were stopped: 0.0014720 seconds, Stopping threads took: 0.0000383 seconds
2021-12-17T11:05:36.551+0800: 586214.863: Total time for which application threads were stopped: 0.0013391 seconds, Stopping threads took: 0.0000371 seconds
2021-12-17T11:05:36.554+0800: 586214.866: Total time for which application threads were stopped: 0.0030225 seconds, Stopping threads took: 0.0000661 seconds
2021-12-17T11:05:39.305+0800: 586217.617: Total time for which application threads were stopped: 0.0027350 seconds, Stopping threads took: 0.0001301 seconds
2021-12-17T11:05:44.307+0800: 586222.620: Total time for which application threads were stopped: 0.0027371 seconds, Stopping threads took: 0.0001302 seconds
2021-12-17T11:05:45.523+0800: 586223.836: Total time for which application threads were stopped: 0.0026834 seconds, Stopping threads took: 0.0001301 seconds
2021-12-17T11:05

:49.310+0800: 586227.623: Total time for which application threads were stopped: 0.0028219 seconds, Stopping threads took: 0.0001403 seconds
2021-12-17T11:05:51.289+0800: 586229.601: Total time for which application threads were stopped: 0.0027332 seconds, Stopping threads took: 0.0001334 seconds
2021-12-17T11:05:54.313+0800: 586232.625: Total time for which application threads were stopped: 0.0027188 seconds, Stopping threads took: 0.0001362 seconds
2021-12-17T11:05:55.014+0800: 586233.326: Total time for which application threads were stopped: 0.0063113 seconds, Stopping threads took: 0.0000823 seconds
2021-12-17T11:05:55.023+0800: 586233.335: Total time for which application threads were stopped: 0.0050357 seconds, Stopping threads took: 0.0001209 seconds
2021-12-17T11:05:56.296+0800: 586234.608: Total time for which application threads were stopped: 0.0027895 seconds, Stopping threads took: 0.0001338 seconds
2021-12-17T11:05:59.316+0800: 586237.628: Total time for which application threads were stopped: 0.0027693 seconds, Stopping threads took: 0.0001506 seconds
2021-12-17T11:06:00.908+0800: 586239.220: Total time for which application threads were stopped: 0.0026593 seconds, Stopping threads took: 0.0001262 seconds
2021-12-17T11:06:02.723+0800: 586241.035: Total time for which application threads were stopped: 0.0025761 seconds, Stopping threads took: 0.0000771 seconds
2021-12-17T11:06:04.319+0800: 586242.631: Total time for which application threads were stopped: 0.0026987 seconds, Stopping threads took: 0.0001338 seconds
2021-12-17T11:06:09.322+0800: 586247.634: Total time for which application threads were stopped: 0.0027850 seconds, Stopping threads took: 0.0001426 seconds
2021-12-17T11:06:13.512+0800: 586251.824: Total time for which application threads were stopped: 0.0044105 seconds, Stopping threads took: 0.0001225 seconds
2021-12-17T11:06:13.516+0800: 586251.828: Total time for which application threads were stopped: 0.0037111 seconds, Stopping threads took: 0.0000743 seconds
2021-12-17T11:06:14.325+0800: 586252.637: Total time for which application threads were stopped: 0.0026957 seconds, Stopping threads took: 0.0001287 seconds
2021-12-17T11:06:15.027+0800: 586253.339: Total time for which application threads were stopped: 0.0027161 seconds, Stopping threads took: 0.0001245 seconds
2021-12-17T11:06:19.327+0800: 586257.640: Total time for which application threads were stopped: 0.0027186 seconds, Stopping threads took: 0.0001334 seconds
2021-12-17T11:06:20.792+0800: 586259.104: Total time for which application threads were stopped: 0.0026591 seconds, Stopping threads took: 0.0001303 seconds
2021-12-17T11:06:24.330+0800: 586262.642: Total time for which application threads were stopped: 0.0026434 seconds, Stopping threads took: 0.0001241 seconds
2021-12-17T11:06:25.598+0800: 586263.910: Total time for which application threads were stopped: 0.0025709 seconds, Stopping threads took: 0.0000825 seconds
2021-12-17T11:06:25.799+0800: 586264.111: Total time for which application threads were stopped: 0.0026484 seconds, Stopping threads took: 0.0001233 seconds
2021-12-17T11:06:29.333+0800: 586267.645: Total time for which application threads were stopped: 0.0027803 seconds, Stopping threads took: 0.0001906 seconds
2021-12-17T11:06:30.420+0800: 586268.732: Total time for which application threads were stopped: 0.0045233 seconds, Stopping threads took: 0.0001526 seconds
2021-12-17T11:06:34.336+0800: 586272.648: Total time for which application threads were stopped: 0.0027355 seconds, Stopping threads took: 0.0001447 seconds
2021-12-17T11:06:35.418+0800: 586273.730: Total time for which application threads were stopped: 0.0026743 seconds, Stopping threads took: 0.0001425 seconds
2021-12-17T11:06:39.339+0800: 586277.651: Total time for which application threads were stopped: 0.0028013 seconds, Stopping threads took: 0.0001549 seconds
2021-12-17T11:06:41.136+0800: 586279.448: Total time for which application threads were stopped: 0.0026801 seconds, Stopping threads took: 0.0001319 seconds
2021-12-17T11:06:44.150+0800: 586282.462: Total time for which application threads were stopped: 0.0029256 seconds, Stopping threads took: 0.0001668 seconds
2021-12-17T11:06:44.342+0800: 586282.654: Total time for which application threads were stopped: 0.0027620 seconds, Stopping threads took: 0.0001327 seconds
2021-12-17T11:06:44.530+0800: 586282.842: Total time for which application threads were stopped: 0.0026366 seconds, Stopping threads took: 0.0001293 seconds
{Heap before GC invocations=7687 (full 5):
 PSYoungGen      total 4187136K, used 4185942K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 4179968K, 100% used [0x00000006c0000000,0x00000007bf200000,0x00000007bf200000)
  from space 7168K, 83% used [0x00000007bf200000,0x00000007bf7d5b78,0x00000007bf900000)
  to   space 7168K, 0% used [0x00000007bf900000,0x00000007bf900000,0x00000007c0000000)
 ParOldGen       total 8388608K, used 1474497K [0x00000004c0000000, 0x00000006c0000000, 0x00000006c0000000)
  object space 8388608K, 17% used [0x00000004c0000000,0x0000000519ff0588,0x00000006c0000000)
 Metaspace       used 158300K, capacity 167588K, committed 167896K, reserved 1198080K
  class space    used 18478K, capacity 20165K, committed 20224K, reserved 1048576K
2021-12-17T11:06:49.116+0800: 586287.428: [GC (Allocation Failure) 2021-12-17T11:06:49.124+0800: 586287.436: [SoftReference, 0 refs, 0.0000289 secs]2021-12-17T11:06:49.124+0800: 586287.436: [WeakReference, 255 refs, 0.0000282 secs]2021-12-17T11:06:49.124+0800: 586287.436: [FinalReference, 525 refs, 0.0001696 secs]2021-12-17T11:06:49.124+0800: 586287.436: [PhantomReference, 21 refs, 2 refs, 0.0000065 secs]2021-12-17T11:06:49.124+0800: 586287.436: [JNI Weak Reference, 0.1216362 secs][PSYoungGen: 4185942K->4429K(4187136K)] 5660440K->1478958K(12575744K), 0.1316513 secs] [Times: user=0.11 sys=0.04, real=0.13 secs] 
Heap after GC invocations=7687 (full 5):
 PSYoungGen      total 4187136K, used 4429K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 4179968K, 0% used [0x00000006c0000000,0x00000006c0000000,0x00000007bf200000)
  from space 7168K, 61% used [0x00000007bf900000,0x00000007bfd534a0,0x00000007c0000000)
  to   space 7168K, 0% used [0x00000007bf200000,0x00000007bf200000,0x00000007bf900000)
 ParOldGen       total 8388608K, used 1474529K [0x00000004c0000000, 0x00000006c0000000, 0x00000006c0000000)
  object space 8388608K, 17% used [0x00000004c0000000,0x0000000519ff8588,0x00000006c0000000)
 Metaspace       used 158300K, capacity 167588K, committed 167896K, reserved 1198080K
  class space    used 18478K, capacity 20165K, committed 20224K, reserved 1048576K
}
2021-12-17T11:06:49.248+0800: 586287.560: Total time for which application threads were stopped: 0.1347731 seconds, Stopping threads took: 0.0001560 seconds
2021-12-17T11:06:49.345+0800: 586287.657: Total time for which application threads were stopped: 0.0028468 seconds, Stopping threads took: 0.0001287 seconds
2021-12-17T11:06:50.296+0800: 586288.608: Total time for which application threads were stopped: 0.0027915 seconds, Stopping threads took: 0.0001519 seconds
2021-12-17T11:06:54.347+0800: 586292.660: Total time for which application threads were stopped: 0.0027486 seconds, Stopping threads took: 0.0001270 seconds
2021-12-17T11:06:55.303+0800: 586293.615: Total time for which application threads were stopped: 0.0028923 seconds, Stopping threads took: 0.0001501 seconds
2021-12-17T11:06:59.350+0800: 586297.662: Total time for which application threads were stopped: 0.0027103 seconds, Stopping threads took: 0.0001349 seconds
2021-12-17T11:06:59.929+0800: 586298.241: Total time for which application threads were stopped: 0.0028057 seconds, Stopping threads took: 0.0001801 seconds
2021-12-17T11:07:02.748+0800: 586301.060: Total time for which application threads were stopped: 0.0026147 seconds, Stopping threads took: 0.0000881 seconds
2021-12-17T11:07:04.353+0800: 586302.666: Total time for which application threads were stopped: 0.0029218 seconds, Stopping threads took: 0.0001487 seconds
2021-12-17T11:07:09.356+0800: 586307.668: Total time for which application threads were stopped: 0.0028200 seconds, Stopping threads took: 0.0001361 seconds
2021-12-17T11:07:14.033+0800: 586312.345: Total time for which application threads were stopped: 0.0026529 seconds, Stopping threads took: 0.0001298 seconds
2021-12-17T11:07:14.359+0800: 586312.671: Total time for which application threads were stopped: 0.0028125 seconds, Stopping threads took: 0.0001263 seconds
2021-12-17T11:07:19.362+0800: 586317.674: Total time for which application threads were stopped: 0.0027028 seconds, Stopping threads took: 0.0001289 seconds
2021-12-17T11:07:19.799+0800: 586318.111: Total time for which application threads were stopped: 0.0027259 seconds, Stopping threads took: 0.0001389 seconds
2021-12-17T11:07:24.365+0800: 586322.677: Total time for which application threads were stopped: 0.0026719 seconds, Stopping threads took: 0.0001370 seconds
2021-12-17T11:07:24.806+0800: 586323.118: Total time for which application threads were stopped: 0.0026830 seconds, Stopping threads took: 0.0001379 seconds
2021-12-17T11:07:25.598+0800: 586323.910: Total time for which application threads were stopped: 0.0026317 seconds, Stopping threads took: 0.0000792 seconds
2021-12-17T11:07:29.368+0800: 586327.680: Total time for which application threads were stopped: 0.0028429 seconds, Stopping threads took: 0.0001358 seconds
2021-12-17T11:07:29.437+0800: 586327.749: Total time for which application threads were stopped: 0.0026888 seconds, Stopping threads took: 0.0001463 seconds
2021-12-17T11:07:34.371+0800: 586332.683: Total time for which application threads were stopped: 0.0027324 seconds, Stopping threads took: 0.0001267 seconds
2021-12-17T11:07:39.374+0800: 586337.686: Total time for which application threads were stopped: 0.0028530 seconds, Stopping threads took: 0.0001392 seconds

 

2. 环境说明

1)环境JDK版本:

openjdk version "1.8.0_252"
OpenJDK Runtime Environment (build 1.8.0_252-b09)
OpenJDK 64-Bit Server VM (build 25.252-b09, mixed mode)

2)应用的pod(k8s分配) 内存12G

3)应用启动的JVM参数设置:

JAVA_OPTS="-Duser.home=${APP_HOME} -Dspring.profiles.active=prod -Dhsf.http.enable=true -Dhsf.http.port=12220 -Xms12288m -Xmx12288m -XX:+PrintReferenceGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:gc.log"

3. 尝试过的解决方法

参考过大神的方法帖子:https://mp.weixin.qq.com/s/m0YpJuHB3pkrvUylYbe5eg

但是JVM调整调试打印的方法不大会,所以没法进一步核查;

4. 提问

 

 

 

 

147 阅读
请先登录,再评论

同问

25月前