Skip to content

Commit 11a1917

Browse files
ycombinatorycombinator
authored
Fixes parsing of GC entries in elasticsearch server log (elastic#9603)
Resolves elastic#9513. This PR: * removes the incorrectly-parsed `gc_overhead` field. Turns out what we were parsing was actually an insignificant sequential number, not GC overhead, * parses out a new `gc.collection_duration` field, e.g. `1.2s`, which is the time spent performing GC, and * parses out a new `gc.observation_duration` field, e.g. `1.8s`, which is the overall time over which GC collection was performed It also splits up the long grok expression in the ingest pipeline into smaller patterns and references those patterns, hopefully for easier readability.
1 parent eae3bff commit 11a1917

File tree

5 files changed

+72
-11
lines changed

5 files changed

+72
-11
lines changed

Diff for: ‎filebeat/docs/fields.asciidoc

+24-2
Original file line numberDiff line numberDiff line change
@@ -4239,14 +4239,36 @@ example:
42394239
42404240
--
42414241
4242-
*`elasticsearch.server.gc_overhead`*::
4242+
*`elasticsearch.server.gc.overhead_seq`*::
42434243
+
42444244
--
42454245
type: long
42464246
4247-
example:
4247+
example: 3449992
4248+
4249+
Sequence number
4250+
4251+
--
4252+
4253+
*`elasticsearch.server.gc.collection_duration.ms`*::
4254+
+
4255+
--
4256+
type: float
4257+
4258+
example: 1600
4259+
4260+
Time spent in GC, in milliseconds
4261+
4262+
--
4263+
4264+
*`elasticsearch.server.gc.observation_duration.ms`*::
4265+
+
4266+
--
4267+
type: float
42484268
4269+
example: 1800
42494270
4271+
Total time over which collection was observed, in milliseconds
42504272
42514273
--
42524274

Diff for: ‎filebeat/module/elasticsearch/fields.go

+1-1
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

Diff for: ‎filebeat/module/elasticsearch/server/_meta/fields.yml

+12-4
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,15 @@
2323
description: ""
2424
example: ""
2525
type: long
26-
- name: gc_overhead
27-
description: ""
28-
example: ""
29-
type: long
26+
- name: overhead_seq
27+
description: "Sequence number"
28+
example: 3449992
29+
type: long
30+
- name: collection_duration.ms
31+
description: "Time spent in GC, in milliseconds"
32+
example: 1600
33+
type: float
34+
- name: observation_duration.ms
35+
description: "Total time over which collection was observed, in milliseconds"
36+
example: 1800
37+
type: float

Diff for: ‎filebeat/module/elasticsearch/server/ingest/pipeline.json

+31-2
Original file line numberDiff line numberDiff line change
@@ -20,13 +20,42 @@
2020
"field": "message",
2121
"pattern_definitions": {
2222
"GREEDYMULTILINE": "(.|\n)*",
23-
"INDEXNAME": "[a-zA-Z0-9_.-]*"
23+
"INDEXNAME": "[a-zA-Z0-9_.-]*",
24+
"GC_ALL": "\\[gc\\]\\[%{NUMBER:elasticsearch.server.gc.overhead_seq}\\] overhead, spent \\[%{NUMBER:elasticsearch.server.gc.collection_duration.time:float}%{DATA:elasticsearch.server.gc.collection_duration.unit}\\] collecting in the last \\[%{NUMBER:elasticsearch.server.gc.observation_duration.time:float}%{DATA:elasticsearch.server.gc.observation_duration.unit}\\]",
25+
"GC_YOUNG": "\\[gc\\]\\[young\\]\\[%{NUMBER:elasticsearch.server.gc.young.one}\\]\\[%{NUMBER:elasticsearch.server.gc.young.two}\\]%{SPACE}%{GREEDYMULTILINE:message}",
26+
"LOG_HEADER": "\\[%{TIMESTAMP_ISO8601:elasticsearch.server.timestamp}\\]\\[%{LOGLEVEL:log.level}%{SPACE}?\\]\\[%{DATA:elasticsearch.server.component}%{SPACE}\\](%{SPACE})?(\\[%{DATA:elasticsearch.node.name}\\])?(%{SPACE})?"
2427
},
2528
"patterns": [
26-
"\\[%{TIMESTAMP_ISO8601:elasticsearch.server.timestamp}\\]\\[%{LOGLEVEL:log.level}%{SPACE}?\\]\\[%{DATA:elasticsearch.server.component}%{SPACE}\\](%{SPACE})?(\\[%{DATA:elasticsearch.node.name}\\])?(%{SPACE})?(\\[gc\\](\\[young\\]\\[%{NUMBER:elasticsearch.server.gc.young.one}\\]\\[%{NUMBER:elasticsearch.server.gc.young.two}\\]|\\[%{NUMBER:elasticsearch.server.gc_overhead}\\]))?%{SPACE}((\\[%{INDEXNAME:elasticsearch.index.name}\\]|\\[%{INDEXNAME:elasticsearch.index.name}\\/%{DATA:elasticsearch.index.id}\\]))?%{SPACE}%{GREEDYMULTILINE:message}"
29+
"%{LOG_HEADER}%{GC_ALL}",
30+
"%{LOG_HEADER}%{GC_YOUNG}",
31+
"%{LOG_HEADER}%{SPACE}((\\[%{INDEXNAME:elasticsearch.index.name}\\]|\\[%{INDEXNAME:elasticsearch.index.name}\\/%{DATA:elasticsearch.index.id}\\]))?%{SPACE}%{GREEDYMULTILINE:message}"
2732
]
2833
}
2934
},
35+
{
36+
"script": {
37+
"lang": "painless",
38+
"source": "if (ctx.elasticsearch.server.gc != null && ctx.elasticsearch.server.gc.observation_duration != null) { if (ctx.elasticsearch.server.gc.observation_duration.unit == params.seconds_unit) { ctx.elasticsearch.server.gc.observation_duration.ms = ctx.elasticsearch.server.gc.observation_duration.time * params.ms_in_one_s;}if (ctx.elasticsearch.server.gc.observation_duration.unit == params.milliseconds_unit) { ctx.elasticsearch.server.gc.observation_duration.ms = ctx.elasticsearch.server.gc.observation_duration.time; } if (ctx.elasticsearch.server.gc.observation_duration.unit == params.minutes_unit) { ctx.elasticsearch.server.gc.observation_duration.ms = ctx.elasticsearch.server.gc.observation_duration.time * params.ms_in_one_m; }} if (ctx.elasticsearch.server.gc != null && ctx.elasticsearch.server.gc.collection_duration != null) { if (ctx.elasticsearch.server.gc.collection_duration.unit == params.seconds_unit) { ctx.elasticsearch.server.gc.collection_duration.ms = ctx.elasticsearch.server.gc.collection_duration.time * params.ms_in_one_s;} if (ctx.elasticsearch.server.gc.collection_duration.unit == params.milliseconds_unit) {ctx.elasticsearch.server.gc.collection_duration.ms = ctx.elasticsearch.server.gc.collection_duration.time; } if (ctx.elasticsearch.server.gc.collection_duration.unit == params.minutes_unit) { ctx.elasticsearch.server.gc.collection_duration.ms = ctx.elasticsearch.server.gc.collection_duration.time * params.ms_in_one_m; }}",
39+
"params": {
40+
"minutes_unit": "m",
41+
"seconds_unit": "s",
42+
"milliseconds_unit": "ms",
43+
"ms_in_one_s": 1000,
44+
"ms_in_one_m": 60000
45+
}
46+
}
47+
},
48+
{
49+
"remove": {
50+
"field": [
51+
"elasticsearch.server.gc.collection_duration.time",
52+
"elasticsearch.server.gc.collection_duration.unit",
53+
"elasticsearch.server.gc.observation_duration.time",
54+
"elasticsearch.server.gc.observation_duration.unit"
55+
],
56+
"ignore_missing": true
57+
}
58+
},
3059
{
3160
"rename": {
3261
"field": "elasticsearch.server.timestamp",

Diff for: ‎filebeat/module/elasticsearch/server/test/test.log-expected.json

+4-2
Original file line numberDiff line numberDiff line change
@@ -212,13 +212,15 @@
212212
"@timestamp": "2018-07-03T11:45:45,604",
213213
"elasticsearch.node.name": "srvmulpvlsk252_md",
214214
"elasticsearch.server.component": "o.e.m.j.JvmGcMonitorService",
215-
"elasticsearch.server.gc_overhead": "3449992",
215+
"elasticsearch.server.gc.collection_duration.ms": 1600.0,
216+
"elasticsearch.server.gc.observation_duration.ms": 1800.0,
217+
"elasticsearch.server.gc.overhead_seq": "3449992",
216218
"event.dataset": "server",
217219
"event.module": "elasticsearch",
218220
"input.type": "log",
219221
"log.level": "WARN",
220222
"log.offset": 10205,
221-
"message": "overhead, spent [1.6s] collecting in the last [1.8s]",
223+
"message": "[2018-07-03T11:45:45,604][WARN ][o.e.m.j.JvmGcMonitorService] [srvmulpvlsk252_md] [gc][3449992] overhead, spent [1.6s] collecting in the last [1.8s]",
222224
"service.name": "elasticsearch"
223225
},
224226
{

0 commit comments

Comments
 (0)