GC submetrics not reported
Closed this issue · 4 comments
Some submetrics (such as gen0 gen0t gen0usr gen0sys gen0real ) are not reported.
[GC-server]
infile=gc.log
sub_metrics=appstop alloc promo used0 used1 used commit0 commit1 commit gen0 gen0t gen0usr gen0sys gen0real cmsIM cmsRM cmsRS GCPause cmsCM cmsCP cmsCS cmsCR safept apptime used0AfterGC used1AfterGC usedAfterGC
2015-02-13T18:11:59.494+0000: 81698.230: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7146785K(8388608K)] 8430222K(19713280K), 0.1652645 secs] [Times: user=2.89 sys=0.00, real=0.16 secs]
2015-02-13T18:11:59.660+0000: 81698.396: [CMS-concurrent-mark-start]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-mark: 4.008/4.072 secs] [Times: user=28.57 sys=1.24, real=4.07 secs]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-preclean: 0.025/0.025 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
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]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2015-02-13T18:15:18.816+0000: 81897.552: [GC (CMS Final Remark) [YG occupancy: 10021269 K (11324672 K)]81897.552: [Rescan (parallel) , 0.1378718 secs]81897.690: [weak refs processing, 0.0000404 secs]81897.690: [class unloading, 0.0310806 secs]81897.721: [scrub symbol table, 0.0045451 secs]81897.726: [scrub string table, 0.0007730 secs][1 CMS-remark: 7914657K(8388608K)] 17935927K(19713280K), 0.1793485 secs] [Times: user=2.49 sys=0.00, real=0.18 secs]
2015-02-13T18:15:18.996+0000: 81897.732: [CMS-concurrent-sweep-start]
2015-02-13T18:15:19.038+0000: 81897.774: [GC (Allocation Failure) 81897.774: [ParNew: 10059140K->10059140K(11324672K), 0.0000485 secs]81897.774: [CMS2015-02-13T18:15:25.439+0000: 81904.175: [CMS-concurrent-sweep: 6.442/6.443 secs] [Times: user=6.49 sys=0.00, real=6.44 secs](concurrent mode failure): 7914636K->7755237K(8388608K), 31.4851701 secs] 17973777K->7755237K(19713280K), [Metaspace: 40670K->40670K(1085440K)], 31.4856191 secs] [Times: user=31.48 sys=0.00, real=31.48 secs]
2015-02-13T18:15:52.523+0000: 81931.260: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7755237K(8388608K)] 9775341K(19713280K), 0.0051375 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
2015-02-13T18:15:52.530+0000: 81931.266: [CMS-concurrent-mark-start]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-mark: 9.582/9.587 secs] [Times: user=43.52 sys=1.85, real=9.58 secs]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-preclean-start]
2015-02-13T18:16:02.143+0000: 81940.879: [CMS-concurrent-preclean: 0.026/0.026 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
The issue may be introduced by format change in the GC logs. For that, can you verify if naarad work for the GC log with the following param in Java process:
-XX:-PrintGCCause
From: zhenyun <notifications@github.commailto:notifications@github.com>
Reply-To: linkedin/naarad <reply@reply.github.commailto:reply@reply.github.com>
Date: Wednesday, February 18, 2015 at 1:52 PM
To: linkedin/naarad <naarad@noreply.github.commailto:naarad@noreply.github.com>
Subject: [naarad] GC submetrics not reported (#312)
Some submetrics (such as gen0 gen0t gen0usr gen0sys gen0real ) are not reported.
[GC-server]
infile=gc.log
sub_metrics=appstop alloc promo used0 used1 used commit0 commit1 commit gen0 gen0t gen0usr gen0sys gen0real cmsIM cmsRM cmsRS GCPause cmsCM cmsCP cmsCS cmsCR safept apptime used0AfterGC used1AfterGC usedAfterGC
2015-02-13T18:11:59.494+0000: 81698.230: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7146785K(8388608K)] 8430222K(19713280K), 0.1652645 secs] [Times: user=2.89 sys=0.00, real=0.16 secs]
2015-02-13T18:11:59.660+0000: 81698.396: [CMS-concurrent-mark-start]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-mark: 4.008/4.072 secs] [Times: user=28.57 sys=1.24, real=4.07 secs]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-preclean: 0.025/0.025 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2015-02-13T18:15:18.816+0000: 81897.552: [GC (CMS Final Remark) [YG occupancy: 10021269 K (11324672 K)]81897.552: [Rescan (parallel) , 0.1378718 secs]81897.690: [weak refs processing, 0.0000404 secs]81897.690: [class unloading, 0.0310806 secs]81897.721: [scrub symbol table, 0.0045451 secs]81897.726: [scrub string table, 0.0007730 secs][1 CMS-remark: 7914657K(8388608K)] 17935927K(19713280K), 0.1793485 secs] [Times: user=2.49 sys=0.00, real=0.18 secs]
2015-02-13T18:15:18.996+0000: 81897.732: [CMS-concurrent-sweep-start]
2015-02-13T18:15:19.038+0000: 81897.774: [GC (Allocation Failure) 81897.774: [ParNew: 10059140K->10059140K(11324672K), 0.0000485 secs]81897.774: [CMS2015-02-13T18:15:25.439+0000: 81904.175: [CMS-concurrent-sweep: 6.442/6.443 secs] Times: user=6.49 sys=0.00, real=6.44 secs<concurrent%20mode%20failure>: 7914636K->7755237K(8388608K), 31.4851701 secs] 17973777K->7755237K(19713280K), [Metaspace: 40670K->40670K(1085440K)], 31.4856191 secs] [Times: user=31.48 sys=0.00, real=31.48 secs]
2015-02-13T18:15:52.523+0000: 81931.260: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7755237K(8388608K)] 9775341K(19713280K), 0.0051375 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
2015-02-13T18:15:52.530+0000: 81931.266: [CMS-concurrent-mark-start]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-mark: 9.582/9.587 secs] [Times: user=43.52 sys=1.85, real=9.58 secs]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-preclean-start]
2015-02-13T18:16:02.143+0000: 81940.879: [CMS-concurrent-preclean: 0.026/0.026 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
—
Reply to this email directly or view it on GitHubhttps://github.com//issues/312.
It works with examples/log/gc.log (which does not have "allocation failure" lines).
Naarad should support the default logs (i.e., with GCcauses).
From: joyxiong [notifications@github.com]
Sent: Wednesday, February 18, 2015 3:16 PM
To: linkedin/naarad
Cc: Zhenyun Zhuang
Subject: Re: [naarad] GC submetrics not reported (#312)
The issue may be introduced by format change in the GC logs. For that, can you verify if naarad work for the GC log with the following param in Java process:
-XX:-PrintGCCause
From: zhenyun <notifications@github.commailto:notifications@github.com>
Reply-To: linkedin/naarad <reply@reply.github.commailto:reply@reply.github.com>
Date: Wednesday, February 18, 2015 at 1:52 PM
To: linkedin/naarad <naarad@noreply.github.commailto:naarad@noreply.github.com>
Subject: [naarad] GC submetrics not reported (#312)
Some submetrics (such as gen0 gen0t gen0usr gen0sys gen0real ) are not reported.
[GC-server]
infile=gc.log
sub_metrics=appstop alloc promo used0 used1 used commit0 commit1 commit gen0 gen0t gen0usr gen0sys gen0real cmsIM cmsRM cmsRS GCPause cmsCM cmsCP cmsCS cmsCR safept apptime used0AfterGC used1AfterGC usedAfterGC
2015-02-13T18:11:59.494+0000: 81698.230: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7146785K(8388608K)] 8430222K(19713280K), 0.1652645 secs] [Times: user=2.89 sys=0.00, real=0.16 secs]
2015-02-13T18:11:59.660+0000: 81698.396: [CMS-concurrent-mark-start]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-mark: 4.008/4.072 secs] [Times: user=28.57 sys=1.24, real=4.07 secs]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-preclean: 0.025/0.025 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2015-02-13T18:15:18.816+0000: 81897.552: [GC (CMS Final Remark) [YG occupancy: 10021269 K (11324672 K)]81897.552: [Rescan (parallel) , 0.1378718 secs]81897.690: [weak refs processing, 0.0000404 secs]81897.690: [class unloading, 0.0310806 secs]81897.721: [scrub symbol table, 0.0045451 secs]81897.726: [scrub string table, 0.0007730 secs][1 CMS-remark: 7914657K(8388608K)] 17935927K(19713280K), 0.1793485 secs] [Times: user=2.49 sys=0.00, real=0.18 secs]
2015-02-13T18:15:18.996+0000: 81897.732: [CMS-concurrent-sweep-start]
2015-02-13T18:15:19.038+0000: 81897.774: [GC (Allocation Failure) 81897.774: [ParNew: 10059140K->10059140K(11324672K), 0.0000485 secs]81897.774: [CMS2015-02-13T18:15:25.439+0000: 81904.175: [CMS-concurrent-sweep: 6.442/6.443 secs] Times: user=6.49 sys=0.00, real=6.44 secs<concurrent%20mode%20failure>: 7914636K->7755237K(8388608K), 31.4851701 secs] 17973777K->7755237K(19713280K), [Metaspace: 40670K->40670K(1085440K)], 31.4856191 secs] [Times: user=31.48 sys=0.00, real=31.48 secs]
2015-02-13T18:15:52.523+0000: 81931.260: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7755237K(8388608K)] 9775341K(19713280K), 0.0051375 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
2015-02-13T18:15:52.530+0000: 81931.266: [CMS-concurrent-mark-start]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-mark: 9.582/9.587 secs] [Times: user=43.52 sys=1.85, real=9.58 secs]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-preclean-start]
2015-02-13T18:16:02.143+0000: 81940.879: [CMS-concurrent-preclean: 0.026/0.026 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
�
Reply to this email directly or view it on GitHubhttps://github.com//issues/312.
�
Reply to this email directly or view it on GitHubhttps://github.com//issues/312#issuecomment-74969690.
In this particular case, different version of JDK has differing default. Having said that, naarad needs to support all the default.
As the issue is taken care of by the outstanding pull request, I will close this issue 312
From: zhenyun <notifications@github.commailto:notifications@github.com>
Reply-To: linkedin/naarad <reply@reply.github.commailto:reply@reply.github.com>
Date: Wednesday, February 18, 2015 at 3:39 PM
To: linkedin/naarad <naarad@noreply.github.commailto:naarad@noreply.github.com>
Cc: Chaoyue Xiong <cxiong@linkedin.commailto:cxiong@linkedin.com>
Subject: Re: [naarad] GC submetrics not reported (#312)
It works with examples/log/gc.log (which does not have "allocation failure" lines).
Naarad should support the default logs (i.e., with GCcauses).
From: joyxiong [notifications@github.commailto:notifications@github.com]
Sent: Wednesday, February 18, 2015 3:16 PM
To: linkedin/naarad
Cc: Zhenyun Zhuang
Subject: Re: [naarad] GC submetrics not reported (#312)
The issue may be introduced by format change in the GC logs. For that, can you verify if naarad work for the GC log with the following param in Java process:
-XX:-PrintGCCause
From: zhenyun <notifications@github.commailto:notifications@github.commailto:notifications@github.com>
Reply-To: linkedin/naarad <reply@reply.github.commailto:reply@reply.github.commailto:reply@reply.github.com>
Date: Wednesday, February 18, 2015 at 1:52 PM
To: linkedin/naarad <naarad@noreply.github.commailto:naarad@noreply.github.commailto:naarad@noreply.github.com>
Subject: [naarad] GC submetrics not reported (#312)
Some submetrics (such as gen0 gen0t gen0usr gen0sys gen0real ) are not reported.
[GC-server]
infile=gc.log
sub_metrics=appstop alloc promo used0 used1 used commit0 commit1 commit gen0 gen0t gen0usr gen0sys gen0real cmsIM cmsRM cmsRS GCPause cmsCM cmsCP cmsCS cmsCR safept apptime used0AfterGC used1AfterGC usedAfterGC
2015-02-13T18:11:59.494+0000: 81698.230: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7146785K(8388608K)] 8430222K(19713280K), 0.1652645 secs] [Times: user=2.89 sys=0.00, real=0.16 secs]
2015-02-13T18:11:59.660+0000: 81698.396: [CMS-concurrent-mark-start]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-mark: 4.008/4.072 secs] [Times: user=28.57 sys=1.24, real=4.07 secs]
2015-02-13T18:12:03.732+0000: 81702.468: [CMS-concurrent-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-preclean: 0.025/0.025 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:12:03.757+0000: 81702.493: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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%20mode%20failure>: 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]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean-start]
2015-02-13T18:15:18.815+0000: 81897.551: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2015-02-13T18:15:18.816+0000: 81897.552: [GC (CMS Final Remark) [YG occupancy: 10021269 K (11324672 K)]81897.552: [Rescan (parallel) , 0.1378718 secs]81897.690: [weak refs processing, 0.0000404 secs]81897.690: [class unloading, 0.0310806 secs]81897.721: [scrub symbol table, 0.0045451 secs]81897.726: [scrub string table, 0.0007730 secs][1 CMS-remark: 7914657K(8388608K)] 17935927K(19713280K), 0.1793485 secs] [Times: user=2.49 sys=0.00, real=0.18 secs]
2015-02-13T18:15:18.996+0000: 81897.732: [CMS-concurrent-sweep-start]
2015-02-13T18:15:19.038+0000: 81897.774: [GC (Allocation Failure) 81897.774: [ParNew: 10059140K->10059140K(11324672K), 0.0000485 secs]81897.774: [CMS2015-02-13T18:15:25.439+0000: 81904.175: [CMS-concurrent-sweep: 6.442/6.443 secs] Times: user=6.49 sys=0.00, real=6.44 secs<concurrent%20mode%20failure>: 7914636K->7755237K(8388608K), 31.4851701 secs] 17973777K->7755237K(19713280K), [Metaspace: 40670K->40670K(1085440K)], 31.4856191 secs] [Times: user=31.48 sys=0.00, real=31.48 secs]
2015-02-13T18:15:52.523+0000: 81931.260: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7755237K(8388608K)] 9775341K(19713280K), 0.0051375 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
2015-02-13T18:15:52.530+0000: 81931.266: [CMS-concurrent-mark-start]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-mark: 9.582/9.587 secs] [Times: user=43.52 sys=1.85, real=9.58 secs]
2015-02-13T18:16:02.117+0000: 81940.853: [CMS-concurrent-preclean-start]
2015-02-13T18:16:02.143+0000: 81940.879: [CMS-concurrent-preclean: 0.026/0.026 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
�
Reply to this email directly or view it on GitHubhttps://github.com//issues/312.
�
Reply to this email directly or view it on GitHubhttps://github.com//issues/312#issuecomment-74969690.
�
Reply to this email directly or view it on GitHubhttps://github.com//issues/312#issuecomment-74972809.
The issue is taken care of by the outstanding pull request