We were trying to tune the Sun JVM Garbage Collector of our WebLogic Server v. 10.3.2 when the server stopped for over one hour. It was lunch time so we did not kill the process. After 4012 seconds it came back. For your information, the server was a development instance with a 512 MB JVM on Solaris 9.
Here is the log message (wrapped for readability):
2012-01-10T12:48:31.227+0100:
10361.371: [GC[YG occupancy: 23095 K (29504 K)]
10361.371: [Rescan (parallel) , 4012.3452758 secs]
14373.717: [weak refs processing, 0.0006401 secs]
14373.717: [class unloading, 0.0815919 secs]
14373.799: [scrub symbol & string tables, 0.1392282 secs]
[1 CMS-remark: 416411K(491520K)] 439506K(521024K), 4012.6147003 secs]
[Times: user=3959.56 sys=5.79, real=4012.61 secs]
The WLS was using JDK 1.6.0_14 and was started with the following flags:
-Xms512m -Xmx512m -XX:MaxPermSize=256m -XX:+CMSClassUnloadingEnabled -XX:+CMSIncrementalMode -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:+UseAdaptiveGCBoundary -XX:+UseCMSCompactAtFullCollection -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseMPSS -XX:NewRatio=3 -verbose:gc -Xloggc:./logs/gc.log.<pid> -XX:+PrintCommandLineFlags -XX:-PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution
When the GC pause occurred, we were stressing the server for nearly 3 hours with 400 threads using Apache JMeter.
The symptoms seemed to be due to a failing remark of the CMS.
Note that -XX:+CMSPermGenSweepingEnabled was missing from the settings.
Here is a small part of the log starting about one minute before the event.
2012-01-10T12:47:29.083+0100: 10299.227: [GC 10299.228: [ParNew (promotion failed) Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2029960 bytes, 2029960 total : 29378K->28552K(29504K), 0.2164622 secs]10299.444: [CMSbailing out to foreground collection 2012-01-10T12:47:30.813+0100: 10300.957: [CMS-concurrent-mark: 56.302/79.626 secs] [Times: user=97.13 sys=5.50, real=79.63 secs] (concurrent mode failure): 488360K->390201K(491520K), 14.6267834 secs] 517169K->390201K(521024K), [CMS Perm : 137819K->137819K(229768K)] icms_dc=100 , 14.8440513 secs] [Times: user=14.50 sys=0.06, real=14.84 secs] 2012-01-10T12:47:43.950+0100: 10314.094: [GC [1 CMS-initial-mark: 390201K(491520K)] 390226K(521024K), 0.0210868 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 2012-01-10T12:47:43.971+0100: 10314.116: [CMS-concurrent-mark-start] 2012-01-10T12:47:44.895+0100: 10315.039: [GC 10315.040: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1421632 bytes, 1421632 total : 26240K->1542K(29504K), 0.0466250 secs] 416441K->391743K(521024K) icms_dc=100 , 0.0471847 secs] [Times: user=0.07 sys=0.01, real=0.05 secs] 2012-01-10T12:47:46.081+0100: 10316.226: [GC 10316.226: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2130848 bytes, 2130848 total - age 2: 621224 bytes, 2752072 total : 27782K->3264K(29504K), 0.0912163 secs] 417983K->394029K(521024K) icms_dc=100 , 0.0918158 secs] [Times: user=0.13 sys=0.00, real=0.09 secs] 2012-01-10T12:47:47.069+0100: 10317.214: [GC 10317.214: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1532704 bytes, 1532704 total : 29504K->2128K(29504K), 0.0645678 secs] 420269K->393945K(521024K) icms_dc=100 , 0.0652126 secs] [Times: user=0.10 sys=0.00, real=0.07 secs] 2012-01-10T12:47:48.216+0100: 10318.361: [GC 10318.361: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1998704 bytes, 1998704 total - age 2: 417832 bytes, 2416536 total : 28368K->3264K(29504K), 0.0936471 secs] 420185K->395543K(521024K) icms_dc=100 , 0.0943337 secs] [Times: user=0.13 sys=0.00, real=0.09 secs] 2012-01-10T12:47:49.362+0100: 10319.506: [GC 10319.507: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1745080 bytes, 1745080 total : 29504K->2317K(29504K), 0.0753500 secs] 421783K->396133K(521024K) icms_dc=100 , 0.0759595 secs] [Times: user=0.12 sys=0.01, real=0.08 secs] 2012-01-10T12:47:50.413+0100: 10320.557: [GC 10320.565: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1927192 bytes, 1927192 total : 28556K->2533K(29504K), 0.0767485 secs] 422373K->396871K(521024K) icms_dc=100 , 0.0774777 secs] [Times: user=0.10 sys=0.01, real=0.08 secs] 2012-01-10T12:47:51.542+0100: 10321.687: [GC 10321.687: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2387440 bytes, 2387440 total : 28773K->2897K(29504K), 0.0869769 secs] 423111K->397701K(521024K) icms_dc=100 , 0.0876438 secs] [Times: user=0.12 sys=0.00, real=0.09 secs] 2012-01-10T12:47:52.519+0100: 10322.664: [GC 10322.664: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1365472 bytes, 1365472 total : 29137K->1730K(29504K), 0.0605590 secs] 423941K->397207K(521024K) icms_dc=100 , 0.0612702 secs] [Times: user=0.09 sys=0.00, real=0.06 secs] 2012-01-10T12:47:53.507+0100: 10323.651: [GC 10323.652: [ParNew Desired survivor size 1671168 bytes, new threshold 2 (max 4) - age 1: 1586232 bytes, 1586232 total - age 2: 426512 bytes, 2012744 total : 27970K->2435K(29504K), 0.0606037 secs] 423447K->397912K(521024K) icms_dc=100 , 0.0614555 secs] [Times: user=0.08 sys=0.01, real=0.08 secs] 2012-01-10T12:47:54.678+0100: 10324.822: [GC 10324.823: [ParNew Desired survivor size 1671168 bytes, new threshold 2 (max 4) - age 1: 1614728 bytes, 1614728 total - age 2: 551112 bytes, 2165840 total : 28675K->3264K(29504K), 0.0772313 secs] 424152K->399491K(521024K) icms_dc=100 , 0.0778065 secs] [Times: user=0.11 sys=0.00, real=0.08 secs] 2012-01-10T12:47:55.890+0100: 10326.035: [GC 10326.035: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2183264 bytes, 2183264 total - age 2: 487184 bytes, 2670448 total : 29504K->2743K(29504K), 0.0720833 secs] 425731K->399306K(521024K) icms_dc=100 , 0.0727963 secs] [Times: user=0.11 sys=0.00, real=0.07 secs] 2012-01-10T12:47:56.928+0100: 10327.072: [GC 10327.072: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1707264 bytes, 1707264 total : 28983K->2247K(29504K), 0.0592782 secs] 425546K->399569K(521024K) icms_dc=100 , 0.0599055 secs] [Times: user=0.11 sys=0.00, real=0.06 secs] 2012-01-10T12:47:57.812+0100: 10327.957: [GC 10327.957: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1287016 bytes, 1287016 total : 28487K->1498K(29504K), 0.0632497 secs] 425809K->400115K(521024K) icms_dc=100 , 0.0638507 secs] [Times: user=0.11 sys=0.00, real=0.06 secs] 2012-01-10T12:47:58.914+0100: 10329.058: [GC 10329.058: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1969560 bytes, 1969560 total - age 2: 336096 bytes, 2305656 total : 27738K->2627K(29504K), 0.0887327 secs] 426355K->401244K(521024K) icms_dc=100 , 0.0894363 secs] [Times: user=0.09 sys=0.00, real=0.09 secs] 2012-01-10T12:47:59.989+0100: 10330.133: [GC 10330.134: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1856112 bytes, 1856112 total : 28867K->1984K(29504K), 0.0861588 secs] 427484K->401442K(521024K) icms_dc=100 , 0.0871543 secs] [Times: user=0.10 sys=0.01, real=0.09 secs] 2012-01-10T12:48:01.177+0100: 10331.322: [GC 10331.322: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1946880 bytes, 1946880 total : 28224K->2144K(29504K), 0.0640842 secs] 427682K->402110K(521024K) icms_dc=100 , 0.0647545 secs] [Times: user=0.09 sys=0.00, real=0.06 secs] 2012-01-10T12:48:02.222+0100: 10332.366: [GC 10332.367: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1781688 bytes, 1781688 total : 28384K->2002K(29504K), 0.1089648 secs] 428350K->402485K(521024K) icms_dc=100 , 0.1096323 secs] [Times: user=0.09 sys=0.00, real=0.11 secs] 2012-01-10T12:48:03.176+0100: 10333.321: [GC 10333.321: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1406760 bytes, 1406760 total : 28242K->1455K(29504K), 0.0612320 secs] 428725K->403160K(521024K) icms_dc=100 , 0.0619027 secs] [Times: user=0.11 sys=0.00, real=0.06 secs] 2012-01-10T12:48:04.255+0100: 10334.399: [GC 10334.399: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2337136 bytes, 2337136 total - age 2: 448960 bytes, 2786096 total : 27695K->3116K(29504K), 0.0763676 secs] 429400K->404821K(521024K) icms_dc=100 , 0.0769820 secs] [Times: user=0.14 sys=0.00, real=0.08 secs] 2012-01-10T12:48:05.349+0100: 10335.493: [GC 10335.494: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1813704 bytes, 1813704 total : 29356K->2142K(29504K), 0.0679328 secs] 431061K->404709K(521024K) icms_dc=100 , 0.0686002 secs] [Times: user=0.09 sys=0.00, real=0.07 secs] 2012-01-10T12:48:06.447+0100: 10336.591: [GC 10336.592: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2286920 bytes, 2286920 total : 28382K->2816K(29504K), 0.0969917 secs] 430949K->405794K(521024K) icms_dc=100 , 0.0976037 secs] [Times: user=0.12 sys=0.00, real=0.10 secs] 2012-01-10T12:48:07.441+0100: 10337.586: [GC 10337.586: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1861792 bytes, 1861792 total : 29056K->1915K(29504K), 0.0628323 secs] 432034K->405533K(521024K) icms_dc=100 , 0.0634190 secs] [Times: user=0.10 sys=0.00, real=0.06 secs] 2012-01-10T12:48:08.408+0100: 10338.552: [GC 10338.552: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1780984 bytes, 1780984 total : 28155K->2104K(29504K), 0.0572868 secs] 431773K->406220K(521024K) icms_dc=100 , 0.0578836 secs] [Times: user=0.10 sys=0.00, real=0.06 secs] 2012-01-10T12:48:09.393+0100: 10339.537: [GC 10339.538: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1548600 bytes, 1548600 total : 28344K->1770K(29504K), 0.0545423 secs] 432460K->406462K(521024K) icms_dc=100 , 0.0555288 secs] [Times: user=0.09 sys=0.00, real=0.06 secs] 2012-01-10T12:48:10.559+0100: 10340.703: [GC 10340.704: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2251864 bytes, 2251864 total - age 2: 741016 bytes, 2992880 total : 28010K->3263K(29504K), 0.0760876 secs] 432702K->408060K(521024K) icms_dc=100 , 0.0767605 secs] [Times: user=0.11 sys=0.00, real=0.08 secs] 2012-01-10T12:48:11.575+0100: 10341.719: [GC 10341.720: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1831480 bytes, 1831480 total : 29503K->2310K(29504K), 0.0698465 secs] 434300K->407967K(521024K) icms_dc=100 , 0.0704635 secs] [Times: user=0.10 sys=0.00, real=0.07 secs] 2012-01-10T12:48:12.798+0100: 10342.942: [GC 10342.942: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2394160 bytes, 2394160 total : 28550K->2848K(29504K), 0.0637657 secs] 434207K->408889K(521024K) icms_dc=100 , 0.0644630 secs] [Times: user=0.12 sys=0.00, real=0.06 secs] 2012-01-10T12:48:13.773+0100: 10343.917: [GC 10343.917: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1871360 bytes, 1871360 total : 29088K->2934K(29504K), 0.0775717 secs] 435129K->409328K(521024K) icms_dc=100 , 0.0782961 secs] [Times: user=0.13 sys=0.00, real=0.08 secs] 2012-01-10T12:48:14.643+0100: 10344.787: [GC 10344.787: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1026904 bytes, 1026904 total : 29174K->1682K(29504K), 0.0466279 secs] 435568K->408628K(521024K) icms_dc=100 , 0.0472251 secs] [Times: user=0.09 sys=0.00, real=0.05 secs] 2012-01-10T12:48:15.960+0100: 10346.104: [GC 10346.105: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2583256 bytes, 2583256 total - age 2: 587528 bytes, 3170784 total : 27922K->3264K(29504K), 0.0841241 secs] 434868K->410320K(521024K) icms_dc=100 , 0.0847487 secs] [Times: user=0.12 sys=0.00, real=0.08 secs] 2012-01-10T12:48:17.163+0100: 10347.307: [GC 10347.307: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2387728 bytes, 2387728 total : 29504K->2684K(29504K), 0.1115597 secs] 436560K->412403K(521024K) icms_dc=100 , 0.1122336 secs] [Times: user=0.16 sys=0.01, real=0.11 secs] 2012-01-10T12:48:18.075+0100: 10348.220: [GC 10348.220: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1640352 bytes, 1640352 total : 28924K->2238K(29504K), 0.0595880 secs] 438643K->412423K(521024K) icms_dc=100 , 0.0602538 secs] [Times: user=0.11 sys=0.00, real=0.06 secs] 2012-01-10T12:48:18.904+0100: 10349.048: [GC 10349.049: [ParNew Desired survivor size 1671168 bytes, new threshold 2 (max 4) - age 1: 1248592 bytes, 1248592 total - age 2: 426104 bytes, 1674696 total : 28478K->1956K(29504K), 0.0487952 secs] 438663K->412141K(521024K) icms_dc=100 , 0.0494058 secs] [Times: user=0.08 sys=0.00, real=0.05 secs] 2012-01-10T12:48:20.066+0100: 10350.210: [GC 10350.210: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1783136 bytes, 1783136 total - age 2: 424576 bytes, 2207712 total : 28196K->3263K(29504K), 0.0757208 secs] 438381K->414217K(521024K) icms_dc=100 , 0.0764049 secs] [Times: user=0.10 sys=0.00, real=0.08 secs] 2012-01-10T12:48:21.188+0100: 10351.332: [GC 10351.332: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2274888 bytes, 2274888 total : 29503K->2941K(29504K), 0.0766826 secs] 440457K->414741K(521024K) icms_dc=100 , 0.0773416 secs] [Times: user=0.13 sys=0.00, real=0.08 secs] 2012-01-10T12:48:21.869+0100: 10352.013: [CMS-concurrent-mark: 29.138/37.897 secs] [Times: user=48.30 sys=3.02, real=37.90 secs] 2012-01-10T12:48:21.869+0100: 10352.013: [CMS-concurrent-preclean-start] 2012-01-10T12:48:22.198+0100: 10352.342: [GC 10352.342: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1781272 bytes, 1781272 total : 29181K->1931K(29504K), 0.0595743 secs] 440981K->414271K(521024K) icms_dc=100 , 0.0601765 secs] [Times: user=0.10 sys=0.00, real=0.06 secs] 2012-01-10T12:48:23.243+0100: 10353.387: [GC 10353.387: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1658768 bytes, 1658768 total : 28171K->2402K(29504K), 0.1133229 secs] 440511K->415504K(521024K) icms_dc=100 , 0.1140012 secs] [Times: user=0.10 sys=0.00, real=0.11 secs] 2012-01-10T12:48:24.357+0100: 10354.501: [GC 10354.501: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1825648 bytes, 1825648 total - age 2: 611568 bytes, 2437216 total : 28642K->2696K(29504K), 0.0541984 secs] 441744K->415797K(521024K) icms_dc=100 , 0.0548543 secs] [Times: user=0.10 sys=0.00, real=0.05 secs] 2012-01-10T12:48:24.611+0100: 10354.755: [CMS-concurrent-preclean: 2.283/2.742 secs] [Times: user=3.49 sys=0.23, real=2.74 secs] 2012-01-10T12:48:24.611+0100: 10354.755: [CMS-concurrent-abortable-preclean-start] 2012-01-10T12:48:25.256+0100: 10355.400: [GC 10355.400: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1724624 bytes, 1724624 total : 28936K->2511K(29504K), 0.0795210 secs] 442037K->416432K(521024K) icms_dc=100 , 0.0801196 secs] [Times: user=0.12 sys=0.00, real=0.08 secs] 2012-01-10T12:48:26.229+0100: 10356.373: [GC 10356.374: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1840888 bytes, 1840888 total : 28751K->2308K(29504K), 0.1241761 secs] 442672K->416804K(521024K) icms_dc=100 , 0.1247967 secs] [Times: user=0.09 sys=0.01, real=0.12 secs] 2012-01-10T12:48:27.354+0100: 10357.498: [GC 10357.498: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2272456 bytes, 2272456 total : 28548K->3101K(29504K), 0.0742987 secs] 443044K->418129K(521024K) icms_dc=100 , 0.0749267 secs] [Times: user=0.12 sys=0.00, real=0.08 secs] 2012-01-10T12:48:28.311+0100: 10358.455: [GC 10358.456: [ParNew Desired survivor size 1671168 bytes, new threshold 4 (max 4) - age 1: 1625056 bytes, 1625056 total : 29341K->1773K(29504K), 0.0684923 secs] 444369K->417257K(521024K) icms_dc=100 , 0.0691360 secs] [Times: user=0.11 sys=0.00, real=0.07 secs] 2012-01-10T12:48:29.293+0100: 10359.437: [GC 10359.438: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1773160 bytes, 1773160 total - age 2: 661536 bytes, 2434696 total : 28013K->3132K(29504K), 0.1480543 secs] 443497K->418617K(521024K) icms_dc=100 , 0.1486734 secs] [Times: user=0.11 sys=0.00, real=0.15 secs] 2012-01-10T12:48:30.394+0100: 10360.537: [GC 10360.538: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 1711440 bytes, 1711440 total : 29372K->2342K(29504K), 0.1017757 secs] 444857K->418753K(521024K) icms_dc=100 , 0.1024336 secs] [Times: user=0.10 sys=0.01, real=0.10 secs] CMS: abort preclean due to time 2012-01-10T12:48:30.591+0100: 10360.735: [CMS-concurrent-abortable-preclean: 4.084/5.981 secs] [Times: user=7.55 sys=0.49, real=5.98 secs] 2012-01-10T12:48:31.227+0100: 10361.371: [GC[YG occupancy: 23095 K (29504 K)]10361.371: [Rescan (parallel) , 4012.3452758 secs]14373.717: [weak refs processing, 0.0006401 secs]14373.717: [class unloading, 0.0815919 secs]14373.799: [scrub symbol & string tables, 0.1392282 secs] [1 CMS-remark: 416411K(491520K)] 439506K(521024K), 4012.6147003 secs] [Times: user=3959.56 sys=5.79, real=4012.61 secs] 2012-01-10T13:55:23.902+0100: 14373.987: [CMS-concurrent-sweep-start] 2012-01-10T13:55:24.477+0100: 14374.562: [GC 14374.563: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2103760 bytes, 2103760 total : 28582K->2430K(29504K), 0.0725702 secs] 444941K->419250K(521024K) icms_dc=100 , 0.0730772 secs] [Times: user=0.13 sys=0.01, real=0.07 secs] 2012-01-10T13:55:27.340+0100: 14377.425: [GC 14377.425: [ParNew Desired survivor size 1671168 bytes, new threshold 1 (max 4) - age 1: 2870352 bytes, 2870352 total : 28670K->3263K(29504K), 0.1134823 secs] 444120K->420055K(521024K) icms_dc=100 , 0.1140602 secs] [Times: user=0.16 sys=0.00, real=0.11 secs] 2012-01-10T13:55:28.670+0100: 14378.755: [CMS-concurrent-sweep: 4.051/4.768 secs] [Times: user=5.12 sys=0.38, real=4.77 secs] 2012-01-10T13:55:28.678+0100: 14378.763: [CMS-concurrent-reset-start] 2012-01-10T13:55:28.695+0100: 14378.780: [CMS-concurrent-reset: 0.017/0.017 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
Some links about GC tuning:
- Tuning Java Garbage Collection (LinkedIn)
- Java HotSpot VM Options (Oracle)
- FAQ about Garbage Collection in the Hotspot Java Virtual Machine (Oracle)
- Concurrent Mark Sweep Collector Enhancements (Oracle)
- Tuning Garbage Collection Outline (summary or outline of Sun’s document: Tuning Garbage collection with the 1.4.2 Hotspot JVM)
Comments are closed.