性能问答>重启后YGC时间较长,经历一次FGC后YGC下降明显,怎么排查>
3回复
3年前

重启后YGC时间较长,经历一次FGC后YGC下降明显,怎么排查



我们这边遇到一个情况是,每次重启YGC大约60~80ms,FGC后YGC降到20ms~30ms,这个一般怎么排查好呢?
JVM参数

-Xms10g -Xmx10g -Xmn8g -XX:MetaspaceSize=2g -XX:MaxMetaspaceSize=2g -XX:MinMetaspaceFreeRatio=0 -XX:MaxMetaspaceFreeRatio=100 -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:CMSInitiatingOccupancyFraction=60 -XX:+CMSParallelRemarkEnabled -XX:SoftRefLRUPolicyMSPerMB=0 -XX:+CMSClassUnloadingEnabled -XX:SurvivorRatio=8 -XX:+DisableExplicitGC -XX:-OmitStackTraceInFastThrow -XX:+PrintReferenceGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+PrintHeapAtGC

重启后稳定一段时间后YGC日志

{Heap before GC invocations=30 (full 0):
 par new generation   total 7549760K, used 6799988K [0x0000000540000000, 0x0000000740000000, 0x0000000740000000)
  eden space 6710912K, 100% used [0x0000000540000000, 0x00000006d99a0000, 0x00000006d99a0000)
  from space 838848K,  10% used [0x00000006d99a0000, 0x00000006df09d2b0, 0x000000070ccd0000)
  to   space 838848K,   0% used [0x000000070ccd0000, 0x000000070ccd0000, 0x0000000740000000)
 concurrent mark-sweep generation total 2097152K, used 190228K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 270917K, capacity 288719K, committed 288896K, reserved 1306624K
  class space    used 29534K, capacity 32617K, committed 32640K, reserved 1048576K
2021-01-21T10:44:25.801+0800: 798.446: [GC (Allocation Failure) 2021-01-21T10:44:25.802+0800: 798.446: [ParNew2021-01-21T10:44:25.866+0800: 798.510: [SoftReference, 446 refs, 0.0001675 secs]2021-01-21T10:44:25.866+0800: 798.511: [WeakReference, 5504 refs, 0.0004158 secs]2021-01-21T10:44:25.866+0800: 798.511: [FinalReference, 3469 refs, 0.0013003 secs]2021-01-21T10:44:25.868+0800: 798.512: [PhantomReference, 1 refs, 9 refs, 0.0000927 secs]2021-01-21T10:44:25.868+0800: 798.512: [JNI Weak Reference, 0.0001262 secs]: 6799988K->94101K(7549760K), 0.0667137 secs] 6990217K->286240K(9646912K), 0.0679152 secs] [Times: user=0.35 sys=0.00, real=0.07 secs]
Heap after GC invocations=31 (full 0):
 par new generation   total 7549760K, used 94101K [0x0000000540000000, 0x0000000740000000, 0x0000000740000000)
  eden space 6710912K,   0% used [0x0000000540000000, 0x0000000540000000, 0x00000006d99a0000)
  from space 838848K,  11% used [0x000000070ccd0000, 0x00000007128b5618, 0x0000000740000000)
  to   space 838848K,   0% used [0x00000006d99a0000, 0x00000006d99a0000, 0x000000070ccd0000)
 concurrent mark-sweep generation total 2097152K, used 192138K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 270917K, capacity 288719K, committed 288896K, reserved 1306624K
  class space    used 29534K, capacity 32617K, committed 32640K, reserved 1048576K
}

这个时候手动触发FGC,YGC日志如下

{Heap before GC invocations=184 (full 1):
 par new generation   total 7549760K, used 6759945K [0x0000000540000000, 0x0000000740000000, 0x0000000740000000)
  eden space 6710912K, 100% used [0x0000000540000000, 0x00000006d99a0000, 0x00000006d99a0000)
  from space 838848K,   5% used [0x000000070ccd0000, 0x000000070fcb26b8, 0x0000000740000000)
  to   space 838848K,   0% used [0x00000006d99a0000, 0x00000006d99a0000, 0x000000070ccd0000)
 concurrent mark-sweep generation total 2097152K, used 286653K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 236071K, capacity 253147K, committed 313856K, reserved 1327104K
  class space    used 25637K, capacity 28467K, committed 35328K, reserved 1048576K
2021-01-21T11:31:21.122+0800: 3613.767: [GC (Allocation Failure) 2021-01-21T11:31:21.123+0800: 3613.767: [ParNew2021-01-21T11:31:21.138+0800: 3613.783: [SoftReference, 368 refs, 0.0001248 secs]2021-01-21T11:31:21.138+0800: 3613.783: [WeakReference, 517 refs, 0.0000651 secs]2021-01-21T11:31:21.138+0800: 3613.783: [FinalReference, 3727 refs, 0.0014593 secs]2021-01-21T11:31:21.140+0800: 3613.785: [PhantomReference, 0 refs, 0 refs, 0.0000123 secs]2021-01-21T11:31:21.140+0800: 3613.785: [JNI Weak Reference, 0.0001213 secs]: 6759945K->48233K(7549760K), 0.0180800 secs] 7046598K->336004K(9646912K), 0.0192935 secs] [Times: user=0.12 sys=0.00, real=0.02 secs]
Heap after GC invocations=185 (full 1):
 par new generation   total 7549760K, used 48233K [0x0000000540000000, 0x0000000740000000, 0x0000000740000000)
  eden space 6710912K,   0% used [0x0000000540000000, 0x0000000540000000, 0x00000006d99a0000)
  from space 838848K,   5% used [0x00000006d99a0000, 0x00000006dc8ba6b0, 0x000000070ccd0000)
  to   space 838848K,   0% used [0x000000070ccd0000, 0x000000070ccd0000, 0x0000000740000000)
 concurrent mark-sweep generation total 2097152K, used 287771K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 236071K, capacity 253147K, committed 313856K, reserved 1327104K
  class space    used 25637K, capacity 28467K, committed 35328K, reserved 1048576K
}
2021-01-21T11:31:21.142+0800: 3613.787: Total time for which application threads were stopped: 0.0259542 seconds, Stopping threads took: 0.0009365 seconds


从日志上排除了Reference和safepoint原因,请教一下大家,有没有思路优化?

2946 阅读
请先登录,查看3条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步