性能问答>Young GC越来越慢,从40ms逐渐增加到80ms,直到发生CMS GC,Young GC降回40ms,然后又增加,有哪些原因呢?>
5回复

Young GC越来越慢,从40ms逐渐增加到80ms,直到发生CMS GC,Young GC降回40ms,然后又增加,有哪些原因呢?



线上服务机器,CMS GC大概1天一次,每次CMS GC后,Young GC的性能很好,大概40ms左右,随着运行时间增加,Young GC升到80ms,直到触发CMS GC。查了半天资料,网上说有两种原因:
(1)StringTable太大?
我没有用-XX:+PrintStringTableStatistics统计StringTable,但查看CMS GC日志,发现scrub string table非常耗时[scrub string table, 0.2077233 secs],这是不是也从侧面反映了当前StringTable是比较大?

2020-06-01T23:31:54.546+0800: 47159.891: [CMS-concurrent-mark-start]
2020-06-01T23:31:54.892+0800: 47160.237: [CMS-concurrent-mark: 0.346/0.346 secs] [Times: user=0.46 sys=0.16, real=0.34 secs] 
2020-06-01T23:31:54.893+0800: 47160.237: [CMS-concurrent-preclean-start]
2020-06-01T23:31:54.938+0800: 47160.283: [CMS-concurrent-preclean: 0.045/0.045 secs] [Times: user=0.08 sys=0.01, real=0.05 secs] 
2020-06-01T23:31:54.938+0800: 47160.283: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2020-06-01T23:31:59.978+0800: 47165.323: [CMS-concurrent-abortable-preclean: 5.035/5.040 secs] [Times: user=8.39 sys=1.09, real=5.04 secs] 
2020-06-01T23:31:59.978+0800: 47165.323: Application time: 5.4319173 seconds
2020-06-01T23:31:59.984+0800: 47165.329: [GC (CMS Final Remark) [YG occupancy: 925114 K (1887488 K)]{Heap before GC invocations=5628 (full 1):
 par new generation   total 1887488K, used 925114K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)
  eden space 1677824K,  52% used [0x0000000673400000, 0x00000006a8c168b8, 0x00000006d9a80000)
  from space 209664K,  23% used [0x00000006d9a80000, 0x00000006dc9d7f48, 0x00000006e6740000)
  to   space 209664K,   0% used [0x00000006e6740000, 0x00000006e6740000, 0x00000006f3400000)
 concurrent mark-sweep generation total 3354624K, used 2683885K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 138120K, capacity 143771K, committed 143872K, reserved 1175552K
  class space    used 16128K, capacity 17124K, committed 17152K, reserved 1048576K
2020-06-01T23:31:59.984+0800: 47165.329: [GC (CMS Final Remark) 47165.329: [ParNew: 925114K->44684K(1887488K), 0.0977515 secs] 3608999K->2728976K(5242112K), 0.0982853 secs] [Times: user=0.33 sys=0.03, real=0.10 secs] 
Heap after GC invocations=5629 (full 1):
 par new generation   total 1887488K, used 44684K [0x0000000673400000, 0x00000006f3400000, 0x00000006f3400000)
  eden space 1677824K,   0% used [0x0000000673400000, 0x0000000673400000, 0x00000006d9a80000)
  from space 209664K,  21% used [0x00000006e6740000, 0x00000006e92e3230, 0x00000006f3400000)
  to   space 209664K,   0% used [0x00000006d9a80000, 0x00000006d9a80000, 0x00000006e6740000)
 concurrent mark-sweep generation total 3354624K, used 2684291K [0x00000006f3400000, 0x00000007c0000000, 0x00000007c0000000)
 Metaspace       used 138120K, capacity 143771K, committed 143872K, reserved 1175552K
  class space    used 16128K, capacity 17124K, committed 17152K, reserved 1048576K
}
47165.428: [Rescan (parallel) , 0.0153295 secs]47165.443: [weak refs processing, 0.0612119 secs]47165.504: [class unloading, 0.1916678 secs]47165.696: [scrub symbol table, 0.0471500 secs]47165.743: [scrub string table, 0.2077233 secs][1 CMS-remark: 2684291K(3354624K)] 2728976K(5242112K), 0.6482910 secs] [Times: user=0.81 sys=0.15, real=0.65 secs] 
2020-06-01T23:32:00.633+0800: 47165.978: Total time for which application threads were stopped: 0.6546011 seconds, Stopping threads took: 0.0007203 seconds
2020-06-01T23:32:00.633+0800: 47165.978: [CMS-concurrent-sweep-start]

代码中没有显示地使用String.intern(),但使用了fastjson和jackson来把Stirng对象返序列化成类。

(2)老年代空间占用会影响Young GC的对象晋升效率?
老年代内存占用60%和老年代内存占用40%的时候的Young GC效率会不同吗?这个的原理或依据是什么呢?空闲链表给晋升对象分配空间耗时?

JVM参数是下面:

VM Arguments: jvm_args: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handler.pkgs=org.apache.catalina.webresources -Djava.awt.headless=true -Xms5324m -Xmx5324m -Xss512k -XX:PermSize=350m -XX:MaxPermSize=350m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=256m -XX:NewSize=2048m -XX:MaxNewSize=2048m -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=9 -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly -XX:+CMSScavengeBeforeRemark -XX:+ScavengeBeforeFullGC -XX:+UseCMSCompactAtFullCollection -XX:+CMSParallelRemarkEnabled -XX:CMSFullGCsBeforeCompaction=9 -XX:CMSInitiatingOccupancyFraction=80 -XX:+CMSClassUnloadingEnabled -XX:SoftRefLRUPolicyMSPerMB=0 -XX:-ReduceInitialCardMarks -XX:+CMSPermGenSweepingEnabled -XX:CMSInitiatingPermOccupancyFraction=80 -XX:+ExplicitGCInvokesConcurrent -Djava.nio.channels.spi.SelectorProvider=sun.nio.ch.EPollSelectorProvider -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintHeapAtGC -Xloggc:/data/applogs/heap_trace.txt -XX:+IgnoreUnrecognizedVMOptions -XX:-HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/applogs/HeapDumpOnOutOfMemoryError -Duser.timezone=Asia/Shanghai -Dclient.encoding.override=UTF-8 -Dfile.encoding=UTF-8 -Duser.region=CN -Djava.endorsed.dirs=/usr/local/tomcat/endorsed -Dcatalina.base=/usr/local/tomcat -Dcatalina.home=/usr/local/tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp java_command: org.apache.catalina.startup.Bootstrap start java_class_path (initial): /usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/tomcat-juli.jar Launcher Type: SUN_STANDARD
6154 阅读
请先登录,查看5条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步