0

java -version

java version "1.6.0_21" Java(TM) SE Runtime Environment (build 1.6.0_21-b07) Java HotSpot(TM) 64-Bit Server VM (build 17.0-b17, mixed mode)

jvm configuration :

-server -XX:+DoEscapeAnalysis -XX:+CMSParallelRemarkEnabled -XX:+UseBiasedLocking -XX:ParallelGCThreads=20 -XX:+UseLargePages -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSConcurrentMTEnabled -XX:SurvivorRatio=8 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=15 -XX:ReservedCodeCacheSize=128m -XX:+UseCodeCacheFlushing -XX:NewRatio=3 -XX:+DisableExplicitGC -Dsun.rmi.dgc.client.gcInterval=1800000 -Dsun.rmi.dgc.server.gcInterval=1800000 -Djava.net.preferIPv4Stack=true -Xss1024k -Xms8192m -Xmx8192m -XX:MaxPermSize=1024m -XX:PermSize=1024m -Dremoting.bind_by_host=false -Dorg.jboss.resolver.warning=true -Dclient.encoding.override=UTF-8 -Dfile.encoding=UTF-8 -Dnet.sf.ehcache.skipUpdateCheck=true -Dorg.apache.xerces.xni.parser.XMLParserConfiguration=org.apache.xerces.parsers.XIncludeAwareParserConfiguration

-Djavax.xml.parsers.DocumentBuilderFactory=org.apache.xerces.jaxp.DocumentBuilderFactoryImpl -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+HeapDumpOnOutOfMemoryError -Djava.net.preferIPv4Stack=true -Dorg.apache.el.parser.COERCE_TO_ZERO=false -Dorg.apache.catalina.connector.Request.SESSION_ID_CHECK=false

32163.991: [CMS-concurrent-mark-start]
32165.339: [CMS-concurrent-mark: 1.318/1.347 secs] [Times: user=6.49 sys=0.39, real=1.35 secs] 
32165.339: [CMS-concurrent-preclean-start]
32165.370: [CMS-concurrent-preclean: 0.030/0.031 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
32165.370: [CMS-concurrent-abortable-preclean-start]  CMS: abort preclean due to time 32170.796: [CMS-concurrent-abortable-preclean:
3.737/5.426 secs] [Times: user=10.70 sys=0.31, real=5.43 secs] 
32170.873: [GC[YG occupancy: 754283 K (1887488 K)]32170.873: [Rescan (parallel) , 0.1046140 secs]32170.978: [weak refs processing,
0.0612460 secs] [1 CMS-remark: 5824525K(6291456K)] 6578809K(8178944K), 0.1700560 secs] [Times: user=1.51 sys=0.02, real=0.17 secs] 
32171.100: [CMS-concurrent-sweep-start]
32173.805: [GC 32173.805: [ParNew: 1887488K->209664K(1887488K), 0.3380510 secs] 6928845K->5305271K(8178944K), 0.3385670 secs] [Times: user=1.25 sys=0.05, real=0.34 secs] 
32176.970: [GC 32176.970: [ParNew: 1887488K->209664K(1887488K), 0.1728610 secs] 5660997K->4005785K(8178944K), 0.1734010 secs] [Times: user=1.09 sys=0.10, real=0.17 secs] 
32179.315: [CMS-concurrent-sweep: 6.088/8.215 secs] [Times: user=48.00 sys=2.80, real=8.22 secs] 
32179.315: [CMS-concurrent-reset-start]
32179.507: [CMS-concurrent-reset: 0.192/0.192 secs] [Times: user=1.51 sys=0.22, real=0.19 secs]

Is it CMS-concurrent-preclean abort causing time consuming execution of CMS-concurrent-sweep? Will it cause 48 seconds world stop exeperience to user? What is the inference from the above gc log.

the8472
  • 40,999
  • 5
  • 70
  • 122
Steephen
  • 14,645
  • 7
  • 40
  • 47

1 Answers1

1

  • all phases denoted CMS-concurrent-* are, as the name says, concurrent and therefore not STW pauses. CMS Initial Mark and CMS Final Remark are the pauses caused by the concurrent cycle. Of course the young gen collector has its own STW pauses

  • user=xxx has the same semantics as the output of the time command. It refers to core-time for which the process is scheduled, it has very relation to elapsed wall time. real is what you're looking for if you're interested in the duration of STW pauses.

What is the inference from the above gc log.

The longest STW pause visible in that GC log lasts for 340 milliseconds.

This can also be logged more explicitly with the -XX:+PrintGCApplicationConcurrentTime setting. You may also want to take a look at GCViewer which makes analyzing those logs easier.

Sidenote: If you're concerned about performance you may want to upgrade your JVM, over time there have been jit improvements. Escape analysis did little back in 1.6 (only lock elision, not SA)

the8472
  • 40,999
  • 5
  • 70
  • 122