GC processing seems not working well

[zhenyun]

GC output is incorrect; GC log has many "concurrent mode failure" pauses, but they are not captured in naarad output.

2015-02-13T18:12:03.758+0000: 81702.494: [GC (CMS Final Remark) [YG occupancy: 11081913 K (11324672 K)]81702.494: [Rescan (parallel) , 0.8135453 secs]81703.308: [weak refs processing, 0.0003257 secs]81703.308: [class unloading, 0.0504717 secs]81703.359: [scrub symbol table, 0.0050806 secs]81703.364: [scrub string table, 0.0008752 secs][1 CMS-remark: 7146785K(8388608K)] 18228698K(19713280K), 0.8785469 secs] [Times: user=14.59 sys=0.01, real=0.88 secs]
2015-02-13T18:12:04.637+0000: 81703.373: [CMS-concurrent-sweep-start]
2015-02-13T18:12:04.714+0000: 81703.450: [GC (Allocation Failure) 81703.450: [ParNew: 11324672K->11324672K(11324672K), 0.0000507 secs]81703.450: [CMS2015-02-13T18:12:10.419+0000: 81709.155: [CMS-concurrent-sweep: 5.780/5.782 secs] [Times: user=5.93 sys=0.01, real=5.78 secs]
 (concurrent mode failure): 7146755K->8388607K(8388608K), 35.6608929 secs] 18471427K->9339375K(19713280K), [Metaspace: 40532K->40494K(1085440K)], 35.6611210 secs] [Times: user=35.28 sys=0.41, real=35.65 secs]
2015-02-13T18:12:42.375+0000: 81741.111: [GC (CMS Initial Mark) [1 CMS-initial-mark: 8388607K(8388608K)] 14121740K(19713280K), 1.3262900 secs] [Times: user=6.34 sys=0.00, real=1.33 secs]
2015-02-13T18:12:43.702+0000: 81742.438: [CMS-concurrent-mark-start]
2015-02-13T18:12:46.527+0000: 81745.263: [Full GC (Allocation Failure) 81745.263: [CMS2015-02-13T18:12:47.568+0000: 81746.304: [CMS-concurrent-mark: 3.849/3.866 secs] [Times: user=23.71 sys=0.57, real=3.87 secs]
 (concurrent mode failure): 8388607K->8388607K(8388608K), 29.1086962 secs] 19699610K->8580380K(19713280K), [Metaspace: 40521K->40521K(1085440K)], 29.1088352 secs] [Times: user=32.76 sys=0.22, real=29.10 secs]
2015-02-13T18:13:17.636+0000: 81776.372: [GC (CMS Initial Mark) [1 CMS-initial-mark: 8388607K(8388608K)] 13683867K(19713280K), 0.5105597 secs] [Times: user=6.85 sys=0.00, real=0.51 secs]
2015-02-13T18:13:18.147+0000: 81776.883: [CMS-concurrent-mark-start]
2015-02-13T18:13:21.241+0000: 81779.977: [Full GC (Allocation Failure) 81779.977: [CMS2015-02-13T18:13:23.254+0000: 81781.990: [CMS-concurrent-mark: 5.069/5.107 secs] [Times: user=28.72 sys=1.20, real=5.11 secs]
 (concurrent mode failure): 8388607K->8388607K(8388608K), 30.5527795 secs] 19694023K->8660673K(19713280K), [Metaspace: 40562K->40562K(1085440K)], 30.5529365 secs] [Times: user=36.71 sys=0.72, real=30.55 secs]
