# Constant high cpu usage from Filebeat

**URL:** <https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028>\
**Category:** Beats\
**Tags:** filebeat\
**Created:** [February 12, 2019, 12:22pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028 "2019-02-12T12:22:59Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![bugggbear](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bugggbear/32/37615_2.png) [@bugggbear](https://discuss.elastic.co/u/bugggbear)\
**Post date:** [February 12, 2019, 12:22pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/1 "2019-02-12T12:22:59Z")

</div>

Hello,

I'm using filebeat (6.4.3) to ship Apache logs (and some system ones) directly to ES.

Currently Filebeat is configured by using apache2 module and wildcard path setting, pointing to a directory with near 16 000 log files (not all of them are constant updating).

The event intensity is about 1000/s at max.

Filebeat is constantly using more than 100% cpu (more than 1 core) on a "Intel(R) Xeon(R) CPU E5-2630 0 @ 2.30GHz" cpu.

My current registry file is of 1,5MB size (don't know if that matters).

This is a sample snippet from my filebeat log :

===================

`2019-02-12T14:18:39.945+0200 INFO [monitoring] log/log.go:141 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":102890,"time":{"ms":6569}},"total":{"ticks":997290,"time":{"ms":48492},"value":997290},"user":{"ticks":894400,"time":{"ms":41923}}},"info":{"ephemeral_id":"707a2420-9c67-4a21-b1cc-605a5aa74d78","uptime":{"ms":1450532}},"memstats":{"gc_next":70045040,"memory_alloc":41175592,"memory_total":83141794256,"rss":-7925760}},"filebeat":{"events":{"active":7768,"added":16776,"done":9008},"harvester":{"open_files":617,"running":701,"started":114},"input":{"log":{"files":{"renamed":48}}}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":10158,"active":73,"batches":272,"failed":14,"total":10245},"read":{"bytes":216823,"errors":3},"write":{"bytes":8552477}},"pipeline":{"clients":20,"events":{"active":4122,"filtered":6364,"published":10174,"retry":64,"total":16544},"queue":{"acked":6112}}},"registrar":{"states":{"current":7239,"update":9008},"writes":{"success":1130,"total":1130}},"system":{"load":{"1":9.57,"15":11.48,"5":10.86,"norm":{"1":0.3988,"15":0.4783,"5":0.4525}}}}}}`

===================

I've also tried to do httprof profiling and I'm attaching the result of 30s profile (as a png).

 ![profile](https://us1.discourse-cdn.com/elastic/original/3X/4/0/4073865bd096648492eb68049a4a159125b7e615.png)

---

<div class="post-metadata">

**Author:** ![nskerl](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nskerl/32/40847_2.png) [@nskerl](https://discuss.elastic.co/u/nskerl)\
**Post date:** [February 12, 2019, 6:00pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/2 "2019-02-12T18:00:44Z")

</div>

Just wanted to ref my own issue here, as I saw a very similar CPU pattern with a high number of `current` files. I see the same in your output. I was able to resolve my CPU issue by reducing the number of _stale_ files in the registry, but I still don't understand why that helped.

> [@Log file size vs. quantity](https://discuss.elastic.co/t/log-file-size-vs-quantity/168090):
>
> While troubleshooting high cpu usage by Filebeat (80% sustained, even when logs are idle), I noticed it showed a large number of files (current: 8811) in the registrar: "harvester":{"open\_files":4,"running":4}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":214,"batches":4,"total":214},"read":{"bytes":24},"write":{"bytes":16075}},"pipeline":{"clients":1,"events":{"active":0,"published":214,"total":214},"queue":{"acked":214}}},"registrar":{"states":{"current":8811,"upda…

---

<div class="post-metadata">

**Author:** ![bugggbear](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bugggbear/32/37615_2.png) [@bugggbear](https://discuss.elastic.co/u/bugggbear)\
**Post date:** [February 13, 2019, 7:41am UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/3 "2019-02-13T07:41:58Z")

</div>

Hi and thanks for your feedback !

Could you share, how did you managed to reduce the stale files in the registry ?

---

<div class="post-metadata">

**Author:** ![nskerl](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nskerl/32/40847_2.png) [@nskerl](https://discuss.elastic.co/u/nskerl)\
**Post date:** [February 13, 2019, 5:09pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/4 "2019-02-13T17:09:09Z")

</div>

We deleted them from the watched directory. That seemed to allow [clean\_removed](https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-input-log.html#filebeat-input-log-clean-removed) to release them. The `current` count drops almost immediately after we purged them, and the CPU came down with it.

---

<div class="post-metadata">

**Author:** ![bugggbear](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bugggbear/32/37615_2.png) [@bugggbear](https://discuss.elastic.co/u/bugggbear)\
**Post date:** [February 13, 2019, 6:58pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/5 "2019-02-13T18:58:49Z")

</div>

That's not applicable in my case, because these are Apache domains access logs, which are needed. The problem is that most of them are rarely updated or the update rate is pretty low, but there's no way to delete them.

---

<div class="post-metadata">

**Author:** ![bugggbear](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/bugggbear/32/37615_2.png) [@bugggbear](https://discuss.elastic.co/u/bugggbear)\
**Post date:** [February 14, 2019, 8:40am UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/6 "2019-02-14T08:40:21Z")

</div>

Actually you are right, that the registry file is the main reason for the high cpu usage.

I tried to stop the apache2 module on a single server, where Filebeat was making the most CPU , and after doing it , there was almost no impact on the CPU (the registry stayed the same). Filebeat was consuming about 1300 cpu minutes per 24h on the same server.

Yesterday I decided to try and delete the registry file (while apache2 module is still disabled). After restarting , the CPU for 20 hours is approximately 13 cpu minutes (which is almost 100x times lower).

Isn't this reported as a bug ? Because for me such behavior is totally broken.

---

<div class="post-metadata">

**Author:** ![nskerl](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/nskerl/32/40847_2.png) [@nskerl](https://discuss.elastic.co/u/nskerl)\
**Post date:** [February 14, 2019, 6:03pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/7 "2019-02-14T18:03:58Z")

</div>

I agree. I don't know if its a bug or just how filebeat works.

The documentation [here](https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-input-log.html#filebeat-input-log-close-inactive) suggests that after 5 minutes (default), the inactive files should be closed, but that doesn't mean filebeat stops tracking them:

> If the closed file changes again, a new harvester is started and the latest changes will be picked up after `scan_frequency` has elapsed.

So, to derive if the "file changes again" it seems it has to inspect the file. I can see this happening in the debug logs:

```
|2019-02-14T08:27:57.485-0800|DEBUG|[prospector]|log/prospector.go:361|Check file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log|
|2019-02-14T08:27:57.485-0800|DEBUG|[prospector]|log/prospector.go:447|Update existing file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log, offset: 173310|
|2019-02-14T08:27:57.485-0800|DEBUG|[prospector]|log/prospector.go:501|File didn't change: d:\logs\iis\W3SVC3\u_ex19012920_x.log|
|2019-02-14T08:28:08.919-0800|DEBUG|[prospector]|log/prospector.go:361|Check file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log|
|2019-02-14T08:28:08.919-0800|DEBUG|[prospector]|log/prospector.go:447|Update existing file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log, offset: 173310|
|2019-02-14T08:28:08.919-0800|DEBUG|[prospector]|log/prospector.go:501|File didn't change: d:\logs\iis\W3SVC3\u_ex19012920_x.log|
|2019-02-14T08:28:19.931-0800|DEBUG|[prospector]|log/prospector.go:361|Check file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log|
|2019-02-14T08:28:19.931-0800|DEBUG|[prospector]|log/prospector.go:447|Update existing file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log, offset: 173310|
|2019-02-14T08:28:19.931-0800|DEBUG|[prospector]|log/prospector.go:501|File didn't change: d:\logs\iis\W3SVC3\u_ex19012920_x.log|
|2019-02-14T08:28:31.608-0800|DEBUG|[prospector]|log/prospector.go:361|Check file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log|
|2019-02-14T08:28:31.608-0800|DEBUG|[prospector]|log/prospector.go:447|Update existing file for harvesting: d:\logs\iis\W3SVC3\u_ex19012920_x.log, offset: 173310|
|2019-02-14T08:28:31.608-0800|DEBUG|[prospector]|log/prospector.go:501|File didn't change: d:\logs\iis\W3SVC3\u_ex19012920_x.log|

```

That file hasn't been touched in \> 2 weeks. However, every 10s (the default scan\_frequency) filebeat is inspecting it. Even if it's a small operation, inspecting a large number of files every 10s could account for the cpu pattern we are seeing.

[clean\_inactive](https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-input-log.html#filebeat-input-log-clean-inactive) appears to remove the file from the registrar completely, but I dont like that if the file is updated after being cleaned it is read from the beginning. I guess that is useful if you know for sure the file wont be updated.

In my case I think deleting the file and relying on [clean\_removed](https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-input-log.html#filebeat-input-log-scan-frequency) is safer.

In your case, since you can't delete, we might be better off adjusting the [scan\_frequency](https://www.elastic.co/guide/en/beats/filebeat/current/filebeat-input-log.html#filebeat-input-log-scan-frequency) to poll every minute or so instead of the default 10s. There is also [max\_procs](https://www.elastic.co/guide/en/beats/filebeat/current/configuration-general-options.html#_literal_max_procs_literal) but I have not experimented with that yet.

Let me know what you find out!

---

<div class="post-metadata">

**Author:** ![J.Teekaram\_prasath](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/j.teekaram_prasath/32/40948_2.png) [@J.Teekaram\_prasath](https://discuss.elastic.co/u/J.Teekaram_prasath)\
**Post date:** [February 14, 2019, 9:39pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/8 "2019-02-14T21:39:58Z")

</div>

Did you specified log rotateeverybyte and files to keep in filebeat.yml.

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [March 14, 2019, 9:40pm UTC](https://discuss.elastic.co/t/constant-high-cpu-usage-from-filebeat/168028/9 "2019-03-14T21:40:07Z")

</div>

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.
