求助>重启后YGC时间较长,经历一次FGC后YGC下降明显,怎么排查>
3回复
1月前

重启后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原因,请教一下大家,有没有思路优化?

588 阅读
请先登录,再评论

回复列表

ferdi1月前

从你贴的日志来看,耗时的差异主要来自于拷贝内容的大小,前后对比,新生代存活大小正好大概一半,理论上这个不算太大的问题,可以考虑启动完成后主动进行一次fullgc,如果对暂停时间有比较严格的要求也可以尝试换G1设置-XX:MaxGCPauseMillis最大暂停时间。另一方面可以提供下完整的gc日志吗?有一点比较好奇,为啥一直到fullgc,s区的占用才减下来?

孜孜1月前
回复 ferdi:

-XX:MaxGCPauseMillis官方都是建议谨慎使用,设置100ms对我们也没有意义,完整GC日志太多不好贴

回复
心弦1月前

大内存的话,用G1会不会好一点?