strange gc log

BlueDavy Lin bluedavy at gmail.com
Mon Sep 6 02:26:09 PDT 2010


hi!

     can someone help to see the gc log,it seems very strange,I want
to know why cms gc executes so frequency and why full gc executes?

     the java startup args:
     -server -Xms4g -Xmx4g -XX:PermSize=256m -XX:MaxPermSize=256m
-Xmn2560m -XX:+UseCompressedOops -XX:SurvivorRatio=10
-XX:+UseConcMarkSweepGC  -XX:CMSMaxAbortablePrecleanTime=5000
-XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=80
-XX:+DisableExplicitGC

     os: linux 2.6.18 x86_64
     jdk: 1.6.0_21

     gc log:

     2010-09-05T14:16:01.836+0800: 684.499: [GC [1 CMS-initial-mark:
1242572K(1572864K)] 2479836K(3975872K), 0.0197940 secs] [Times:
user=0.02 sys=0.00, real=0.03 secs]
2010-09-05T14:16:01.856+0800: 684.519: [CMS-concurrent-mark-start]
2010-09-05T14:16:03.054+0800: 685.717: [CMS-concurrent-mark:
1.188/1.198 secs] [Times: user=3.11 sys=0.06, real=1.20 secs]
2010-09-05T14:16:03.054+0800: 685.717: [CMS-concurrent-preclean-start]
2010-09-05T14:16:03.067+0800: 685.730: [CMS-concurrent-preclean:
0.011/0.013 secs] [Times: user=0.04 sys=0.01, real=0.01 secs]
2010-09-05T14:16:03.067+0800: 685.730: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2010-09-05T14:16:08.085+0800:
690.748: [CMS-concurrent-abortable-preclean: 4.728/5.017 secs] [Times:
user=12.12 sys=0.41, real=5.02 secs]
2010-09-05T14:16:08.094+0800: 690.757: [GC[YG occupancy: 2059988 K
(2403008 K)]690.757: [Rescan (parallel) , 0.5824240 secs]691.340:
[weak refs processing, 0.0000830 secs]691.340: [class unloading,
0.0142850 secs]691.354: [scrub symbol & string tables, 0.0107830 secs]
[1 CMS-remark: 1242572K(1572864K)] 3302560K(3975872K), 0.6142790 secs]
[Times: user=0.90 sys=0.00, real=0.61 secs]
2010-09-05T14:16:08.724+0800: 691.387: [CMS-concurrent-sweep-start]
2010-09-05T14:16:09.285+0800: 691.948: [CMS-concurrent-sweep:
0.537/0.561 secs] [Times: user=1.62 sys=0.07, real=0.57 secs]
2010-09-05T14:16:09.285+0800: 691.948: [CMS-concurrent-reset-start]
2010-09-05T14:16:09.289+0800: 691.952: [CMS-concurrent-reset:
0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
2010-09-05T14:16:09.686+0800: 692.349: [GC 692.349: [ParNew:
2249591K->2249591K(2403008K), 0.0000280 secs]692.349: [CMS:
1114272K->587057K(1572864K), 2.9468320 secs]
3363863K->1746311K(3975872K), [CMS Perm : 95684K->95670K(262144K)],
2.9472510 secs] [Times: user=2.95 sys=0.00, real=2.95 secs]
2010-09-05T14:16:12.633+0800: 695.296: [Full GC 695.296: [CMS:
587057K->585692K(1572864K), 2.6811650 secs]
1746311K->1744909K(3975872K), [CMS Perm : 95670K->94666K(262144K)],
2.6814300 secs] [Times: user=2.68 sys=0.00, real=2.68 secs]
2010-09-05T14:16:22.052+0800: 704.715: [GC 704.716: [ParNew:
2184576K->160953K(2403008K), 0.1662390 secs]
2770268K->746646K(3975872K), 0.1667690 secs] [Times: user=0.64
sys=0.00, real=0.17 secs]
2010-09-05T14:16:35.833+0800: 718.496: [GC 718.496: [ParNew:
2345529K->116941K(2403008K), 0.1740300 secs]
2931222K->1323305K(3975872K), 0.1744060 secs] [Times: user=0.34
sys=0.00, real=0.18 secs]
2010-09-05T14:16:36.026+0800: 718.689: [GC [1 CMS-initial-mark:
1206364K(1572864K)] 1336022K(3975872K), 0.0104660 secs] [Times:
user=0.01 sys=0.00, real=0.01 secs]
2010-09-05T14:16:36.037+0800: 718.700: [CMS-concurrent-mark-start]
2010-09-05T14:16:37.310+0800: 719.973: [CMS-concurrent-mark:
1.256/1.273 secs] [Times: user=2.83 sys=0.03, real=1.27 secs]
2010-09-05T14:16:37.310+0800: 719.973: [CMS-concurrent-preclean-start]
2010-09-05T14:16:37.323+0800: 719.987: [CMS-concurrent-preclean:
0.011/0.013 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2010-09-05T14:16:37.324+0800: 719.987: [CMS-concurrent-abortable-preclean-start]
2010-09-05T14:16:38.886+0800: 721.549:
[CMS-concurrent-abortable-preclean: 0.591/1.563 secs] [Times:
user=2.49 sys=0.03, real=1.57 secs]
2010-09-05T14:16:39.276+0800: 721.939: [GC[YG occupancy: 1417682 K
(2403008 K)]721.939: [Rescan (parallel) , 0.0897100 secs]722.029:
[weak refs processing, 0.0034310 secs]722.032: [class unloading,
0.0287520 secs]722.061: [scrub symbol & string tables, 0.0106100 secs]
[1 CMS-remark: 1206364K(1572864K)] 2624046K(3975872K), 0.1391780 secs]
[Times: user=0.29 sys=0.00, real=0.14 secs]
2010-09-05T14:16:39.415+0800: 722.078: [CMS-concurrent-sweep-start]
2010-09-05T14:16:39.876+0800: 722.539: [CMS-concurrent-sweep:
0.460/0.460 secs] [Times: user=1.27 sys=0.06, real=0.46 secs]
2010-09-05T14:16:39.876+0800: 722.539: [CMS-concurrent-reset-start]
2010-09-05T14:16:39.880+0800: 722.543: [CMS-concurrent-reset:
0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2010-09-05T14:16:40.463+0800: 723.126: [GC [1 CMS-initial-mark:
1184963K(1572864K)] 2729912K(3975872K), 0.3193890 secs] [Times:
user=0.32 sys=0.00, real=0.32 secs]
2010-09-05T14:16:40.782+0800: 723.446: [CMS-concurrent-mark-start]
2010-09-05T14:16:41.949+0800: 724.612: [CMS-concurrent-mark:
1.167/1.167 secs] [Times: user=2.84 sys=0.12, real=1.17 secs]
2010-09-05T14:16:41.949+0800: 724.612: [CMS-concurrent-preclean-start]
2010-09-05T14:16:41.965+0800: 724.628: [CMS-concurrent-preclean:
0.013/0.016 secs] [Times: user=0.02 sys=0.01, real=0.02 secs]
2010-09-05T14:16:41.965+0800: 724.628: [CMS-concurrent-abortable-preclean-start]
2010-09-05T14:16:46.912+0800: 729.575: [GC 729.575: [ParNew:
2101741K->2101741K(2403008K), 0.0000280 secs]729.575:
[CMS2010-09-05T14:16:46.913+0800: 729.577:
[CMS-concurrent-abortable-preclean: 2.175/4.948 secs] [Times:
user=8.40 sys=0.20, real=4.94 secs]
 (concurrent mode failure): 1184963K->648104K(1572864K), 3.2280790
secs] 3286704K->1752744K(3975872K), [CMS Perm :
95838K->95825K(262144K)], 3.2284640 secs] [Times: user=3.23 sys=0.00,
real=3.23 secs]
2010-09-05T14:16:50.140+0800: 732.803: [Full GC 732.803: [CMS:
648104K->646954K(1572864K), 2.2277720 secs]
1752744K->1751573K(3975872K), [CMS Perm : 95825K->94698K(262144K)],
2.2280240 secs] [Times: user=2.22 sys=0.01, real=2.22 secs]
2010-09-05T14:16:52.456+0800: 735.119: [GC [1 CMS-initial-mark:
646954K(1572864K)] 1848970K(3975872K), 0.0460980 secs] [Times:
user=0.04 sys=0.00, real=0.04 secs]
2010-09-05T14:16:52.503+0800: 735.166: [CMS-concurrent-mark-start]
2010-09-05T14:16:54.948+0800: 737.611: [CMS-concurrent-mark:
1.927/2.444 secs] [Times: user=6.68 sys=0.88, real=2.45 secs]
2010-09-05T14:16:54.948+0800: 737.611: [CMS-concurrent-preclean-start]
2010-09-05T14:16:55.346+0800: 738.009: [GC 738.009: [ParNew:
2127836K->218432K(2403008K), 0.1695320 secs]
2774791K->865770K(3975872K), 0.1701180 secs] [Times: user=0.65
sys=0.00, real=0.16 secs]
2010-09-05T14:16:56.149+0800: 738.812: [CMS-concurrent-preclean:
1.014/1.202 secs] [Times: user=2.97 sys=0.05, real=1.20 secs]
2010-09-05T14:16:56.150+0800: 738.813: [CMS-concurrent-abortable-preclean-start]
2010-09-05T14:16:59.504+0800: 742.167:
[CMS-concurrent-abortable-preclean: 2.722/3.354 secs] [Times:
user=7.02 sys=0.08, real=3.35 secs]
2010-09-05T14:16:59.509+0800: 742.172: [GC[YG occupancy: 1311433 K
(2403008 K)]742.173: [Rescan (parallel) , 0.0650310 secs]742.238:
[weak refs processing, 0.0000140 secs]742.238: [class unloading,
0.0146320 secs]742.252: [scrub symbol & string tables, 0.0109040 secs]
[1 CMS-remark: 647338K(1572864K)] 1958771K(3975872K), 0.0973620 secs]
[Times: user=0.27 sys=0.00, real=0.10 secs]
2010-09-05T14:16:59.608+0800: 742.271: [CMS-concurrent-sweep-start]
2010-09-05T14:17:00.061+0800: 742.724: [CMS-concurrent-sweep:
0.453/0.453 secs] [Times: user=1.13 sys=0.03, real=0.45 secs]
2010-09-05T14:17:00.061+0800: 742.724: [CMS-concurrent-reset-start]
2010-09-05T14:17:00.065+0800: 742.728: [CMS-concurrent-reset:
0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2010-09-05T14:17:00.948+0800: 743.611: [GC 743.612: [ParNew:
1462330K->52761K(2403008K), 0.1786850 secs]
2090139K->1255261K(3975872K), 0.1791020 secs] [Times: user=0.43
sys=0.00, real=0.18 secs]
2010-09-05T14:17:01.325+0800: 743.989: [GC [1 CMS-initial-mark:
1202500K(1572864K)] 2304040K(3975872K), 0.0081610 secs] [Times:
user=0.01 sys=0.00, real=0.01 secs]
2010-09-05T14:17:01.334+0800: 743.997: [CMS-concurrent-mark-start]
2010-09-05T14:17:02.514+0800: 745.177: [CMS-concurrent-mark:
1.162/1.180 secs] [Times: user=2.82 sys=0.06, real=1.18 secs]
2010-09-05T14:17:02.514+0800: 745.177: [CMS-concurrent-preclean-start]
2010-09-05T14:17:02.528+0800: 745.191: [CMS-concurrent-preclean:
0.012/0.014 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
2010-09-05T14:17:02.528+0800: 745.191: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2010-09-05T14:17:07.576+0800:
750.239: [CMS-concurrent-abortable-preclean: 2.221/5.047 secs] [Times:
user=9.10 sys=0.30, real=5.05 secs]
2010-09-05T14:17:07.602+0800: 750.265: [GC[YG occupancy: 1713121 K
(2403008 K)]750.265: [Rescan (parallel) , 0.4983770 secs]750.763:
[weak refs processing, 0.0000300 secs]750.763: [class unloading,
0.0316270 secs]750.795: [scrub symbol & string tables, 0.0106300 secs]
[1 CMS-remark: 1202500K(1572864K)] 2915621K(3975872K), 0.5473800 secs]
[Times: user=0.84 sys=0.00, real=0.55 secs]
2010-09-05T14:17:08.150+0800: 750.813: [CMS-concurrent-sweep-start]
2010-09-05T14:17:08.613+0800: 751.276: [CMS-concurrent-sweep:
0.463/0.463 secs] [Times: user=1.07 sys=0.06, real=0.47 secs]
2010-09-05T14:17:08.613+0800: 751.276: [CMS-concurrent-reset-start]
2010-09-05T14:17:08.617+0800: 751.280: [CMS-concurrent-reset:
0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2010-09-05T14:17:08.964+0800: 751.627: [GC 751.627: [ParNew:
1791951K->1791951K(2403008K), 0.0000280 secs]751.627: [CMS:
1187947K->650228K(1572864K), 2.6818560 secs]
2979898K->1752988K(3975872K), [CMS Perm : 96066K->96052K(262144K)],
2.6823340 secs] [Times: user=2.68 sys=0.00, real=2.68 secs]
2010-09-05T14:17:11.647+0800: 754.310: [Full GC 754.310: [CMS:
650228K->648975K(1572864K), 2.2741560 secs]
1752988K->1751698K(3975872K), [CMS Perm : 96052K->94725K(262144K)],
2.2744930 secs] [Times: user=2.28 sys=0.00, real=2.27 secs]
2010-09-05T14:17:13.931+0800: 756.594: [GC [1 CMS-initial-mark:
648975K(1572864K)] 1752021K(3975872K), 0.0096910 secs] [Times:
user=0.02 sys=0.00, real=0.01 secs]
2010-09-05T14:17:13.941+0800: 756.604: [CMS-concurrent-mark-start]
2010-09-05T14:17:16.221+0800: 758.884: [CMS-concurrent-mark:
1.747/2.279 secs] [Times: user=4.71 sys=0.97, real=2.28 secs]
2010-09-05T14:17:16.221+0800: 758.884: [CMS-concurrent-preclean-start]
2010-09-05T14:17:17.333+0800: 759.996: [CMS-concurrent-preclean:
1.094/1.112 secs] [Times: user=1.48 sys=0.03, real=1.12 secs]
2010-09-05T14:17:17.333+0800: 759.996: [CMS-concurrent-abortable-preclean-start]
2010-09-05T14:17:21.890+0800: 764.553: [GC 764.553: [ParNew (promotion
failed): 2184576K->2295598K(2403008K), 0.4990260 secs]765.052: [CMS
CMS: abort preclean due to time 2010-09-05T14:17:23.477+0800: 766.140:
[CMS-concurrent-abortable-preclean: 2.000/6.144 secs] [Times:
user=4.47 sys=0.21, real=6.14 secs]
 (concurrent mode failure): 648978K->709070K(1572864K), 4.0372860
secs] 2833551K->709070K(3975872K), [CMS Perm :
96317K->95399K(262144K)], 4.5369600 secs] [Times: user=4.99 sys=0.00,
real=4.54 secs]
2010-09-05T14:17:48.656+0800: 791.319: [GC 791.320: [ParNew:
2184563K->147456K(2403008K), 0.0281760 secs]
2893633K->856526K(3975872K), 0.0287130 secs] [Times: user=0.09
sys=0.00, real=0.03 secs]
2010-09-05T14:18:14.627+0800: 817.290: [GC 817.290: [ParNew:
2332032K->152747K(2403008K), 0.0383970 secs]
3041102K->861817K(3975872K), 0.0387980 secs] [Times: user=0.08
sys=0.00, real=0.04 secs]

-- 
=============================
|     BlueDavy                                      |
|     OSGi China User Group Director    |
|     http://china.osgiusers.org               |
|     http://www.bluedavy.com     |
=============================


More information about the hotspot-gc-dev mailing list