[ 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-unsubscr...@synapse.apache.org For additional commands, e-mail: dev-h...@synapse.apache.org