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.
ycombinator · Dec 27, 2018 · 11a1917 · 11a1917
1 parent eae3bff
commit 11a1917
Show file tree

Hide file tree

Showing 5 changed files with 72 additions and 11 deletions.
diff --git a/filebeat/docs/fields.asciidoc b/filebeat/docs/fields.asciidoc
@@ -4239,14 +4239,36 @@ example:
 
 --
 
-*`elasticsearch.server.gc_overhead`*::
+*`elasticsearch.server.gc.overhead_seq`*::
 +
 --
 type: long
 
-example: 
+example: 3449992
+
+Sequence number
+
+--
+
+*`elasticsearch.server.gc.collection_duration.ms`*::
++
+--
+type: float
+
+example: 1600
+
+Time spent in GC, in milliseconds
+
+--
+
+*`elasticsearch.server.gc.observation_duration.ms`*::
++
+--
+type: float
 
+example: 1800
 
+Total time over which collection was observed, in milliseconds
 
 --
 

diff --git a/filebeat/module/elasticsearch/fields.go b/filebeat/module/elasticsearch/fields.go
diff --git a/filebeat/module/elasticsearch/server/_meta/fields.yml b/filebeat/module/elasticsearch/server/_meta/fields.yml
@@ -23,7 +23,15 @@
         description: ""
         example: ""
         type: long
-  - name: gc_overhead
-    description: ""
-    example: ""
-    type: long
+    - name: overhead_seq
+      description: "Sequence number"
+      example: 3449992
+      type: long
+    - name: collection_duration.ms
+      description: "Time spent in GC, in milliseconds"
+      example: 1600
+      type: float
+    - name: observation_duration.ms
+      description: "Total time over which collection was observed, in milliseconds"
+      example: 1800
+      type: float
diff --git a/filebeat/module/elasticsearch/server/ingest/pipeline.json b/filebeat/module/elasticsearch/server/ingest/pipeline.json
@@ -20,13 +20,42 @@
                 "field": "message",
                 "pattern_definitions": {
                     "GREEDYMULTILINE": "(.|\n)*",
-                    "INDEXNAME": "[a-zA-Z0-9_.-]*"
+                    "INDEXNAME": "[a-zA-Z0-9_.-]*",
+                    "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}\\]",
+                    "GC_YOUNG": "\\[gc\\]\\[young\\]\\[%{NUMBER:elasticsearch.server.gc.young.one}\\]\\[%{NUMBER:elasticsearch.server.gc.young.two}\\]%{SPACE}%{GREEDYMULTILINE:message}",
+                    "LOG_HEADER": "\\[%{TIMESTAMP_ISO8601:elasticsearch.server.timestamp}\\]\\[%{LOGLEVEL:log.level}%{SPACE}?\\]\\[%{DATA:elasticsearch.server.component}%{SPACE}\\](%{SPACE})?(\\[%{DATA:elasticsearch.node.name}\\])?(%{SPACE})?"
                 },
                 "patterns": [
-                    "\\[%{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}"
+                    "%{LOG_HEADER}%{GC_ALL}",
+                    "%{LOG_HEADER}%{GC_YOUNG}",
+                    "%{LOG_HEADER}%{SPACE}((\\[%{INDEXNAME:elasticsearch.index.name}\\]|\\[%{INDEXNAME:elasticsearch.index.name}\\/%{DATA:elasticsearch.index.id}\\]))?%{SPACE}%{GREEDYMULTILINE:message}"
                 ]
             }
         },
+        {
+            "script": {
+                "lang": "painless",
+                "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; }}",
+                "params": {
+                    "minutes_unit": "m",
+                    "seconds_unit": "s",
+                    "milliseconds_unit": "ms",
+                    "ms_in_one_s": 1000,
+                    "ms_in_one_m": 60000
+                }
+            }
+        },
+        {
+            "remove": {
+                "field": [
+                    "elasticsearch.server.gc.collection_duration.time",
+                    "elasticsearch.server.gc.collection_duration.unit",
+                    "elasticsearch.server.gc.observation_duration.time",
+                    "elasticsearch.server.gc.observation_duration.unit"
+                ],
+                "ignore_missing": true
+            }
+        },
         {
             "rename": {
                 "field": "elasticsearch.server.timestamp",

diff --git a/filebeat/module/elasticsearch/server/test/test.log-expected.json b/filebeat/module/elasticsearch/server/test/test.log-expected.json
@@ -212,13 +212,15 @@
         "@timestamp": "2018-07-03T11:45:45,604", 
         "elasticsearch.node.name": "srvmulpvlsk252_md", 
         "elasticsearch.server.component": "o.e.m.j.JvmGcMonitorService", 
-        "elasticsearch.server.gc_overhead": "3449992", 
+        "elasticsearch.server.gc.collection_duration.ms": 1600.0, 
+        "elasticsearch.server.gc.observation_duration.ms": 1800.0, 
+        "elasticsearch.server.gc.overhead_seq": "3449992", 
         "event.dataset": "server", 
         "event.module": "elasticsearch", 
         "input.type": "log", 
         "log.level": "WARN", 
         "log.offset": 10205, 
-        "message": "overhead, spent [1.6s] collecting in the last [1.8s]", 
+        "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]", 
         "service.name": "elasticsearch"
     }, 
     {