2015-02-13T18:13:53.794+0000: 81812.531: [GC (CMS Initial Mark) [1 CMS-initial-mark: 8388607K(8388608K)] 12153202K(19713280K), 0.5623895 secs] [Times: user=4.87 sys=0.00, real=0.56 secs]
2015-02-13T18:13:54.358+0000: 81813.094: [CMS-concurrent-mark-start]
2015-02-13T18:13:57.045+0000: 81815.781: [CMS-concurrent-mark: 2.678/2.687 secs] [Times: user=15.86 sys=0.18, real=2.69 secs]
2015-02-13T18:13:57.045+0000: 81815.781: [CMS-concurrent-preclean-start]
2015-02-13T18:14:02.852+0000: 81821.588: [Full GC (Allocation Failure) 81821.588: [CMS2015-02-13T18:14:06.926+0000: 81825.662: [CMS-concurrent-preclean: 9.861/9.881 secs] [Times: user=16.74 sys=0.09, real=9.88 secs]
 (concurrent mode failure): 8388607K->8388607K(8388608K), 34.3839825 secs] 19710084K->9741195K(19713280K), [Metaspace: 40654K->40654K(1085440K)], 34.3841350 secs] [Times: user=34.38 sys=0.00, real=34.38 secs]
2015-02-13T18:14:39.236+0000: 81857.972: [GC (CMS Initial Mark) [1 CMS-initial-mark: 8388607K(8388608K)] 13104908K(19713280K), 2.0344740 secs] [Times: user=4.12 sys=0.00, real=2.03 secs]
2015-02-13T18:14:41.271+0000: 81860.007: [CMS-concurrent-mark-start]
2015-02-13T18:14:44.474+0000: 81863.210: [Full GC (Allocation Failure) 81863.211: [CMS2015-02-13T18:14:45.014+0000: 81863.751: [CMS-concurrent-mark: 3.730/3.743 secs] [Times: user=23.96 sys=0.50, real=3.74 secs]
 (concurrent mode failure): 8388607K->7914657K(8388608K), 26.4161784 secs] 19713277K->7914657K(19713280K), [Metaspace: 40661K->40661K(1085440K)], 26.4163346 secs] [Times: user=28.22 sys=0.16, real=26.42 secs]
2015-02-13T18:15:12.891+0000: 81891.627: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7914657K(8388608K)] 11342745K(19713280K), 0.1370962 secs] [Times: user=2.39 sys=0.00, real=0.13 secs]
2015-02-13T18:15:13.029+0000: 81891.765: [CMS-concurrent-mark-start]
2015-02-13T18:15:18.775+0000: 81897.511: [CMS-concurrent-mark: 5.742/5.746 secs] [Times: user=33.03 sys=0.51, real=5.75 secs]
2015-02-13T18:15:18.775+0000: 81897.511: [CMS-concurrent-preclean-start]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-preclean: 0.040/0.040 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]

[RiteshMaheshwari]

@zhenyun , can you add more details please? Sample log if possible with data/results. Also if there are multiple problems, please open multiple issues.

[RiteshMaheshwari]

Is this for JDK 8? Does naarad work fine for you with the log in examples/log/ directory?

[zhenyun]

it works with examples/log/gc.log, but that gc.log does not have some values, eg. Allocation failures.

[RiteshMaheshwari]

Once @alfh 's pull requests are merged, can you verify if this is still a problem? I think #300 should solve this.

[zhenyun]

I used this (shortened) gc.log:

