You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@synapse.apache.org by "Hiranya Jayathilaka (JIRA)" <ji...@apache.org> on 2016/05/26 23:55:13 UTC
[jira] [Resolved] (SYNAPSE-987) CMS running for every 6 seconds
[ https://issues.apache.org/jira/browse/SYNAPSE-987?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Hiranya Jayathilaka resolved SYNAPSE-987.
-----------------------------------------
Resolution: Won't Fix
Please reopen with more details, if this is still a valid issue.
> CMS running for every 6 seconds
> -------------------------------
>
> Key: SYNAPSE-987
> URL: https://issues.apache.org/jira/browse/SYNAPSE-987
> Project: Synapse
> Issue Type: Test
> Components: Core
> Affects Versions: 2.1
> Reporter: Arockia Raphael
> Assignee: Hiranya Jayathilaka
>
> Synapse deployed in Production with 10 rest Proxy services. axis2.xml is having default configuration. Load is not that huge. approx 5 calls/minute. This issue started only after 1 week of synapse server started in production. Initially minor GC was happening every half an hour and full GC happened once in 3 days.
> Following is configured in wrapper.conf.
> wrapper.java.additional.10=-Dsun.rmi.dgc.client.gcInterval=604800000
> wrapper.java.additional.11=-Dsun.rmi.dgc.server.gcInterval=604800000
> wrapper.java.additional.12=-XX:NewSize=1024m
> wrapper.java.additional.13=-XX:MaxNewSize=1024m
> wrapper.java.additional.14=-XX:PermSize=256m
> wrapper.java.additional.15=-XX:MaxPermSize=256m
> wrapper.java.additional.16=-XX:SurvivorRatio=65536
> wrapper.java.additional.17=-XX:TargetSurvivorRatio=0
> wrapper.java.additional.18=-XX:MaxTenuringThreshold=0
> wrapper.java.additional.19=-XX:+UseParNewGC
> wrapper.java.additional.20=-XX:ParallelGCThreads=12
> wrapper.java.additional.21=-XX:+UseConcMarkSweepGC
> wrapper.java.additional.22=-XX:+CMSParallelRemarkEnabled
> wrapper.java.additional.23=-XX:+CMSCompactWhenClearAllSoftRefs
> wrapper.java.additional.24=-XX:+UseCMSInitiatingOccupancyOnly
> wrapper.java.additional.25=-XX:CMSInitiatingOccupancyFraction=85
> wrapper.java.additional.26=-XX:+HeapDumpBeforeFullGC
> wrapper.java.additional.27=-XX:PrintCMSStatistics=2
> wrapper.java.additional.28=-XX:+CMSScavengeBeforeRemark
> wrapper.java.additional.29=-XX:+PrintGC
> wrapper.java.additional.30=-XX:+PrintGCDetails
> wrapper.java.additional.31=-XX:+PrintGCTimeStamps
> wrapper.java.additional.32=-XX:+PrintGCDateStamps
> wrapper.java.additional.33=-XX:+UseCompressedOops
> wrapper.java.additional.34=-XX:+DisableExplicitGC
> wrapper.java.additional.35=-XX:ReservedCodeCacheSize=64m
> wrapper.java.additional.36=-XX:InitialCodeCacheSize=64m
> #wrapper.java,additional.5=-Djavax.net.debug=all
> # Initial Java Heap Size (in MB)
> wrapper.java.initmemory=1024
> # Maximum Java Heap Size (in MB)
> wrapper.java.maxmemory=1024
> Back to Back CMS is running for every 6 seconds
> 2014-04-29T01:01:16.220-0600: 31304.073: [GC 31304.073: [ParNew: 1048448K->0K(1048512K), 0.0028640 secs] 1116752K->68794K(2097088K), 0.0029990 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
> 2014-04-29T01:17:28.267-0600: 32276.120: [GC 32276.120: [ParNew: 1048448K->0K(1048512K), 1.4987770 secs] 1117242K->521514K(2097088K), 1.4989970 secs] [Times: user=6.66 sys=0.23, real=1.50 secs]
> 2014-04-29T01:18:14.681-0600: 32322.534: [GC [1 CMS-initial-mark: 521514K(1048576K)] 1048937K(2097088K), 0.6464780 secs] [Times: user=0.71 sys=0.00, real=0.65 secs]
> 2014-04-29T01:18:15.328-0600: 32323.181: [CMS-concurrent-mark-start]
> Finished cms space scanning in 0th thread: 0.052 sec
> Finished cms space scanning in 2th thread: 0.052 sec
> Finished perm space scanning in 0th thread: 0.020 sec
> Finished perm space scanning in 2th thread: 0.021 sec
> Finished cms space scanning in 1th thread: 0.308 sec
> Finished perm space scanning in 1th thread: 0.000 sec
> Finished work stealing in 0th thread: 0.359 sec
> Finished work stealing in 1th thread: 0.123 sec
> Finished work stealing in 2th thread: 0.358 sec
> 2014-04-29T01:18:15.760-0600: 32323.613: [CMS-concurrent-mark: 0.429/0.432 secs] (CMS-concurrent-mark yielded 2 times)
> [Times: user=1.48 sys=0.00, real=0.43 secs]
> 2014-04-29T01:18:15.760-0600: 32323.613: [CMS-concurrent-preclean-start]
> (cardTable: 1171 cards, re-scanned 1171 cards, 1 iterations)
> 2014-04-29T01:18:15.765-0600: 32323.618: [CMS-concurrent-preclean: 0.005/0.005 secs] (CMS-concurrent-preclean yielded 0 times)
> [Times: user=0.01 sys=0.00, real=0.00 secs]
> 2014-04-29T01:18:15.765-0600: 32323.618: [CMS-concurrent-abortable-preclean-start]
> [0 iterations, 0 waits, 0 cards)] 2014-04-29T01:18:15.765-0600: 32323.618: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] (CMS-concurrent-abortable-preclean yielded 0 times)
> [Times: user=0.00 sys=0.00, real=0.00 secs]
> 2014-04-29T01:18:15.766-0600: 32323.619: [GC[YG occupancy: 538600 K (1048512 K)]2014-04-29T01:18:15.766-0600: 32323.619: [GC 32323.619: [ParNew: 538600K->538600K(1048512K), 0.0000190 secs] 1060114K->1060114K(2097088K), 0.0001450 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
> 32323.619: [Rescan (parallel) (Survivor:0chunks) Finished young gen rescan work in 1th thread: 0.000 sec
> Finished young gen rescan work in 2th thread: 0.000 sec
> Finished young gen rescan work in 3th thread: 0.000 sec
> Finished young gen rescan work in 4th thread: 0.000 sec
> Finished young gen rescan work in 5th thread: 0.000 sec
> Finished young gen rescan work in 6th thread: 0.000 sec
> Finished young gen rescan work in 7th thread: 0.000 sec
> Finished remaining root rescan work in 6th thread: 0.000 sec
> Finished remaining root rescan work in 1th thread: 0.000 sec
> Finished remaining root rescan work in 2th thread: 0.000 sec
> Finished remaining root rescan work in 5th thread: 0.000 sec
> Finished remaining root rescan work in 7th thread: 0.000 sec
> Finished remaining root rescan work in 4th thread: 0.000 sec
> Finished young gen rescan work in 8th thread: 0.000 sec
> Finished remaining root rescan work in 8th thread: 0.000 sec
> Finished young gen rescan work in 9th thread: 0.000 sec
> Finished remaining root rescan work in 9th thread: 0.000 sec
> Finished young gen rescan work in 10th thread: 0.000 sec
> Finished remaining root rescan work in 10th thread: 0.000 sec
> Finished young gen rescan work in 11th thread: 0.000 sec
> Finished remaining root rescan work in 11th thread: 0.000 sec
> Finished dirty card rescan work in 10th thread: 0.000 sec
> Finished dirty card rescan work in 11th thread: 0.000 sec
> Finished dirty card rescan work in 4th thread: 0.000 sec
> Finished dirty card rescan work in 5th thread: 0.000 sec
> Finished dirty card rescan work in 1th thread: 0.000 sec
> Finished dirty card rescan work in 6th thread: 0.000 sec
> Finished dirty card rescan work in 2th thread: 0.000 sec
> Finished dirty card rescan work in 8th thread: 0.000 sec
> Finished dirty card rescan work in 9th thread: 0.000 sec
> Finished dirty card rescan work in 7th thread: 0.000 sec
> Finished remaining root rescan work in 3th thread: 0.001 sec
> Finished dirty card rescan work in 3th thread: 0.000 sec
> Finished young gen rescan work in 0th thread: 0.467 sec
> Finished remaining root rescan work in 0th thread: 0.000 sec
> Finished dirty card rescan work in 0th thread: 0.000 sec
> Finished work stealing in 0th thread: 0.000 sec
> Finished work stealing in 11th thread: 0.466 sec
> Finished work stealing in 1th thread: 0.466 sec
> Finished work stealing in 9th thread: 0.466 sec
> Finished work stealing in 7th thread: 0.466 sec
> Finished work stealing in 5th thread: 0.466 sec
> Finished work stealing in 8th thread: 0.466 sec
> Finished work stealing in 3th thread: 0.465 sec
> Finished work stealing in 6th thread: 0.466 sec
> Finished work stealing in 4th thread: 0.466 sec
> Finished work stealing in 10th thread: 0.466 sec
> Finished work stealing in 2th thread: 0.466 sec
> , 0.4670960 secs]32324.086: [weak refs processing, 0.0012080 secs] [1 CMS-remark: 521514K(1048576K)] 1060114K(2097088K), 0.4686100 secs] [Times: user=5.33 sys=0.00, real=0.47 secs]
> 2014-04-29T01:18:16.235-0600: 32324.088: [CMS-concurrent-sweep-start]
> 2014-04-29T01:18:16.589-0600: 32324.442: [CMS-concurrent-sweep: 0.348/0.354 secs] (CMS-concurrent-sweep yielded 8 times)
> [Times: user=0.44 sys=0.00, real=0.36 secs]
> 2014-04-29T01:18:16.589-0600: 32324.442: [CMS-concurrent-reset-start]
> 2014-04-29T01:18:16.592-0600: 32324.445: [CMS-concurrent-reset: 0.003/0.003 secs] (CMS-concurrent-reset yielded 0 times)
> [Times: user=0.00 sys=0.00, real=0.00 secs]
> CMSCollector shouldConcurrentCollect: 32324.534
> time_until_cms_gen_full 0.0000000
> free=551778056
> contiguous_available=537707408
> promotion_rate=318443
> cms_allocation_rate=0
> occupancy=0.4861166
> initiatingOccupancy=0.8500000
> initiatingPermOccupancy=0.9200000
> 2014-04-29T01:18:16.682-0600: 32324.534: [GC [1 CMS-initial-mark: 509730K(1048576K)] 1127786K(2097088K), 0.6731780 secs] [Times: user=0.74 sys=0.00, real=0.67 secs]
> 2014-04-29T01:18:17.355-0600: 32325.208: [CMS-concurrent-mark-start]
> Finished cms space scanning in 1th thread: 0.050 sec
> Finished cms space scanning in 2th thread: 0.049 sec
> Finished perm space scanning in 2th thread: 0.021 sec
> Finished perm space scanning in 1th thread: 0.022 sec
> Finished cms space scanning in 0th thread: 0.309 sec
> Finished perm space scanning in 0th thread: 0.000 sec
> Finished work stealing in 1th thread: 0.355 sec
> Finished work stealing in 2th thread: 0.356 sec
> Finished work stealing in 0th thread: 0.118 sec
> 2014-04-29T01:18:17.782-0600: 32325.635: [CMS-concurrent-mark: 0.425/0.427 secs] (CMS-concurrent-mark yielded 2 times)
> [Times: user=1.46 sys=0.00, real=0.43 secs]
> 2014-04-29T01:18:17.782-0600: 32325.635: [CMS-concurrent-preclean-start]
> (cardTable: 590 cards, re-scanned 590 cards, 1 iterations)
> 2014-04-29T01:18:17.787-0600: 32325.639: [CMS-concurrent-preclean: 0.004/0.004 secs] (CMS-concurrent-preclean yielded 0 times)
> [Times: user=0.00 sys=0.00, real=0.00 secs]
> 2014-04-29T01:18:17.787-0600: 32325.639: [CMS-concurrent-abortable-preclean-start]
> [0 iterations, 0 waits, 0 cards)] 2014-04-29T01:18:17.787-0600: 32325.639: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] (CMS-concurrent-abortable-preclean yielded 0 times)
> [Times: user=0.00 sys=0.00, real=0.00 secs]
> 2014-04-29T01:18:17.787-0600: 32325.640: [GC[YG occupancy: 632650 K (1048512 K)]2014-04-29T01:18:17.787-0600: 32325.640: [GC 32325.640: [ParNew: 632650K->632650K(1048512K), 0.0000190 secs] 1142381K->1142381K(2097088K), 0.0001130 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
> 32325.640: [Rescan (parallel) (Survivor:0chunks) Finished young gen rescan work in 1th thread: 0.000 sec
> Finished young gen rescan work in 2th thread: 0.000 sec
> Finished young gen rescan work in 3th thread: 0.000 sec
> Finished young gen rescan work in 4th thread: 0.000 sec
> Finished young gen rescan work in 5th thread: 0.000 sec
> Finished young gen rescan work in 6th thread: 0.000 sec
> Finished young gen rescan work in 7th thread: 0.000 sec
> Finished young gen rescan work in 8th thread: 0.000 sec
> Finished young gen rescan work in 9th thread: 0.000 sec
> Finished remaining root rescan work in 8th thread: 0.000 sec
> Finished remaining root rescan work in 4th thread: 0.000 sec
> Finished remaining root rescan work in 7th thread: 0.000 sec
> Finished remaining root rescan work in 2th thread: 0.000 sec
> Finished remaining root rescan work in 1th thread: 0.000 sec
> Finished remaining root rescan work in 3th thread: 0.000 sec
> Finished young gen rescan work in 10th thread: 0.000 sec
> Finished remaining root rescan work in 10th thread: 0.000 sec
> Finished remaining root rescan work in 6th thread: 0.000 sec
> Finished remaining root rescan work in 5th thread: 0.000 sec
> Finished young gen rescan work in 11th thread: 0.000 sec
> Finished remaining root rescan work in 11th thread: 0.000 sec
> Finished dirty card rescan work in 10th thread: 0.000 sec
> Finished dirty card rescan work in 2th thread: 0.000 sec
> Finished dirty card rescan work in 5th thread: 0.000 sec
> Finished dirty card rescan work in 8th thread: 0.000 sec
> Finished dirty card rescan work in 4th thread: 0.000 sec
> Finished dirty card rescan work in 1th thread: 0.000 sec
> Finished dirty card rescan work in 11th thread: 0.000 sec
> Finished dirty card rescan work in 7th thread: 0.000 sec
> Finished dirty card rescan work in 6th thread: 0.000 sec
> Finished dirty card rescan work in 3th thread: 0.000 sec
> Finished remaining root rescan work in 9th thread: 0.001 sec
> Finished dirty card rescan work in 9th thread: 0.000 sec
> Finished young gen rescan work in 0th thread: 0.693 sec
> Finished remaining root rescan work in 0th thread: 0.000 sec
> Finished dirty card rescan work in 0th thread: 0.000 sec
> Finished work stealing in 0th thread: 0.000 sec
> Finished work stealing in 5th thread: 0.693 sec
> Finished work stealing in 4th thread: 0.693 sec
> Finished work stealing in 3th thread: 0.693 sec
> Finished work stealing in 6th thread: 0.693 sec
> Finished work stealing in 9th thread: 0.692 sec
> Finished work stealing in 8th thread: 0.693 sec
> Finished work stealing in 2th thread: 0.693 sec
> Finished work stealing in 10th thread: 0.693 sec
> Finished work stealing in 11th thread: 0.693 sec
> Finished work stealing in 1th thread: 0.693 sec
> Finished work stealing in 7th thread: 0.693 sec
> , 0.6939810 secs]32326.334: [weak refs processing, 0.0005890 secs] [1 CMS-remark: 509730K(1048576K)] 1142381K(2097088K), 0.6948430 secs] [Times: user=7.85 sys=0.00, real=0.70 secs]
> 2014-04-29T01:18:18.483-0600: 32326.336: [CMS-concurrent-sweep-start]
> 2014-04-29T01:18:18.825-0600: 32326.678: [CMS-concurrent-sweep: 0.339/0.342 secs] (CMS-concurrent-sweep yielded 4 times)
> [Times: user=0.44 sys=0.00, real=0.34 secs]
> 2014-04-29T01:18:18.825-0600: 32326.678: [CMS-concurrent-reset-start]
> 2014-04-29T01:18:18.828-0600: 32326.680: [CMS-concurrent-reset: 0.002/0.002 secs] (CMS-concurrent-reset yielded 0 times)
> [Times: user=0.00 sys=0.00, real=0.00 secs]
> CMSCollector shouldConcurrentCollect: 32328.055
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@synapse.apache.org
For additional commands, e-mail: dev-help@synapse.apache.org