From 11a19176a94ac9c9d6e555908088b895518ed535 Mon Sep 17 00:00:00 2001 From: Shaunak Kashyap Date: Thu, 27 Dec 2018 10:59:21 -0800 Subject: [PATCH] Fixes parsing of GC entries in elasticsearch server log (#9603) Resolves #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. --- filebeat/docs/fields.asciidoc | 26 +++++++++++++-- filebeat/module/elasticsearch/fields.go | 2 +- .../elasticsearch/server/_meta/fields.yml | 16 ++++++--- .../elasticsearch/server/ingest/pipeline.json | 33 +++++++++++++++++-- .../server/test/test.log-expected.json | 6 ++-- 5 files changed, 72 insertions(+), 11 deletions(-) diff --git a/filebeat/docs/fields.asciidoc b/filebeat/docs/fields.asciidoc index 7b3319a6f5f..80dc9719cda 100644 --- 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 index e8f9d4b2177..2d69d1872a0 100644 --- a/filebeat/module/elasticsearch/fields.go +++ b/filebeat/module/elasticsearch/fields.go @@ -31,5 +31,5 @@ func init() { // Asset returns asset data func Asset() string { - return "eJzUmltv2zj2wN/7KQ781AKJaidp/lM//IFZT5qm2LaZXDqYcQOBpo4l1hSpkpQd76DffUFSdmRZFzubdrt+iqRDnh/PjUdUDmGGyyEgJ9owqpEomjwDMMxwHEJv437vGUCEmiqWGSbFEP7/GQBsjoX3Mso5PgOYMuSRHjqRQxAkxW019meWGQ4hVjLPijs1OjanK08pZISB/XP9pDJB7wNJEeQUTIJOuleSxHuSZm6l8z8+vNN/HZcferIZLhdSRVuKmYjwvl3zhRVx4vU6p4zjBIk5NKjNIRNZbvbVz6IO7Syq100+nse/LSa3V9PRp1f/9+s1/ToZxYvd1euEqKhVfbQyuhOtp+jvrpDkETNb0uW4aYwdqImf8tScLFFtPKku5iZBLwVTJVNYJIwmYBKmAecoDEjFYiaIwWgICrU5AKOI0JlU9hmwLJwyblD1KloeLGFHVZ/WG6RM7rSHVq4T3wpZj3hgkxADktJcKctMhBTLVOY6JJSi1mGEgmF0ACQ3CQrDKLFThVPCuLtdkfKXsSLC2GsqhUDqRtTdWw0zJM1QYRQq/Jo7q6lchKQ0UXHtBzQbb1P//mb07uu24x8JKnQxXRBvOR6ebz/xMUPg6uz6Bn69vFgNflGOkvW4BdGgkCKbYwRSOG0PYjQhQiB/cQBcUsJDW9DguZVx167AAdM6x6jM+aLZdg/zPNpuJIoUat0ZgheXUIhuplGdOZuBB6+PgsHpL8EgODmqR2ZZLW2mmKAsI7wTdC0Jz3ONyg5/4VPGJ0AlLZpZw3Vi7W9c4pKlk1WUtjc/xJPaOMJ7pHmrMSnPtUE1TKVgRqqXKWFby+lGzRXr5HTRjyLKJBMGbq8uGqFehvcZobOXGmmumFm+DEvmriZoN1wRWzsXyFUs7mHFEUeirqmSnF/50fvbsFAbTmS07GS1Qiunr4snmwIKMuFtpHZgPZvBe7O16UaYKfRB/nRb72rymD5+ToDzEdj+SaMpFAQ77vZZQnR9FFW1dxDY3xunCHSGlE0ZBSMtmFMRVITrmMpclVZyE60ucnYCtL9yB3w+Aio59ztxPWjJ/bny+75G2og25ZJUs2tHsFGFZK3QdhRSRUzE1qKW+x2ZE5gzZXLCISU0YaIFXFOVT0K9TCeSh8bmRGhYit9rHXBJco1gVQAToJFKEWmgHImwa8gz8CzgWHQnuFFMxD8AfAduh9LJvUAyCxVOdZgpaZsxx/8dyW8ss85sL/ug0WGAwikqFBR1aVHN6BlRhHPkoUJNifhR1CV7p0TNLD1ncwQ5+YLUaNsccQSSZbzoMoBp0EZmGUbNi6GcaB3mgksS/aiVeG0uXkSuMfIQO1qfZrnjbGSsK8o7Ml76wIDR5a2P8SJeUE2lSi3wQymsQWwu2eUF2AaxwcjQaegdF2J/lUXI3GgW+ZeRGSqBvG4BpcKy1P8FSiaqkNBKqZDwH4F5Iw3hgJxkNl4r0EYClbZfMp68tF+61xZtiHJSUyaYToLaLuPLPA1VLhpSsHkhHQtwjapFdSTvPr0vaPKslG0HQDQQP72Nct9yizydoKqnNYlCEunQWLuEtso0FY9Hk58TNSHxhjULreC0utpWuKGuaKwD2ZZAt7usmJ/axBbBSDmzLvZQBWcrlyFx9Q24rXXrstYIuIxjv/XGDSoTJNXK+OhG9i2SDAjnsthsiIhWfmH/2ruXtWPC2aSxqDNhMN46c9sBE9bJaxfv9NjAnzEuJ0vT1qHYnem7Id3aMuKImmHWhyY8CmOsvtg/2nEfeQQxCiwaZ0lpnhFBlz+/B53z5NQapLyCn8CdjTbt9u5S5iJ+Sv/+aSf8H/fwsrqGn8DHLXatp1vbDdV8Q+nm8cy1e2yrtzuf2P7AUY2BbT+te2OZZlKg2NzANtX9U8YPcpsnOw+nPjLAgAZp8B4N+Y0YMlJIDLoPRBaX0crZb9PGVXtyUyXyW1fdhNvR33ZO44KmLVd63oXno+bjrvqjrrosrM+Wdc0W2y8omyxVTW0UKw4utxa47iYW8vsrfHBnKOeoEiRRi1+bgqvO0xuK1onD5YLLuDlz/HP/har4RHBW/QC9rX981B/8ctg/PTx6fTPoD/unw8HJwevj47vxxYc3H+Fu7L+U+imCAiL4mqNa3sF4Hn56l3z5dAfjFI1i1H2PPQ2Og/6hnTfonwZHp3fj/p1rCccnwatU3x24izBlnDM9PnHXtnFOmNHjweuT41f21jJDPb47sB268X84BPeZafz77dnVn+HN27MP4Zuzm9Hb9Rzua6keD6y8zBXF8d+fe472c2/49+deSgxNQsK5v5xIqc3n3nAQ9L99+3Z38J/UG9txVsrpVrGJUW190S57o9bYUzSb3usuMdbALSSuSWdm3acXZ/Tufc0Zq4nvuN9PdR3Kxvl3icN6sQ3EPt8nNZqX7OKkRdW1IYa5bNhHX8O6SrHYptL/U4eVatJZDeQ91+xCPHQua+PgctHu1z2SZA8r4b1RJPSQLXhnVqxYCzAxlSqt+TD4KD+VCk1XOrhcYAK8tH9XbSA4OdozGVfVrY3Bv5Yx86RKfTnsVGt9zzDy/2vSBHC0H4CSuWGVHXpT95WXaHKz7g/e/nX0+z9mr78sTmITkzdG7JcerGVDvoiepOp0VICbltSPJG3T9e8AAAD//wsARmM=" + return "eJzUmltv2zgWgN/7Kw781AKJaidptvHDArOeNE2xvUySdjDjBgJNHUusKVIlKTveQf/7gqTsyLIudrbNdvySyCJ5Pp4bD0kfwgyXQ0BOtGFUI1E0eQJgmOE4hN7G970nABFqqlhmmBRD+OcTANjsC29llHN8AjBlyCM9dE0OQZAUt8XYj1lmOIRYyTwrvqmRsTlceUghIwzsv+s3lQF670iKIKdgEnSte6WWeEfSzM10/vu7N/rP4/JLTzbD5UKqaEswExHetUu+tE1c83qZU8ZxgsQcGtTmkIksN/vKZ1GHdBbVyybvL+JfF5OPV9PRpxf/+OWafp2M4sXu4nVCVNQqPlop3TWtp+jvLpDkETNbrct+0+g7UOM/5aE5WaLaeFOdzE2CvhVMlUxhkTCagEmYBpyjMCAVi5kgBqMhKNTmAIwiQmdS2XfAsnDKuEHVq0i514TtVX1br5AyuZMe2nad+LaRtYgHNgkxICnNlbLMREixTGWuQ0Ipah1GKBhGB0Byk6AwjBI7VDgljLuvK638Y6yIMPaZSiGQuh513626GZJmqDAKFX7NndZULkJSGqh49h2albcpf381evN16/H3BBU6ny6ItwwPT7ffeJ8hcHV+fQO/fLhcdX5W9pJ1vwXRoJAim2MEUjhp981oQoRA/uwAuKSEhzahwVPbxj27BAdM6xyjMuezZt3dj/NgvZEoUqh1pwtefoCi6WYY1amzGXhwdhQMTl8Gg+DkqB6ZZbW0mWKCsozwTtB1S3iaa1S2+zMfMj4AKmHRzBquA2t/5RIXLJ2sorS8+S6e1PoR3iHNW5VJea4NqmEqBTNSPU8J25pON2quWCen834UUSaZMPDx6rIR6nl4lxE6e66R5oqZ5fOwpO5qgHbDFb61c4Jc+eIeWhxxJOqaKsn5le+9vw4LseFERstOVttoZfR18mRTQEEmvI3UdqxnM3hnthbdCDOF3sm/39K7GjymDx8T4GIEtn7SaAoBwY6rfZYQXe9FVekdBPbzygkCnSFlU0bBSAvmRASVxnVMZa5KKbmJVuc5OwHaT7kCvhgBlZz7lbgetGT+XPl1XyNtRJtySarRtSPYqEKyFmgrCqkiJmKrUcv9hswJzJkyOeGQEpow0QKuqconoV6mE8lDY2MiNCzFHzUP+EByjWBFABOgkUoRaaAcibBzyDPwLOBYdCe4UUzEjwC+A7dD6eReIJmFCqc6zJS0xZjj/4HkN5ZZZ7aWvZfoMEDhFBUKiro0qWb0jCjCOfJQoaZEPBZ1Sd8pUTNLz9kcQU6+IDXaFkccgWQZL6oMYBq0kVmGUfNkKCdah7ngkkSPNRMvzfmLyDVGHmJH7dMsd5yNjHVJeUfGD94xYPTho/fxwl9QTaVKLfB9KqxBbE7Z5QnYArFBydCp6B0nYj+VScjcaBb5zcgMlUBeN4FSYlnq/wMlE1VIaKVUSPhjYN5IQzggJ5n11wq0kUClrZeMJy+tl27bog1RrtWUCaaToLbK+DJPQ5WLhhBsnkjHBFyhalEdyZtPbwuaPCtF2wEQDcQPb73cl9wiTyeo6mlNopBEOjRWL6HNMk3J48HkF0RNSLyhzUIqOKkutxVmqEsaa0e2KdCtLivm761ii2CknFkTe6iCs5XLkLi6A24r3bq0NQIu49gvvXGDyARJNTM+uJB9jSQDwrksFhsiopVd2H/2rmVtn3A2aUzqTBiMt87cdsCEdfDayTs51vFnjMvJ0rRVKHZl+mFIH20acUTNMOtDEx6FMVY39g823HseQYwCi8JZUppnRNDlz29BZzw5tQopz+AnMGejTrutu5S5iL+nff+wA/7NLbyszuEnsHGLXuvp1npDNd8Qunk8c+1e2+ztzie2LziqPrBtp3VtLNNMChSbC9imuH/L+L7d5snO/amPDDCgQRq8RUN+JYaMFBKD7oLI4jJaOfttWrhqT26qRH7pqhtw2/vbzmmc07TFSs+b8GLUfNxVf9RVF4X10bLO2WJ7g7LJUpXURrHi4HJrgutqYiEfQ+B6fnNUCZIo1Pi1VeXX+DW3W+uimmzU/PHJydnZ2VGt+hsp7kvDcHUQFKQd1wobG+qL0YH9kzLOWVGsNRIOTvv9HUvGtZYmNvbJfoAuEbqy1iq5uPMoFcELoouBMdqD/uVO9OucxeWCy7g5afn3/nKwuJ05r979b0H0xkf9wcvD/unh0dnNoD/snw4HJwdnx8e348t3r97D7dhfUvshggIi+JqjWt7CeB5+epN8+XQL4xSNYtRdhZ8Gx0H/0I4b9E+Do9Pbcf/WVePjk+BFqm8P3EPolTQ+cc92z5Iwo8eDs5PjF/arZYZ6fHtgN0fG/+MQ3A3f+LeP51d/hDevz9+Fr85vRq/XY7iLaj0e2PYyVxTHf33uOdrPveFfn3spMTQJCef+cSKlNp97w0HQ//bt2+3B/5LqbbFfWcm28nyMauvHBGVr1Cp7imbTet3Z3Sq4hcSFHDPrLVJxPeK2yk5ZTXzH/X6q61A2rh5KHNaKbSD2fZOw/abs/KRF1LUhhrlo2Edew7xKvtgm0v+exrZqkll15D3n7Fw8dCZr4+By0W7XPYJkDy3hnVEk9JAteOe2WTEXYGIqVVpzJ/sgO5USTVc4uFhozd1rgpOjPYNxld3aGPyOmJnvKtSnw06x1vYMI/8znyaAo/0AlMwNq1QJm7KvfIsmM+v+4PWfR7/9a3b2ZXESm5i8MmK/8GBRs/TL6LtknY4McNMS+pGkbbL+GwAA//9JWrH5" } diff --git a/filebeat/module/elasticsearch/server/_meta/fields.yml b/filebeat/module/elasticsearch/server/_meta/fields.yml index 47bb4a96761..856178f4ba5 100644 --- 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 index 5a69e101877..b1c149b7ebd 100755 --- 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 index 60fbf0c1a2c..4cbc5adace9 100644 --- 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" }, {