Java HotSpot(TM) 64-Bit Server VM (25.5-b02) for linux-amd64 JRE (1.8.0_05-b13), built on Mar 18 2014 00:29:27 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 49358744k(37037576k free), swap 16776116k(16721768k free)
CommandLine flags: -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:+DisableExplicitGC -XX:ErrorFile=logs/hs_err.log -XX:InitialHeapSize=21474836480 -XX:+ManagementServer -XX:MaxHeapSize=21474836480 -XX:MaxNewSize=12884901888 -XX:MaxTenuringThreshold=7 -XX:NewSize=12884901888 -XX:OldPLABSize=16 -XX:-OmitStackTraceInFastThrow -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2015-02-12T19:30:29.397+0000: 8.133: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(8388608K)] 5033217K(19713280K), 0.1402922 secs] [Times: user=0.29 sys=0.01, real=0.14 secs] 
2015-02-12T19:30:29.537+0000: 8.274: [CMS-concurrent-mark-start]
2015-02-12T19:30:29.542+0000: 8.278: [CMS-concurrent-mark: 0.003/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2015-02-12T19:30:29.542+0000: 8.278: [CMS-concurrent-preclean-start]
2015-02-12T19:30:29.566+0000: 8.303: [CMS-concurrent-preclean: 0.025/0.025 secs] [Times: user=0.02 sys=0.00, real=0.03 secs] 
2015-02-12T19:30:29.567+0000: 8.303: [CMS-concurrent-abortable-preclean-start]
2015-02-13T20:04:13.851+0000: 88432.588: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7760968K(8388608K)] 10111450K(19713280K), 0.0047695 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
2015-02-13T20:04:13.857+0000: 88432.593: [CMS-concurrent-mark-start]
2015-02-13T20:04:20.152+0000: 88438.888: [GC (Allocation Failure) 88438.888: [ParNew: 10066432K->10066432K(11324672K), 0.0000382 secs]88438.888: [CMS2015-02-13T20:04:22.994+0000: 88441.730: [CMS-concurrent-mark: 9.129/9.137 secs] [Times: user=45.69 sys=1.93, real=9.13 secs] 
 (concurrent mode failure): 7760968K->7759276K(8388608K), 28.1546797 secs] 17827400K->7759276K(19713280K), [Metaspace: 40767K->40767K(1085440K)], 28.1548444 secs] [Times: user=36.69 sys=0.85, real=28.15 secs] 
2015-02-13T20:04:50.306+0000: 88469.043: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7759276K(8388608K)] 9934791K(19713280K), 0.0043384 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2015-02-13T20:04:50.312+0000: 88469.048: [CMS-concurrent-mark-start]
2015-02-13T20:04:56.703+0000: 88475.440: [CMS-concurrent-mark: 6.388/6.392 secs] [Times: user=36.28 sys=0.64, real=6.39 secs] 
2015-02-13T20:04:56.704+0000: 88475.440: [CMS-concurrent-preclean-start]
2015-02-13T20:04:56.728+0000: 88475.464: [CMS-concurrent-preclean: 0.024/0.024 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
2015-02-13T20:04:56.728+0000: 88475.464: [CMS-concurrent-abortable-preclean-start]
2015-02-13T20:04:56.728+0000: 88475.464: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2015-02-13T20:04:56.731+0000: 88475.467: [GC (CMS Final Remark) [YG occupancy: 9585948 K (11324672 K)]88475.467: [Rescan (parallel) , 0.0133397 secs]88475.480: [weak refs processing, 0.0000221 secs]88475.480: [class unloading, 0.0358057 secs]88475.516: [scrub symbol table, 0.0051398 secs]88475.521: [scrub string table, 0.0008886 secs][1 CMS-remark: 7759276K(8388608K)] 17345225K(19713280K), 0.0607099 secs] [Times: user=0.27 sys=0.00, real=0.06 secs] 
2015-02-13T20:04:56.792+0000: 88475.528: [CMS-concurrent-sweep-start]
2015-02-13T20:04:57.187+0000: 88475.923: [GC (Allocation Failure) 88475.923: [ParNew: 10059787K->10059787K(11324672K), 0.0000367 secs]88475.924: [CMS2015-02-13T20:05:03.016+0000: 88481.752: [CMS-concurrent-sweep: 6.223/6.224 secs] [Times: user=6.59 sys=0.00, real=6.22 secs] 
 (concurrent mode failure): 7759276K->7760392K(8388608K), 30.6648373 secs] 17819063K->7760392K(19713280K), [Metaspace: 40767K->40767K(1085440K)], 30.6651383 secs] [Times: user=30.66 sys=0.00, real=30.66 secs] 
2015-02-13T20:06:39.480+0000: 88578.216: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7761208K(8388608K)] 10032275K(19713280K), 0.0041592 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
2015-02-13T20:06:39.485+0000: 88578.221: [CMS-concurrent-mark-start]
2015-02-13T20:06:46.833+0000: 88585.569: [GC (Allocation Failure) 88585.569: [ParNew: 10045440K->10045440K(11324672K), 0.0000378 secs]88585.569: [CMS2015-02-13T20:06:48.042+0000: 88586.778: [CMS-concurrent-mark: 8.551/8.557 secs] [Times: user=45.26 sys=1.57, real=8.56 secs] 
 (concurrent mode failure): 7761208K->7761261K(8388608K), 25.9979675 secs] 17806649K->7761261K(19713280K), [Metaspace: 40767K->40767K(1085440K)], 25.9981273 secs] [Times: user=30.41 sys=0.18, real=26.00 secs] 
