synapse-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Hiranya Jayathilaka (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (SYNAPSE-987) CMS running for every 6 seconds
Date Fri, 19 Sep 2014 03:48:33 GMT

    [ https://issues.apache.org/jira/browse/SYNAPSE-987?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14139935#comment-14139935
] 

Hiranya Jayathilaka commented on SYNAPSE-987:
---------------------------------------------

Do you see any unhealthy increase in memory usage by Synapse over time? If the memory usage
is stable over time, there is probably nothing to worry about. Can you also point out the
exact lines in the log, that show the problematic behavior. I haven't seen these wrapper logs
before with GC information.

> 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


Mime
View raw message