Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[filebeat] Wrong "gc_overhead" parsed by Elasticsearch module #9513

Closed
tsouza opened this issue Dec 12, 2018 · 5 comments
Closed

[filebeat] Wrong "gc_overhead" parsed by Elasticsearch module #9513

tsouza opened this issue Dec 12, 2018 · 5 comments

Comments

@tsouza
Copy link

tsouza commented Dec 12, 2018

Version: 6.5.3

The Elasticsearch Filebeat module will parse the following GC log message:

[2018-12-07T16:10:41,612][WARN ][o.e.m.j.JvmGcMonitorService] [node1] [gc][238436] overhead, spent [650ms] collecting in the last [1s]

Into a document that has:

{
  "elasticsearch": {
    "server": {
      "component": "o.e.m.j.JvmGcMonitorService",
      "gc_overhead": "238436"
    },
    "node": {
      "name": "node1"
    }
  }
}

There are a couple of issues here:

  1. The value for field elasticsearch.server.gc_overhead is coming from [gc][238436] overhead. According to this https://github.com/elastic/elasticsearch/blob/master/server/src/main/java/org/elasticsearch/monitor/jvm/JvmGcMonitorService.java#L309 the number 238436 is just a sequential number that holds no significant meaning in GC timings. This is not the GC overhead
  2. It does not collects the two important time components from this log message present in: spent [650ms] collecting in the last [1s]
@BobBlank12
Copy link

This was created in filebeat version 6.4.3

@ph ph added the Team:Integrations Label for the Integrations team label Dec 12, 2018
@elasticmachine
Copy link
Collaborator

Pinging @elastic/infrastructure

@alvarolobato alvarolobato added Feature:Stack Monitoring and removed Team:Integrations Label for the Integrations team labels Dec 17, 2018
@elasticmachine
Copy link
Collaborator

Pinging @elastic/stack-monitoring

@ycombinator ycombinator self-assigned this Dec 17, 2018
@ycombinator
Copy link
Contributor

@tsouza Thanks for reporting this. I'm working on a fix now.

When looking at the parsed document for spent [650ms] collecting in the last [1s], what field names would make most sense to you for the 650ms and 1s values?

@ycombinator
Copy link
Contributor

@tsouza Regarding my question in the previous comment, let's continue the conversation on the PR (#9603) where I made up some strawman field names.

ycombinator added a commit that referenced this issue Dec 27, 2018
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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants