strange gc log

[Y. S. Ramakrishna]

Do you have a longer/more complete GC log, or is
this all of the log you have?

It is possible that you have some rather large objects that
survive for a short while and then die. This seems to be fragmenting
the old generation quite considerably. Did you try to use a heap
say twice as large to see if the behaviour is any better?

Running with -XX:PrintFLSStatistics=1 -XX:PrintCMSStatistics=1 -XX:+PrintHeapAtGC
might provide a bit more information.
(PS: can you send the log file as an attachment, so that your
editor does not insert line-breaks into the log file?)

-- ramki

On 09/06/10 02:26, BlueDavy Lin wrote:
> 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]
>