2015-02-13T20:07:14.834+0000: 88613.570: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7761261K(8388608K)] 10112754K(19713280K), 0.0055989 secs] [Times: user=0.07 sys=0.00, real=0.00 secs] 
2015-02-13T20:07:14.841+0000: 88613.577: [CMS-concurrent-mark-start]
2015-02-13T20:07:20.322+0000: 88619.058: [CMS-concurrent-mark: 5.478/5.482 secs] [Times: user=31.91 sys=0.29, real=5.49 secs] 
2015-02-13T20:07:20.322+0000: 88619.059: [CMS-concurrent-preclean-start]
2015-02-13T20:07:20.347+0000: 88619.083: [CMS-concurrent-preclean: 0.025/0.025 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2015-02-13T20:07:20.347+0000: 88619.083: [CMS-concurrent-abortable-preclean-start]
2015-02-13T20:07:20.347+0000: 88619.083: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2015-02-13T20:07:20.348+0000: 88619.084: [GC (CMS Final Remark) [YG occupancy: 8693236 K (11324672 K)]88619.085: [Rescan (parallel) , 0.0127622 secs]88619.097: [weak refs processing, 0.0000206 secs]88619.097: [class unloading, 0.0332977 secs]88619.131: [scrub symbol table, 0.0045887 secs]88619.135: [scrub string table, 0.0008302 secs][1 CMS-remark: 7761261K(8388608K)] 16454497K(19713280K), 0.0568197 secs] [Times: user=0.26 sys=0.00, real=0.06 secs] 
2015-02-13T20:07:20.406+0000: 88619.142: [CMS-concurrent-sweep-start]
2015-02-13T20:07:21.726+0000: 88620.462: [GC (Allocation Failure) 88620.462: [ParNew: 10050559K->10050559K(11324672K), 0.0000491 secs]88620.462: [CMS2015-02-13T20:07:26.642+0000: 88625.378: [CMS-concurrent-sweep: 6.234/6.236 secs] [Times: user=7.47 sys=0.01, real=6.23 secs] 
 (concurrent mode failure): 7761261K->7761306K(8388608K), 30.1364633 secs] 17811820K->7761306K(19713280K), [Metaspace: 40767K->40767K(1085440K)], 30.1368293 secs] [Times: user=30.12 sys=0.00, real=30.13 secs] 

In naarad output, the following pauses are not identified:
(1) "Allocation Failure" ; (2) "concurrent mode failure"; (3) "CMS Final Remark"

[richardhsu]

Concurrent mode failure seems to be coinciding with Allocation Failure in the format. So I think we should be covered.

#300 will add support for this and we've asked @alfh to update so that the regex is a wildcard for "GC (*)" so it looks like it'd catch your three examples.

[joyxiong]

The wildcard is to cover ParNew GC pause, not for the concurrent mode failure.
However his code do have logic to cover concurrent mode failure as well, so this issue is indeed covered.

From: Richard Hsu <[email protected]mailto:[email protected]>
Reply-To: linkedin/naarad <[email protected]mailto:[email protected]>
Date: Thursday, February 19, 2015 at 8:48 AM
To: linkedin/naarad <[email protected]mailto:[email protected]>
Subject: Re: [naarad] GC processing seems not working well (#311)

Concurrent mode failure seems to be coinciding with Allocation Failure in the format. So I think we should be covered.

#300#300 will add support for this and we've asked @alfhhttps://github.com/alfh to update so that the regex is a wildcard for "GC (*)" so it looks like it'd catch your three examples.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/311#issuecomment-75088759.

[feng-tao]

I saw there are four active pull requests from @alfh which may potentially fix this issue.